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

[Pat McGowan]

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

[Daniel Manrique (roadmr)]

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.

[Caio Begotti (caio1982)]

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)]

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

[Pat McGowan (pat-mcgowan)]

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

[Daniel Manrique (roadmr)]

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!)

[Caio Begotti (caio1982)]

(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)]

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...

[Caio Begotti (caio1982)]

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.

[Pat McGowan (pat-mcgowan)]

see also bug #1442857

[Caio Begotti (caio1982)]

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)]

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)]

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)]

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)]

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.

[Caio Begotti (caio1982)]

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.

[Barry Warsaw (barry)]

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.

[Pat McGowan (pat-mcgowan)]

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