Ubuntu 16.04 to Ubuntu18.04 upgrade fails on snap debug connectivity without logging any useful logs

[sergiiF]

While running the do-release-upgrade I faced the issue. The output from log is like:
DEBUG quirks: running bionicPostInitialUpdate
DEBUG running Quirks.bionicPostInitialUpdate
DEBUG abort called

After some troubleshooting I found that it was failing on calling 'snap debug connectivity'.
Snap version I had was a bit old, which caused it to fail with panic on slice out of range.

The issue is insufficient logging. Because of the actual error was not logged, It was impossible to find the issue without code debugging.

It would be awesome if you can put more logs into _checkStoreConnectivity function and log stderr and stdout output from popen.communicate before calling self.controller.abort()

Also it would be extremely useful to log traceback from abort. Can simplify the troubleshooting dramatically.

Thanks.

[Brian Murray (brian-murray)]

From which release were you upgrading? I ask as the release upgrader should require you to have all updates installed before doing the upgrade. I do see your point about how more verbose logging would be helpful.

[sergiiF (framin)]

FRom: 16.04 LTS
To: 18.04 LTS

Snippet of the function that maid the troubleshooting process painful:
https://pastebin.com/pFdSRP0e

I don't have all the details, since that upgrader was downloaded to /tmp folder that gone away after reboot.

[sergiiF (framin)]

I didn't go deep enough do understand what _checkStoreConnectivity was called for. It might happen that was just a part of updates validation.

I'd like to make it clear - I do understand that having snap version old is my fault. The ticket I created is against the logging that doesn't allow to figure out what is going wrong.

It would be awesome to have:
1. More logging in _checkStoreConnectivity before calling abort()
2. Logging the traceback from def abort function. Having this traceback in the log can help people to 'google' the issue they have much easier.

Thank you!

[Brian Murray (brian-murray)]

On Tue, Jan 08, 2019 at 06:02:42PM -0000, sergiiF wrote:
> I didn't go deep enough do understand what _checkStoreConnectivity was
> called for. It might happen that was just a part of updates validation.
>
> I'd like to make it clear - I do understand that having snap version old
> is my fault. The ticket I created is against the logging that doesn't
> allow to figure out what is going wrong.

I understand that and what you are looking for, but I'm also concerned
about there being another bug in that the upgrader allowed you to
upgrade without having the latest version of snap installed. Could you
answer my original question regarding which release from which you were
upgrading? It'd also help to know the version of the release upgrader
you used - you can find that in /var/log/dist-upgrade/main.log.

Thanks!

--
Brian Murray

[sergiiF (framin)]

2019-01-03 21:02:19,137 INFO uname information: 'Linux skashaba-laptop 4.4.0-83-gene
ric #106-Ubuntu SMP Mon Jun 26 17:54:43 UTC 2017 x86_64'
2019-01-03 21:02:19,410 INFO apt version: '1.2.20'
2019-01-03 21:02:19,411 INFO python version: '3.5.2 (default, Nov 17 2016, 17:05:23)

[GCC 5.4.0 20160609]'
2019-01-03 21:02:19,413 INFO release-upgrader version '18.04.29' started

[sergiiF (framin)]

All logs from there:
2019-01-03 21:02:19,137 INFO Using config files '['./DistUpgrade.cfg.xenial']'
2019-01-03 21:02:19,137 INFO uname information: 'Linux skashaba-laptop 4.4.0-83-gene
ric #106-Ubuntu SMP Mon Jun 26 17:54:43 UTC 2017 x86_64'
2019-01-03 21:02:19,410 INFO apt version: '1.2.20'
2019-01-03 21:02:19,411 INFO python version: '3.5.2 (default, Nov 17 2016, 17:05:23)

[GCC 5.4.0 20160609]'
2019-01-03 21:02:19,413 INFO release-upgrader version '18.04.29' started
2019-01-03 21:02:19,417 INFO locale: 'en_US' 'UTF-8'
2019-01-03 21:02:19,460 INFO screen could not be run
2019-01-03 21:02:19,520 DEBUG Using 'DistUpgradeViewText' view
2019-01-03 21:02:19,563 DEBUG enable dpkg --force-overwrite
2019-01-03 21:02:19,583 DEBUG creating statefile: '/var/log/dist-upgrade/apt-clone_s
ystem_state.tar.gz'
2019-01-03 21:02:21,398 DEBUG lsb-release: 'xenial'
2019-01-03 21:02:21,399 DEBUG _pythonSymlinkCheck run
2019-01-03 21:02:21,400 DEBUG openCache()
2019-01-03 21:02:21,400 DEBUG No such plugin directory: ./plugins
2019-01-03 21:02:21,400 DEBUG plugins for condition 'PreCacheOpen' are '[]'
2019-01-03 21:02:21,400 DEBUG plugins for condition 'bionicPreCacheOpen' are '[]'
2019-01-03 21:02:21,400 DEBUG plugins for condition 'from_xenialPreCacheOpen' are '[]'
2019-01-03 21:02:21,400 DEBUG quirks: running PreCacheOpen
2019-01-03 21:02:21,400 DEBUG running Quirks.PreCacheOpen
2019-01-03 21:02:21,851 DEBUG /openCache(), new cache size 81917
2019-01-03 21:02:21,852 DEBUG need_server_mode(): run in 'desktop' mode, (because of pkg 'ubuntu-desktop')
2019-01-03 21:02:21,852 DEBUG checkViewDepends()
2019-01-03 21:02:21,852 DEBUG running doUpdate() (showErrors=False)
2019-01-03 21:02:22,509 DEBUG openCache()
2019-01-03 21:02:23,003 DEBUG /openCache(), new cache size 81917
2019-01-03 21:02:23,004 DEBUG doPostInitialUpdate
2019-01-03 21:02:23,004 DEBUG plugins for condition 'PostInitialUpdate' are '[]'
2019-01-03 21:02:23,004 DEBUG plugins for condition 'bionicPostInitialUpdate' are '[]'
2019-01-03 21:02:23,004 DEBUG plugins for condition 'from_xenialPostInitialUpdate' are '[]'
2019-01-03 21:02:23,004 DEBUG quirks: running bionicPostInitialUpdate
2019-01-03 21:02:23,004 DEBUG running Quirks.bionicPostInitialUpdate
2019-01-03 21:02:23,016 DEBUG abort called
2019-01-03 21:16:41,405 DEBUG openCache()
2019-01-03 21:16:41,405 DEBUG failed to SystemUnLock() (E:Not locked)
2019-01-03 21:16:41,904 DEBUG /openCache(), new cache size 81917

[Steve Dodd (anarchetic)]

This hit me trying to run a container upgrade in an environment where snapd wasn't running. Not a supported situation I'm sure but the extra logging would be good - just capturing the "snap debug connectivity" output and dumping to log would be fine..

[Steve Dodd (anarchetic)]

Bug #1926267 is related.