Fails to receive OTA updates

[jtd]

Ubuntu Touch 15.04 (r23) [mako]

Issue: Phone appears to fail to receive OTA updates. Previously, I jumped from (r15) to (r23) due to missing OTA updates. Currently, I see (r24) appears to be released on 2015 Oct 16.
Expected behavior: System Settings > System > Updates (or System Settings > About this phone > Check for updates) reveals new image that I can release and download.
Actual behavior: Checking for updates... > Software is up to date

See the comment regarding similar issues for large app installs.
It seems if anything interrupts the transfer or if the connection is somewhat slow the download performance degenerates then times out.

[Pat McGowan (pat-mcgowan)]

Can you include the output of system-image-cli --info and sudo system-image-cli -n
Also attach /var/log/system-image/client.log

[Pat McGowan (pat-mcgowan)]

Also .cache/ubuntu-system-settings/software_updates_helper.log
Is it set for automatic download?

Similar report at bug #1445669

[Pat McGowan (pat-mcgowan)]

This morning on my mako it does not see update 66 which is available on
http://system-image.ubuntu.com/ubuntu-touch/rc-proposed/ubuntu-pd/mako/

[ ] version-66.json 11-Nov-2015 03:40 317
[TXT] version-66.json.asc 11-Nov-2015 03:40 490
[ ] version-66.tar.xz 11-Nov-2015 03:40 440
[TXT] version-66.tar.xz.asc 11-Nov-2015 03:40 490

current build number: 65
device name: mako
channel: ubuntu-touch/rc-proposed/ubuntu-pd
last update: 2015-11-10 08:31:44
version version: 65
version ubuntu: 20151110
version device: 20150911
version custom: 20150929-2-vivid

sudo system-image-cli -n just hangs

sudo system-image-cli -n -v
[systemimage] Nov 11 07:44:37 2015 (31288) Looking for blacklist: https://system-image.ubuntu.com/gpg/blacklist.tar.xz
[systemimage] Nov 11 07:44:37 2015 (31288) [0xb571e450] Requesting group download:
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz -> /var/lib/system-image/keyring.tar.xz
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz.asc -> /var/lib/system-image/keyring.tar.xz.asc

[systemimage] Nov 11 07:44:37 2015 (31288) [/com/canonical/applications/download/ca5a73d76aed42bab4b3e70c78042282] Running group download reactor

system-image-cli:
  Installed: 3.0.2-0ubuntu1

[Pat McGowan (pat-mcgowan)]

phablet@ubuntu-phablet:~$ cat .cache/ubuntu-system-settings/software_updates_helper.log
2015-11-11T00:09:34 DEBUG [4e87] Starting.
2015-11-11T00:09:34 DEBUG [4e87] Broadcast; forking.
2015-11-11T00:09:34 DEBUG [4e87] Done.
2015-11-11T00:09:34 DEBUG [4e8d] Forked.
2015-11-11T00:09:35 DEBUG [4e8d] Checking for update.
2015-11-11T00:09:36 ERROR [4e8d] Introspect error on :1.70:/com/ubuntu/Postal/_: dbus.exceptions.DBusException: org.freedesktop.DBus.Error.UnknownMethod: Unknown method
2015-11-11T00:09:36 DEBUG [4e8d] Executing introspect queue due to error
2015-11-11T05:17:07 DEBUG [4e8d] Available: 0; downloading: 0
2015-11-11T05:17:07 DEBUG [4e8d] Done.

[Pat McGowan (pat-mcgowan)]

from the client.log during a check from system settings

[systemimage] Nov 11 08:09:49 2015 (32286) SystemImage dbus main loop starting [ubuntu-touch/rc-proposed/ubuntu-pd/mako]
[systemimage] Nov 11 08:09:49 2015 (32286) Mediator created <Mediator at 0xb6208d10 | State at 0xb6208cd0>
[systemimage] Nov 11 08:09:49 2015 (32286) CheckForUpdate(): checking lock test and acquire
[systemimage] Nov 11 08:09:49 2015 (32286) CheckForUpdate(): checking lock acquired
[systemimage] Nov 11 08:09:49 2015 (32286) Mediator recreated <Mediator at 0xb59c0bb0 | State at 0xb59c0bf0>
[systemimage] Nov 11 08:09:49 2015 (32286) Enter _check_for_update()
[systemimage] Nov 11 08:09:49 2015 (32286) Looking for blacklist: https://system-image.ubuntu.com/gpg/blacklist.tar.xz
[systemimage] Nov 11 08:09:49 2015 (32286) [0xb59c0ff0] Requesting group download:
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz -> /var/lib/system-image/keyring.tar.xz
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz.asc -> /var/lib/system-image/keyring.tar.xz.asc

[systemimage] Nov 11 08:09:49 2015 (32286) [/com/canonical/applications/download/d2a599a14f254d8ca3971b7921d25464] Running group download reactor

[Pat McGowan (pat-mcgowan)]

After a reboot it found it

[systemimage] Nov 11 08:13:26 2015 (2960) SystemImage dbus main loop starting [ubuntu-touch/rc-proposed/ubuntu-pd/mako]
[systemimage] Nov 11 08:13:27 2015 (2960) Mediator created <Mediator at 0xb6204d10 | State at 0xb6204e30>
[systemimage] Nov 11 08:15:01 2015 (2960) CheckForUpdate(): checking lock test and acquire
[systemimage] Nov 11 08:15:02 2015 (2960) CheckForUpdate(): checking lock acquired
[systemimage] Nov 11 08:15:03 2015 (2960) Mediator recreated <Mediator at 0xb59bcc90 | State at 0xb59bcc10>
[systemimage] Nov 11 08:15:03 2015 (2960) Enter _check_for_update()
[systemimage] Nov 11 08:15:03 2015 (2960) Looking for blacklist: https://system-image.ubuntu.com/gpg/blacklist.tar.xz
[systemimage] Nov 11 08:15:03 2015 (2960) [0xb59bce70] Requesting group download:
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz -> /var/lib/system-image/keyring.tar.xz
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz.asc -> /var/lib/system-image/keyring.tar.xz.asc

[systemimage] Nov 11 08:15:03 2015 (2960) [/com/canonical/applications/download/3645e65e2cf744abb50199fc34cca229] Running group download reactor
[systemimage] Nov 11 08:15:04 2015 (2960) [/com/canonical/applications/download/3645e65e2cf744abb50199fc34cca229] Group download reactor done
[systemimage] Nov 11 08:15:04 2015 (2960) Local blacklist file: /var/lib/system-image/blacklist.tar.xz
[systemimage] Nov 11 08:15:04 2015 (2960) Looking for: https://system-image.ubuntu.com/channels.json
[systemimage] Nov 11 08:15:04 2015 (2960) [0xb59bcc30] Requesting group download:
 https://system-image.ubuntu.com/channels.json -> /tmp/system-image-rxb2e5ls/channels.json
 https://system-image.ubuntu.com/channels.json.asc -> /tmp/system-image-rxb2e5ls/channels.json.asc

[systemimage] Nov 11 08:15:04 2015 (2960) [/com/canonical/applications/download/5824c837ac4d439f940b1718b8365c19] Running group download reactor
[systemimage] Nov 11 08:15:05 2015 (2960) [/com/canonical/applications/download/5824c837ac4d439f940b1718b8365c19] Group download reactor done
[systemimage] Nov 11 08:15:05 2015 (2960) Local channels file: /tmp/system-image-rxb2e5ls/channels.json
[systemimage] Nov 11 08:15:05 2015 (2960) got channel: ubuntu-touch/rc-proposed/ubuntu-pd
[systemimage] Nov 11 08:15:05 2015 (2960) found channel/device entry: ubuntu-touch/rc-proposed/ubuntu-pd/mako
[systemimage] Nov 11 08:15:05 2015 (2960) [0xb59bcc30] Requesting group download:
 https://system-image.ubuntu.com/ubuntu-touch/rc-proposed/ubuntu-pd/mako/index.json -> /tmp/system-image-rxb2e5ls/index.json
 https://system-image.ubuntu.com/ubuntu-touch/rc-proposed/ubuntu-pd/mako/index.json.asc -> /tmp/system-image-rxb2e5ls/index.json.asc

[systemimage] Nov 11 08:15:05 2015 (2960) [/com/canonical/applications/download/5a3145dfacd44cb28a253bae36ac91f6] Running group download reactor
[systemimage] Nov 11 08:15:06 2015 (2960) [/com/canonical/applications/download/5a3145dfacd44cb28a253bae36ac91f6] Group download reactor done
[systemimage] Nov 11 08:15:07 2015 (2960) Upgrade path is 66
[systemimage] Nov 11 08:15:07 2015 (2960) _check_for_update(): checking lock releasing
[systemimage] Nov 11 08:15:07 2015 (2960) _check_for_update(): check...

[Pat McGowan (pat-mcgowan)]

This is happening today on an MX4 running 174, Update to 177 is not available

phablet@ubuntu-phablet:~$ system-image-cli -nv
[systemimage] Nov 24 15:20:06 2015 (13472) Looking for blacklist: https://system-image.ubuntu.com/gpg/blacklist.tar.xz
[systemimage] Nov 24 15:20:06 2015 (13472) [0xb581d330] Requesting group download:
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz -> /var/lib/system-image/keyring.tar.xz
 https://system-image.ubuntu.com/gpg/blacklist.tar.xz.asc -> /var/lib/system-image/keyring.tar.xz.asc

[systemimage] Nov 24 15:20:06 2015 (13472) [/com/canonical/applications/download/fde960f4689747c3875d81ba52a22855] Running group download reactor

Command never returns
The server returns a ping

I do not see any download manager log for the time

[Pat McGowan (pat-mcgowan)]

I killed u-d-m, tried the commend again and it did not work.
Once again a reboot cleared it
Adding a download manager task here.

[Barry Warsaw (barry)]

If the log file (or system-image-cli -vv) ends with "Running group download reactor" it basically means that s-i has told udm to download a bunch of files, and it's waiting for the D-Bus signals indicating successful completion or failure. Since we're not seeing either of those, s-i will just sit and wait, although it will eventually time out.

There could be several reasons why udm is not responding, including networking problems anywhere along the path, or bugs. I don't know whether udm is being actively maintained.

As an experiment, you could try `SYSTEMIMAGE_PYCURL=1 system-image-cli -vv` and see if you get different behavior. This bypasses udm and uses s-i's built-in cURL-based downloader. It's not recommended currently for production phone environments because it doesn't have the same networking behavior as udm, but this is essentially what's used in snappy. (Assuming of course that you're running s-i 3.0 or newer).

If the cURL approach works, then it points to a problem in udm. If it doesn't work, you should at least get more diagnostics to help narrow it down to a problem in the networking, client, or server.

[Pat McGowan (pat-mcgowan)]

Seeing a similar symptom trying to install a large app (file manager) from the store, the download starts fast, slows down then times out. At the same time the browser is responsive, pings, etc.

This was on a reasonably fast 3G connection. Switching to a slightly faster wifi connection (only 4G) after a reboot restarted the download where it left off but then pulled 144% of the fie and declared failure due to a timeout, but it clearly did not timeout.

 A subsequent retry finally installed the app.

[Jean-Baptiste Lallement (jibel)]

It happened this morning on arale. Download failed with a time out while other devices downloaded the update successfully at the same time and logs from my router do not show any networking issue

From system-image/client.log
[systemimage] Dec 01 05:00:11 2015 (10657) [/com/canonical/applications/download/e58d05ab667c4ffea31ec84a37b64947] Running group download reactor
[systemimage] Dec 01 05:10:20 2015 (10657) [/com/canonical/applications/download/e58d05ab667c4ffea31ec84a37b64947] Group download reactor done
[systemimage] Dec 01 05:10:20 2015 (10657) Download failed
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/systemimage/dbus.py", line 226, in _download
    self._api.download()
  File "/usr/lib/python3/dist-packages/systemimage/api.py", line 124, in download
    self._state.run_until('apply')
  File "/usr/lib/python3/dist-packages/systemimage/state.py", line 178, in run_until
    step()
  File "/usr/lib/python3/dist-packages/systemimage/state.py", line 506, in _download_files
    self.downloader.get_files(downloads, pausable=True)
  File "/usr/lib/python3/dist-packages/systemimage/download.py", line 203, in get_files
    self._get_files(records, pausable)
  File "/usr/lib/python3/dist-packages/systemimage/udm.py", line 169, in _get_files
    raise TimeoutError
TimeoutError

There is also this error in ubuntu-download-manager/ubuntu-download-manager.INFO before the update starts:
E1201 05:00:09.382732 10660 downloads_db.cpp:133] Could not create the data path /var/cache/ubuntu-download-manager
I1201 05:00:09.387313 10660 downloads_db.cpp:138] Db file is /var/cache/ubuntu-download-manager/downloads.db
E1201 05:00:09.387907 10660 downloads_db.cpp:147] out of memory Error opening database

I don't know if it is related because it is also present when the update is successful.

[Michael Sheldon (michael-sheldon)]

It'd be useful if we could get the full system ubuntu-download-manager log next time this happens from /var/log/ubuntu-download-manager/ (not the user log from .cache/ubuntu-download-manager).

In attempting to reproduce this I was able to on one occasion get the system into a state where download manager permanently believed that the network connection was "gsm" even when connected to wifi (and since the system image download settings prevent download over gsm it caused the downloads to be permanently queued), so this may be what's happening here. I haven't been able to reproduce it since however, so it'd be good to see the logs next time this occurs for someone else and see if the same has happened.

[Pat McGowan (pat-mcgowan)]

may be dupe of bug #1419803

[Nekhelesh Ramananthan (nik90)]

I am experiencing this issue with my pristine BQ E4.5 device. Here is the output of ubuntu-download-manager.ERROR located in /var/log/ubuntu-download-manager

Log file created at: 2016/01/12 14:47:54
Running on machine: ubuntu-phablet
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E0112 14:47:54.000000 30763 downloads_db.cpp:133] Could not create the data path /var/cache/ubuntu-download-manager
E0112 14:47:54.005391 30763 downloads_db.cpp:147] out of memory Error opening database

[Nekhelesh Ramananthan (nik90)]

When looking at http://paste.ubuntu.com/14689175/ (ubuntu-download-manager.INFO log file), I0128 20:44:51.668818 4255 network_session.cpp:68] Connection type gsm <-- it thinks its on GSM

Elleo: iirc it won't do automatic downloads of updates in GSM mode, unless you've set it to allow that in settings
I think it'll just queue it up and wait for the network type to change to wifi
I think we need to rethink the logic of that
as queueing it up then prevents the user from being able to manually press the download button I think
nik90: can you try connecting to wifi and see if it suddenly starts going?

By changing the auto-download settings in the settings-app to always download, I was able to get OTA-9.

[Michael Sheldon (michael-sheldon)]

Currently when set to wifi only system-image-dbus creates a download with the "allowOverGSM" property set to false, which then sits in the queue until the user gets a wifi connection, and appears to report to system settings that the download has started (despite it actually just being queued).

To handle cases where the user is on GSM and still wants to download the image I think we need to modify system-image-dbus to report the status of the download as being queued while waiting for GSM, this way system settings could provide some form of "download now" button that causes system-image-dbus to set the "allowOverGSM" property on the download back to true and so force the download to start immediately.

This currently causes additional problems due to the network status sometimes being reported incorrectly as still being GSM when really on wifi due to bug #1528886, meaning the download isn't started even when the user really is on wifi. Fixing that will lessen this issue, but it should still be fixed to account for users on GSM who want to force the update to start anyway.

[Ken VanDine (ken-vandine)]

Summarizing plan:

system-image-dbus adds a "force" (or some other name) method to the update which would set allowOverGsm to true

system-image-dbus should proxy the started signal from udm

system-settings will display "Download now" button if the started signal hasn't been received, which will call the force method on s-i-d to force the download regardless of network type.

[Ken VanDine (ken-vandine)]

@jtd have you gotten the update yet? If not, lets give this a try:

* Go into system-settings->Updates and at the bottom change auto download to "Never"

* Enable flight mode

* Enable wifi and make sure you are connected to a wifi network

* Swipe away system-settings to ensure it quits then start it again and go to the updates page to see if it finds an update.

* Download and install the update

Please let us know if this works for you.

[Barry Warsaw (barry)]

So, for the si dbus client we'll:

* Add a Started() signal which just proxies through from UDM.

* Add a ForceAllowGSMDownload() method (no argument), which when called will forward to UDM's current group download's allowGSMDownload(True). If there is no download in progress, it will no-op. It will not change the value of auto_download. It will return a boolean indicating whether a download was in progress or not (i.e. whether the force was in effect or not).

Is that all you need?

I considered adding a flag to DownloadUpdate() but I think that is not necessary.

[Ken VanDine (ken-vandine)]

That's perfect, thanks!

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Barry Warsaw (barry)]

One other thing to remember: we probably want a cli switch to also override allowGSM, though there we won't need to set that on an existing group download since si-cli blocks while a download is happening.

[Barry Warsaw (barry)]

I'm going to call the signal DownloadStarted.

[Barry Warsaw (barry)]

I'm having a difficult time figuring out a good test for ForceAllowGSMDownload(). I already have DownloadStarted() working and tested, but the former is giving me some pause.

Is it possible to set UDM into a mode where it thinks it's only on GSM? What I think I'd like to do is invoke UDM in this mode, with si-client on wifi-only. Then through the si D-Bus API, I'd issue the allowGSMDownload(True) call to UDM, which would then complete its download.

For testing purposes, can I get this in UDM?

[Matthew Paul Thomas (mpt)]

Any system update that is not currently downloading, downloaded, or failed should *already* be showing a “Download” button. That is true whether it would download automatically next time you are on Wi-Fi or not. <https://wiki.ubuntu.com/SoftwareUpdates#presenting-individual> That button already exists in the code (plugins/system-update/PageComponent.qml line 444). If it isn’t appearing when it should, fix that bug, don’t add some extra “Download Now” button that would end up comically duplicating the “Download” button when someone accidentally fixes the bug later. (“Download” “Download Now” “Download Right Now I Really Mean It”)

Meanwhile, the underlying problem here probably would be easier to debug if the Updates screen itself reported download errors as designed, which is bug 1215901 (content) and bug 1282499 (presentation).

[Victor gonzalez (victor-gonzalez-0)]

Hi all,

I've got 2 customers with this bug trying to update to OTA-9, I provided them the steps in #18 and the commands with system-image-cli, the results were:

Customer 1: received the OTA-9 after steps in #18.

Customer 2: didn't get the OTA-9 after trying #18 steps and system-image-cli commands. You'll find attached the output screenshots.

[Barry Warsaw (barry)]

@victor-gonalez-0: It's always going to be helpful to include -v when running system-image-cli since that captures the log output to the console. From the method 2.jpg, you can see that UDM is not doing what it's told to do. IIRC, there's an open bug (I can't find it right now) on this issue in UDM.

Sometimes what happens is that the paths system-image tells UDM to download the files to don't exist after UDM has reported a successful download. That's the bug you see here. I don't know why it happens.

One way around that is to cheat and bypass UDM. Because of snappy, si has an alternative built-in downloader based on pyCurl. It doesn't know how to do things like GSM but it often works when the UDM downloader doesn't. You can invoke it like so:

$ SYSTEMIMAGE_PYCURL=1 system-image-cli -v

[Victor gonzalez (victor-gonzalez-0)]

Hi @barry,

Please find attached the output of $ SYSTEMIMAGE_PYCURL=1 system-image-cli -v done by the user.

[Barry Warsaw (barry)]

On Feb 22, 2016, at 08:15 AM, Victor gonzalez wrote:

>Please find attached the output of $ SYSTEMIMAGE_PYCURL=1 system-image-
>cli -v done by the user.

Notice that the device is trying to update to daily/krillin and that the log
file indicates it's not a valid channel, which seems to be backed up by
viewing the system-image.u.c channels.json file:

http://system-image.ubuntu.com/channels.json

I guess you have to switch them to a valid channel for their device.

[Barry Warsaw (barry)]

I think I have the D-Bus side working now. I want to add the cli switch and then I'll prep a PPA package for you to test to make sure it's actually doing what you want.

[Barry Warsaw (barry)]

I guess I can't link a git branch to an LP bug yet, so:

https://code.launchpad.net/~ubuntu-system-image/ubuntu-system-image/+git/ubuntu-system-image/+merge/287220

[Nikola Srnec (maskor13x)]

I did not recieve the OTA-9 update since the date of release, and OTA-10 has not arrived on my BQ E4.5 yet, will I ever get another update for my phone?