ubuntu-download-manager is reporting the wrong total size during downloads, via its progress signal

Bug #1450144 reported by Pat McGowan on 2015-04-29
66
This bug affects 16 people
Affects Status Importance Assigned to Milestone
Canonical System Image
High
Bill Filler
Capomastro
Medium
Unassigned
Ubuntu system image
Medium
Unassigned
ubuntu-download-manager
Fix Released
High
Michael Sheldon

Bug Description

When downloading updates the UI shows progress in a size much larger than the actual amount of bytes downloaded. Assuming that the headers are providing incorrect information.

Possible duplicates: bug 1420853, bug 1429022, bug 1442857, bug 1456110

Related branches

Changed in capomastro:
status: New → Confirmed
Ara Pulido (ara) on 2015-05-12
tags: added: stakeholder
Ara Pulido (ara) on 2015-05-12
Changed in capomastro:
importance: Undecided → Medium
Daniel Manrique (roadmr) on 2015-05-12
Changed in capomastro:
milestone: none → future
Daniel Manrique (roadmr) wrote :

Hi Pat,

I tried using curl to download a custom tarball.

First I got only the headers to check the content-length:

roadmr@blackdog:/tmp$ curl --head https://sis.capomastro.canonical.com/pool/custom-3ed576bc5513430feab7a10b370d1d5fcade19fb00bf1d7f39b0d6451c7f26a5.tar.xz
HTTP/1.1 200 OK
Date: Tue, 12 May 2015 13:46:33 GMT
Server: Apache/2.4.7 (Ubuntu)
Last-Modified: Tue, 28 Apr 2015 03:19:25 GMT
ETag: "39373f0-514c0545e921b"
Accept-Ranges: bytes
Content-Length: 59995120
Content-Type: application/x-tar

Next I downloaded the tarball, curl's progress bar and estimates looked OK to me:

roadmr@blackdog:/tmp$ curl --output custom.tar.xz https://sis.capomastro.canonical.com/pool/custom-3ed576bc5513430feab7a10b370d1d5fcade19fb00bf1d7f39b0d6451c7f26a5.tar.xz
  % Total % Received % Xferd Average Speed Time Time Time Current
                                 Dload Upload Total Spent Left Speed
100 57.2M 100 57.2M 0 0 751k 0 0:01:17 0:01:17 --:--:-- 1039k

Finally I checked the file size matched what the header told me initially:

roadmr@blackdog:/tmp$ ls -la custom.tar.xz
-rw-rw-r-- 1 roadmr roadmr 59995120 May 12 09:48 custom.tar.xz

I also checked the index.json for the channel (ubuntu-touch/tangxi-vivid-proposed) and device (arale), I found this:

                {
                    "checksum": "3ed576bc5513430feab7a10b370d1d5fcade19fb00bf1d7f39b0d6451c7f26a5",
                    "order": 1,
                    "path": "/pool/custom-3ed576bc5513430feab7a10b370d1d5fcade19fb00bf1d7f39b0d6451c7f26a5.tar.xz",
                    "signature": "/pool/custom-3ed576bc5513430feab7a10b370d1d5fcade19fb00bf1d7f39b0d6451c7f26a5.tar.xz.asc",
                    "size": 59995120
                },

so it looks like sizes match everywhere, at least for the custom tarball.

Did you see this with any other components? perhaps the device or ubuntu tarballs?

Did you see this with a delta? if so, could you tell me which version you were at, and which version it was upgrading you to? That way I can hunt down the deltas in the index and check them with the same process.

Changed in capomastro:
status: Confirmed → Incomplete
Caio Begotti (caio1982) wrote :

Pat, also, did you see that while connected to the VPN or while updating the device from the office? It shouldn't change things that much but it'd be good to have this info.

Pat McGowan (pat-mcgowan) wrote :

It was an update of a delta
I was at the sprint using a router with the VPN enabled

Pat McGowan (pat-mcgowan) wrote :

Using VPN on the phone and updating from 31 to 38 (176.5 MB) I see the following

Daniel Manrique (roadmr) wrote :

We don't seem to have a 31->38 delta. The only version 38 images are a full one and a delta from 37.

The full version 38 images weigh in at 456MB, so I don't think that's what you're getting.

By walking all the deltas to get from 31 to 38, I arrived at a size of 168.348 MiB which is 176.52 MB (176525572) so I think this is what your device is getting. I'll check the headers for each of the files now and download them to validate, it will take a bit longer, will update when I know more. Setting the bug to confirmed again though, since we have the screenshot and required info from Pat (thanks!)

Changed in capomastro:
status: Incomplete → Confirmed
Caio Begotti (caio1982) wrote :

(We actually have an upgrade path from 31->38 but system-image-cli shows it does a small jump at a time, so it goes from 31->32 first, and so on all the way to 38)

Pat, would you be able to send us your /var/log/system-image/client.log right after you reproduce this? The default logging might not be very verbose so it would be great if you could increase its verbosity first. I think it might be a bug in the dbus signals from system-image as the filesizes and headers look ok.

You can increase the verbosity of the client editing /etc/system-image/client.ini as root, I believe, which will probably needs the FS to be writable. I'm not sure if there are detailed instructions for that in the wiki, sorry.

Daniel Manrique (roadmr) wrote :
Download full text (4.3 KiB)

I concur that this looks like a client issue. Also, the screenshot makes me think it's more of a thing with the "bytes downloaded" counter than one with the headers or expected file size. I think the "expected download size" is correct in the screenshot as it matches what we have obtained, but the other one (154 GB??) is completely out of scale.

I walked the files needed to do a 31->38 upgrade, confirmed the final filesize but also verified each file individually, comparing its reported size from the index.json list, the size from the http headers and actual downloaded file size. They all match.

Delta from 31 to 32
/pool/ubuntu-a04d5d2afda5e129e6f5f9f5aad5d15cedf23baeac96ff4dd230eef98f2a29ca.delta-ubuntu-b141b0d99eab9932243271e2017c1c9d46e37d4b484be6341a24fe0d626cd36d.tar.xz
Reported size 29154732
Header size 29154732
Download size 29154732
/ubuntu-touch/tangxi-vivid-proposed/arale/version-32.tar.xz
Reported size 464
Header size 464
Download size 464
/pool/keyring-50c4526d20041aa8802e48e5d6ea66cb834cd1b4f92858390f0c4e8720c6fa8c.tar.xz
Reported size 1516
Header size 1516
Download size 1516

Delta from 32 to 33
/pool/ubuntu-3fab20d1ece4d43360d3607b9fb4c03935609aebb071dda357f4f6cf51ca62c6.delta-ubuntu-a04d5d2afda5e129e6f5f9f5aad5d15cedf23baeac96ff4dd230eef98f2a29ca.tar.xz
Reported size 7672532
Header size 7672532
Download size 7672532
/ubuntu-touch/tangxi-vivid-proposed/arale/version-33.tar.xz
Reported size 464
Header size 464
Download size 464
/pool/keyring-50c4526d20041aa8802e48e5d6ea66cb834cd1b4f92858390f0c4e8720c6fa8c.tar.xz
Reported size 1516
Header size 1516
Download size 1516

Delta from 33 to 34
/pool/ubuntu-9f0821da0a1f7e92fe0cb27e90147f8a57e6a9da81aefcfde1bd83481e1f0302.delta-ubuntu-3fab20d1ece4d43360d3607b9fb4c03935609aebb071dda357f4f6cf51ca62c6.tar.xz
Reported size 6982044
Header size 6982044
Download size 6982044
/ubuntu-touch/tangxi-vivid-proposed/arale/version-34.tar.xz
Reported size 464
Header size 464
Download size 464
/pool/keyring-50c4526d20041aa8802e48e5d6ea66cb834cd1b4f92858390f0c4e8720c6fa8c.tar.xz
Reported size 1516
Header size 1516
Download size 1516

Delta from 34 to 35
/pool/ubuntu-9cdf5f895459fbe6c112229eaada6fea5033cb7a5a56a2dd0bced7602759fff1.delta-ubuntu-9f0821da0a1f7e92fe0cb27e90147f8a57e6a9da81aefcfde1bd83481e1f0302.tar.xz
Reported size 6810052
Header size 6810052
Download size 6810052
/ubuntu-touch/tangxi-vivid-proposed/arale/version-35.tar.xz
Reported size 464
Header size 464
Download size 464
/pool/keyring-50c4526d20041aa8802e48e5d6ea66cb834cd1b4f92858390f0c4e8720c6fa8c.tar.xz
Reported size 1516
Header size 1516
Download size 1516

Delta from 35 to 36
/pool/device-1e1b1cebe8900f5b62bed050a5c23a7765e62600d394cba528169d257e6ab36c.delta-device-320f13ea3dee85f6a8a8a0fe1f6e039b8a6eeaca8fc053d5275602ba2aebee44.tar.xz
Reported size 99461540
Header size 99461540
Download size 99461540
/pool/custom-8274419d06b4da1424e7f7339ff2f8276b38951951d8900e148a4fdfce8fba0d.delta-custom-92aa1322afef2f104a0374f845554f8e45cd2ba7e405be99a1f365fbe122e4e9.tar.xz
Reported size 4341552
Header size 4341552
Download size 4341552
/ubuntu-touch/tangxi-vivid-proposed/arale/version-36.tar.xz
Reported size 460
Header size 460
Download size 46...

Read more...

Caio Begotti (caio1982) wrote :

Pat, I'm marking this as incomplete as we'd need more info and that client log to investigate it further for we believe it's indeed a client issue.

Changed in capomastro:
status: Confirmed → Incomplete
Pat McGowan (pat-mcgowan) wrote :

see also bug #1442857

Caio Begotti (caio1982) wrote :

Attaching debug log of the client on phone reproducing the bug using Capomastro's staging server, upgrade path from 1 to latest image is 2:3:4:5:6:7.

Caio Begotti (caio1982) wrote :

Now this attachment is the log of the full upgrade. Instead of pausing it like I did before as soon as I noticed the size bug, I left it doing its thing. I noticed the client immediately jumps from 0kb download to 1gb and increases from that. At some point the whole system-settings screen became blank, with the default white background. You can see all the events during it in the log.

Caio Begotti (caio1982) wrote :

So at [systemimage] May 29 16:45:54 2015 (3658) EMIT UpdateProgress(118478, 0) the updater screen got blank white as I said earlier. I left the device doing its stuff while I had lunch then when I got back it was still blank white but I had a new client log saying the whole upgrade has finished? Log's attached here. So UpdateProgress() signals seem completely messed up?

Caio Begotti (caio1982) wrote :

Btw, I had to manually kill the settings app and reopen it, then the updater saw the downloaded files and finished the OTA correctly.

Barry Warsaw (barry) wrote :

There are two possibilities. Either we're getting incorrect information from ubuntu-download-manager via its 'progress' signal, or s-i is incorrectly calculating the percentage received from the data udm is giving it. Note that the 'eta' in s-i's UpdateProgress signal will always be zero.

I chatted with Caio on IRC about how to bump up logging manually in order to figure out which scenario is happening. The other thing to keep in mind is that touch is still on system-image 2.5.1. I don't think the code here has changed, but we probably want to think about backporting system-image 3.0 (available now in wily). That version at least gives us the option to bypass udm and use the built-in curl-based downloader.

tags: added: client
Changed in ubuntu-system-image:
status: New → Triaged
importance: Undecided → Medium
Caio Begotti (caio1982) wrote :

So I couldn't enable the _print() trick but I managed to print it myself manually which for this test seems enough. Apparently udm is really sending weird download progress stats. See the attached log :-)

You can see that at [systemimage] May 29 20:51:13 2015 (2055) PROGRESS: 11853 r 8272 t it decides to go crazy, reporting that it's receiving more than the total size (which I thought would be the real final total size of files and wouldn't keep changing?). As a matter of fact this time the test was slow enough that I could see the progress bar reaching 100%, then resetting to 0% then going awry with the 'r' stats (for receiving) making no sense to me.

The percentages calculated by system-image client seem okay. I mean, they are a direct simple calc of these received figures, so of course it's going to be wrong...

I'll try to flash a Wily image onto my Arale and see how it behaves, if it even behaves differently, but I'd say it's udm's fault... for now.

On May 29, 2015, at 09:24 PM, Caio Begotti wrote:

>So I couldn't enable the _print() trick but I managed to print it myself
>manually which for this test seems enough. Apparently udm is really
>sending weird download progress stats. See the attached log :-)

Yeah, there are tricks to getting _print() -- really the debug() helper --
working. I forgot to mention that. ;)

>You can see that at [systemimage] May 29 20:51:13 2015 (2055) PROGRESS:
>11853 r 8272 t it decides to go crazy, reporting that it's receiving
>more than the total size (which I thought would be the real final total
>size of files and wouldn't keep changing?). As a matter of fact this
>time the test was slow enough that I could see the progress bar reaching
>100%, then resetting to 0% then going awry with the 'r' stats (for
>receiving) making no sense to me.
>
>The percentages calculated by system-image client seem okay. I mean,
>they are a direct simple calc of these received figures, so of course
>it's going to be wrong...
>
>I'll try to flash a Wily image onto my Arale and see how it behaves, if
>it even behaves differently, but I'd say it's udm's fault... for now.

I concur.

I know that udm downloads the files in a group download sequentially; it
doesn't actually do parallel downloads. I'm not entirely sure how it
calculates its totals; maybe it's doing a HEAD on the various files? At
least, that's how we do it in the si 3.0 built-in curl downloader.

It does seem like udm should at the very least adjust its total if it
downloads more than it originally thought. In any case, I'll add a bug task
for udm and we'll have to let Manuel sort it out.

Changed in ubuntu-system-image:
status: Triaged → Incomplete
Barry Warsaw (barry) on 2015-05-29
summary: - server is reporting the wrong size during downloads
+ ubuntu-download-manager is reporting the wrong total size during
+ downloads
summary: ubuntu-download-manager is reporting the wrong total size during
- downloads
+ downloads, via its progress signal
description: updated
description: updated
Changed in canonical-devices-system-image:
milestone: none → ww40-2015
Changed in ubuntu-download-manager:
assignee: nobody → Manuel de la Peña (mandel)
Pat McGowan (pat-mcgowan) wrote :

This has a lot of reports and seems simple to fix?

Changed in canonical-devices-system-image:
assignee: nobody → John McAleely (john.mcaleely)
importance: Undecided → High
status: New → Confirmed
Changed in ubuntu-download-manager:
importance: Undecided → High
status: New → Confirmed
Changed in canonical-devices-system-image:
assignee: John McAleely (john.mcaleely) → Bill Filler (bfiller)
milestone: ww40-2015 → backlog
Changed in ubuntu-download-manager:
assignee: Manuel de la Peña (mandel) → Michael Sheldon (michael-sheldon)
Changed in canonical-devices-system-image:
status: Confirmed → In Progress
Changed in ubuntu-download-manager:
status: Confirmed → In Progress
Bill Filler (bfiller) on 2016-01-04
Changed in canonical-devices-system-image:
milestone: backlog → ww02-2016
Changed in canonical-devices-system-image:
status: In Progress → Confirmed
status: Confirmed → Fix Committed
Changed in canonical-devices-system-image:
status: Fix Committed → Fix Released
Changed in ubuntu-download-manager:
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers