Snap changes unusable while changes in flight

snapd
1

Not sure this is a bug or just my laptop. (ThinkPad i7 / SSD /32GB RAM). I kicked off a snap refresh 15 mins ago. It’s still chugging away (as you can see, it’s refreshing quite a few snaps). I wanted to see what’s happening, so I thought I’d use snap changes and snap change (changeid).

It took 2 mins 41 seconds to return the output of the snap change (changeid) command.

5223  Doing   today at 08:46 GMT        -                         Refresh snaps "qownnotes", "azimuth", "gnome-3-32-1804", "lxd", "chromium", "rslauncher", "wire", "gtk2-common-themes", "youtube-dl", "waterfox-snap", "mumble", "ddgr", "epicpinball", "figma-linux", "minetest", "olivia", "opensurge", "core", "doctl", "review-tools", "thunderbird", "caprine", "lemmings-christmas", "starship", "simplenote", "gedit", "inkscape", "mame", "shellcheck", "mgba", "gnome-characters", "hugo", "obs-studio", "yakyak", "mindustry"

alan@KinkPad-K450:~$ snap change 5223
^C
alan@KinkPad-K450:~$ time snap change 5223

The output of snap change 5223 is too long for this forum, so it’s here https://paste.ubuntu.com/p/r8kyGXqTVD/

Granted, the system is quite busy while these snaps are refreshing…

alan@KinkPad-K450:~$ dstat
You did not select any stats, using -cdngy by default.
--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw 
 60  12  28   0   0| 491k  956k|   0     0 |1439B  137k|2432  5728 
 81  19   0   0   0|4096B 3660k| 657k   12k|   0     0 |3450  8635 
 74  26   0   0   0|   0  1196k|7694B 2926B|   0     0 |2293  4103 
 72  28   0   0   0|   0     0 |3313B 2078B|   0     0 |2895  9853 
 74  26   0   0   0|  16k  432k|5354B 5400B|   0     0 |5842    19k
 74  24   1   1   0|1775k   15M|8014B   32k|   0     0 |2371  4889 
 76  23   0   0   0|   0  1728k|5294B 6094B|   0     0 |1966  3391 
 76  24   0   0   0|   0  1804k|2907B 2002B|   0     0 |2021  3801 
 76  24   0   0   0|   0  1516k|3639B 1989B|   0     0 |3205  7240 
 76  24   0   0   0|   0     0 |5425B 3405B|   0     0 |1754  3233 
 71  29   0   0   0|   0  5304k|5462B   20k|   0     0 |4053    14k
 77  22   1   0   0|  20k 4148k|5036B 2913B|   0     0 |2953  8452 
 75  24   0   1   0|   0    12M|3434B 1564B|   0     0 |2068  4180 
 77  23   0   0   0|   0    88k|3235B 1811B|   0     0 |2034  3237 
 75  24   1   0   0|   0  6944k|4227B 4462B|   0     0 |2310  4506 
 76  23   0   1   0|   0  7072k|3479B 2355B|   0     0 |2020  3903 
 76  24   0   0   0|   0     0 |3136B 2077B|   0     0 |1775  3037 
 74  24   1   1   0| 926k   11M|2689B 1669B|   0     0 |2268  4039 
 80  20   0   0   0|   0  3456k|2542B 1882B|   0     0 |1888  3375 
 77  23   0   0   0|   0   640k|3715B 2868B|   0     0 |1899  3033 
 75  24   0   0   0|   0  3568k|7273B 4952B|   0     0 |3347    10k
 77  22   0   0   0|  12k 6252k|5242B   13k|   0     0 |1940  3457 
 67  32   0   0   0| 372k 2068k|4883B 5486B|   0     0 |4259    12k
 73  24   2   1   0|1198k 7868k|3757B 1630B|   0     0 |4440    13k
 75  24   0   0   0| 196k 5188k|5826B 5748B|   0     0 |3063  7817 ^C
alan@KinkPad-K450:~$

Time passes…

Now it’s finished, snap change (changeid) is fast again:

alan@KinkPad-K450:~$ time snap change 5223 | tail
2020-02-06T08:48:51Z INFO Waiting for restart...
2020-02-06T08:48:52Z INFO Waiting for restart...
2020-02-06T08:51:03Z INFO cannot auto-connect slot core:avahi-observe to plug remmina:avahi-observe, candidates found: avahi:avahi-observe, core:avahi-observe
2020-02-06T08:51:03Z INFO cannot auto-connect slot core:avahi-observe to plug firefox:avahi-observe, candidates found: avahi:avahi-observe, core:avahi-observe

......................................................................
Consider re-refresh of "qownnotes", "azimuth", "gnome-3-32-1804", "lxd", "chromium", "rslauncher", "wire", "gtk2-common-themes", "youtube-dl", "waterfox-snap", "mumble", "ddgr", "epicpinball", "figma-linux", "minetest", "olivia", "opensurge", "core", "doctl", "review-tools", "thunderbird", "caprine", "lemmings-christmas", "starship", "simplenote", "gedit", "inkscape", "mame", "shellcheck", "mgba", "gnome-characters", "hugo", "obs-studio", "yakyak", "mindustry"

2020-02-06T09:04:31Z INFO No re-refreshes found.


real	0m0.092s
user	0m0.055s
sys	0m0.030s

So, given snap changes and snap change (changeid) are likely to be used to answer the questions “What changed on my system recently?” and “What’s changing right now?” it feels like it can only be serviceably used for the former, not the latter. Given there are no log files for me to tail (think /var/log/dpkg.log) to see what’s going on, is it time to re-think the way we log changes? I have previously lamented the problem that snap changes is held in memory and thus lost after a while, so there’s no historical archive of changes (e.g. over a weekend). The above example (to me) indicates a further reason our snap logging needs a re-think.

2 Likes
2

I just tried again while snap refresh was only updating 3 snaps. It took 52 seconds for snap change (changeid) to respond.

3

Observed the same thing yesterday. A device was busy chugging away with snapd using up a lot of CPU, but there was seemingly no way to figure out what it’s actually doing. After running snap changes it actually didn’t respond for so long, I assumed it had just crashed, so I Ctrl-C’ed it out of its misery.

And indeed, I couldn’t help but wish there was plain old (journald) log somewhere that I could just tail.

1 Like
4

Happens to me as well.

I also like to see more specific info from snap changes instead of generic “auto-refresh snap xyz”:
“updated chromium from 79.0 to 80.0”
snap list could be more helpful as well and display a column with an update timestamp, so I could understand which snaps updated when.

1 Like
5

Yes, snap changes is pretty limited in the information it provides; maybe try snap tasks <change_id> since that provides more detailed info on what’s actually happening/happened?

6

As I understand it snap tasks <change_id> is just a synonym for snap changes <change_id> and as such is equally blocked and unhelpful while changes are in flight.

I am having this issue again.
The only way I can see that changes are actually happening is having dmesg -Tw running in another terminal and see apparmor changes being applied. Neither snap changes, snap change or snap tasks is helpful while changes are in flight:-

This is running:

5427 Doing today at 23:46 GMT - Refresh snaps "syncthing", "youtube-dl", "gedit", "gnome-characters", "vokoscreen-ng", "core", "fluffychat", "mame", "beebeep", "chromium", "mindustry", "waterfox-snap", "pick-colour-picker", "obs-studio", "simplenote", "thelounge", "qownnotes", "epicpinball", "spt", "opentoonz", "slack", "helm", "review-tools", "code", "wine-platform-runtime", "x16emu", "wire", "irccloud-desktop", "brackets", "irssi", "stress-ng", "insomnia", "lemmings-christmas", "starship", "makemkv", "mdl", "inkscape", "mumble", "minetest", "spek", "mgba", "libreoffice", "cobalt", "gitter-desktop", "irccloud", "olivia", "ubuntu-mate-welcome"

The snap change 5427 and snap tasks 5427 terminal windows are just sat there doing nothing, while the dmesg -Tw terminal is full of:-

[Wed Feb 12 06:54:36 2020] audit: type=1400 audit(1581811022.851:75746): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/core/8689/usr/lib/snapd/snap-confine" pid=3913102 comm="apparmor_parser"
[Wed Feb 12 06:54:36 2020] audit: type=1400 audit(1581811022.851:75747): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="/snap/core/8689/usr/lib/snapd/snap-confine//mount-namespace-capture-helper" pid=3913102 comm="apparmor_parser"
[Wed Feb 12 06:54:37 2020] audit: type=1400 audit(1581811023.659:75748): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap-update-ns.insomnia" pid=3913108 comm="apparmor_parser"
[Wed Feb 12 06:54:37 2020] audit: type=1400 audit(1581811023.763:75749): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="snap.insomnia.insomnia" pid=3913109 comm="apparmor_parser"
[Wed Feb 12 06:54:37 2020] audit: type=1400 audit(1581811023.771:75750): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap-update-ns.core" pid=3913120 comm="apparmor_parser"
[Wed Feb 12 06:54:37 2020] audit: type=1400 audit(1581811023.779:75751): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="snap.core.hook.configure" pid=3913121 comm="apparmor_parser"