snap auto-refresh breaks cluster

[eug48]

This morning a close-to-production cluster fell over after snap's auto-refresh "feature" failed on 3 of 4 worker nodes - looks like it hanged at the Copy snap "microk8s" data step. microk8s could be restarted after aborting the auto-refresh, but this only worked after manually killing snapd.. For a production-ready Kubernetes distribution I really think this is a far from acceptable default.. Perhaps until snapd allows disabling auto-refreshes microk8s scripts could recommend running sudo snap set system refresh.hold=2050-01-01T15:04:05Z or similar. Also a kubernetes-native integration with snapd refreshes could be considered (e.g. a prometheus/grafana dashboard/alert) to prompt manual updates - presumably one node at a time to begin with.

Otherwise microk8s is working rather well so thank you very much.

More details about the outage:

kubectl get nodes
NAME           STATUS     ROLES    AGE   VERSION
10.aa.aa.aaa   Ready      <none>   38d   v1.17.3
10.aa.aa.aaa   NotReady   <none>   18d   v1.17.2
10.aa.aa.aaa   NotReady   <none>   38d   v1.17.2
10.aa.aa.aaa   NotReady   <none>   18d   v1.17.2
aaa-master     Ready      <none>   59d   v1.17.3

microk8s is disabled..

root@wk3:/home# snap list
Name      Version    Rev   Tracking  Publisher   Notes
core      16-2.43.3  8689  stable    canonical✓  core
kubectl   1.17.3     1424  1.17      canonical✓  classic
microk8s  v1.17.2    1176  1.17      canonical✓  disabled,classic

root@wk3:/home# snap changes microk8s
ID   Status  Spawn                Ready  Summary
20   Doing   today at 09:56 AEDT  -      Auto-refresh snap "microk8s"

Data copy appears hanged

root@wk3:/home# snap tasks --last=auto-refresh
Status  Spawn                Ready                Summary
Done    today at 09:56 AEDT  today at 09:56 AEDT  Ensure prerequisites for "microk8s" are available
Done    today at 09:56 AEDT  today at 09:56 AEDT  Download snap "microk8s" (1254) from channel "1.17/stable"
Done    today at 09:56 AEDT  today at 09:56 AEDT  Fetch and check assertions for snap "microk8s" (1254)
Done    today at 09:56 AEDT  today at 09:56 AEDT  Mount snap "microk8s" (1254)
Done    today at 09:56 AEDT  today at 09:56 AEDT  Run pre-refresh hook of "microk8s" snap if present
Done    today at 09:56 AEDT  today at 09:57 AEDT  Stop snap "microk8s" services
Done    today at 09:56 AEDT  today at 09:57 AEDT  Remove aliases for snap "microk8s"
Done    today at 09:56 AEDT  today at 09:57 AEDT  Make current revision for snap "microk8s" unavailable
Doing   today at 09:56 AEDT  -                    Copy snap "microk8s" data
Do      today at 09:56 AEDT  -                    Setup snap "microk8s" (1254) security profiles
Do      today at 09:56 AEDT  -                    Make snap "microk8s" (1254) available to the system
Do      today at 09:56 AEDT  -                    Automatically connect eligible plugs and slots of snap "microk8s"
Do      today at 09:56 AEDT  -                    Set automatic aliases for snap "microk8s"
Do      today at 09:56 AEDT  -                    Setup snap "microk8s" aliases
Do      today at 09:56 AEDT  -                    Run post-refresh hook of "microk8s" snap if present
Do      today at 09:56 AEDT  -                    Start snap "microk8s" (1254) services
Do      today at 09:56 AEDT  -                    Clean up "microk8s" (1254) install
Do      today at 09:56 AEDT  -                    Run configure hook of "microk8s" snap if present
Do      today at 09:56 AEDT  -                    Run health check of "microk8s" snap
Doing   today at 09:56 AEDT  -                    Consider re-refresh of "microk8s"

There doesn't seem to be much to copy anyway:

root@wk3 /v/l/snapd# du -sh /var/lib/snapd/ /var/snap/ /snap
527M	/var/lib/snapd/
74G	/var/snap/
2.0G	/snap

root@wk3 /s/microk8s# du -sh /snap/microk8s/*
737M	/snap/microk8s/1176
737M	/snap/microk8s/1254

root@wk3 /s/microk8s# du -sh /var/snap/microk8s/*
232K	/var/snap/microk8s/1176
74G	/var/snap/microk8s/common

Starting microk8s fails

user@wk3 /s/m/1254> sudo snap start microk8s
error: snap "microk8s" has "auto-refresh" change in progress

root@wk3:/home# snap enable microk8s
error: snap "microk8s" has "auto-refresh" change in progress

Fails to abort..

root@wk3:/home# snap abort 20
root@wk3:/home# snap changes
ID   Status  Spawn                Ready  Summary
20   Abort   today at 09:56 AEDT  -      Auto-refresh snap "microk8s"

user@wk3 /s/m/1254> sudo snap start microk8s
error: snap "microk8s" has "auto-refresh" change in progress

root@wk3:/home# snap enable microk8s
error: snap "microk8s" has "auto-refresh" change in progress

snapd service hangs when trying to stop it...

root@wk2 ~# systemctl stop snapd.service
(hangs)

have to resort to manually stopping the process

killall snapd

finally change is undone..

root@wk3:/home# snap changes
ID   Status  Spawn                Ready                Summary
20   Undone  today at 09:56 AEDT  today at 10:41 AEDT  Auto-refresh snap "microk8s"

root@wk3:/home# snap tasks --last=auto-refresh
Status  Spawn                Ready                Summary
Done    today at 09:56 AEDT  today at 10:41 AEDT  Ensure prerequisites for "microk8s" are available
Undone  today at 09:56 AEDT  today at 10:41 AEDT  Download snap "microk8s" (1254) from channel "1.17/stable"
Done    today at 09:56 AEDT  today at 10:41 AEDT  Fetch and check assertions for snap "microk8s" (1254)
Undone  today at 09:56 AEDT  today at 10:41 AEDT  Mount snap "microk8s" (1254)
Undone  today at 09:56 AEDT  today at 10:41 AEDT  Run pre-refresh hook of "microk8s" snap if present
Undone  today at 09:56 AEDT  today at 10:41 AEDT  Stop snap "microk8s" services
Undone  today at 09:56 AEDT  today at 10:41 AEDT  Remove aliases for snap "microk8s"
Undone  today at 09:56 AEDT  today at 10:41 AEDT  Make current revision for snap "microk8s" unavailable
Undone  today at 09:56 AEDT  today at 10:41 AEDT  Copy snap "microk8s" data
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Setup snap "microk8s" (1254) security profiles
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Make snap "microk8s" (1254) available to the system
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Automatically connect eligible plugs and slots of snap "microk8s"
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Set automatic aliases for snap "microk8s"
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Setup snap "microk8s" aliases
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Run post-refresh hook of "microk8s" snap if present
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Start snap "microk8s" (1254) services
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Clean up "microk8s" (1254) install
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Run configure hook of "microk8s" snap if present
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Run health check of "microk8s" snap
Hold    today at 09:56 AEDT  today at 10:30 AEDT  Consider re-refresh of "microk8s

root@wk3:/home# snap list
Name      Version    Rev   Tracking  Publisher   Notes
core      16-2.43.3  8689  stable    canonical✓  core
kubectl   1.17.3     1424  1.17      canonical✓  classic
microk8s  v1.17.2    1176  1.17      canonical✓  classic

Nothing much in snapd logs except for a polkit error - unsure if related:

root@wk3:/home# journalctl -b -u snapd.service

...
Mar 09 06:11:34 wk3 snapd[15182]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Mar 09 16:11:31 wk3 snapd[15182]: storehelpers.go:436: cannot refresh: snap has no updates available: "core", "kubectl", "microk8s"
Mar 09 16:11:31 wk3 snapd[15182]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Mar 09 19:06:31 wk3 snapd[15182]: storehelpers.go:436: cannot refresh: snap has no updates available: "core", "kubectl", "microk8s"
Mar 09 19:06:31 wk3 snapd[15182]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Mar 10 02:51:31 wk3 snapd[15182]: storehelpers.go:436: cannot refresh: snap has no updates available: "core", "kubectl", "microk8s"
Mar 10 02:51:31 wk3 snapd[15182]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Mar 10 09:56:31 wk3 snapd[15182]: storehelpers.go:436: cannot refresh: snap has no updates available: "core", "kubectl"
Mar 10 10:12:18 wk3 snapd[15182]: daemon.go:208: polkit error: Authorization requires interaction
Mar 10 10:39:24 wk3 systemd[1]: Stopping Snappy daemon...
Mar 10 10:39:24 wk3 snapd[15182]: main.go:155: Exiting on terminated signal.
Mar 10 10:40:54 wk3 systemd[1]: snapd.service: State 'stop-sigterm' timed out. Killing.
Mar 10 10:40:54 wk3 systemd[1]: snapd.service: Killing process 15182 (snapd) with signal SIGKILL.
Mar 10 10:40:54 wk3 systemd[1]: snapd.service: Main process exited, code=killed, status=9/KILL
Mar 10 10:40:54 wk3 systemd[1]: snapd.service: Failed with result 'timeout'.
Mar 10 10:40:54 wk3 systemd[1]: Stopped Snappy daemon.
Mar 10 10:40:54 wk3 systemd[1]: snapd.service: Triggering OnFailure= dependencies.
Mar 10 10:40:54 wk3 systemd[1]: snapd.service: Found left-over process 16729 (sync) in control group while starting unit. Ignoring.
Mar 10 10:40:54 wk3 systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 10 10:40:54 wk3 systemd[1]: Starting Snappy daemon...
Mar 10 10:40:54 wk3 snapd[18170]: AppArmor status: apparmor is enabled and all features are available
Mar 10 10:40:54 wk3 snapd[18170]: AppArmor status: apparmor is enabled and all features are available
Mar 10 10:40:54 wk3 snapd[18170]: daemon.go:346: started snapd/2.43.3 (series 16; classic) ubuntu/18.04 (amd64) linux/4.15.0-88-generic.
Mar 10 10:40:54 wk3 snapd[18170]: daemon.go:439: adjusting startup timeout by 45s (pessimistic estimate of 30s plus 5s per snap)
Mar 10 10:40:54 wk3 systemd[1]: Started Snappy daemon.

[eug48]

I've left one worker node in the stuck state in case that's useful for troubleshooting, and have now come across a well-known issue in that pods running on that NotReady node are stuck as Terminating. With prometheus this is a problem because the StatefulSet will not start another instance until that pod is manually force-deleted. Just mentioning here as this is another reason why I think microk8s is not ready for auto-refreshes.

[ktsakalozos]

Thank you for reporting this @eug48. I opened an issue/topic with the snap team at [1].

One note here is that you cannot hold snap refreshes forever (sudo snap set system refresh.hold=2050-01-01T15:04:05Z does not work). You can defer refreshes for up to 90 days, I think. If you want to block refreshes you need to setup a snap store proxy [2]

[1] https://forum.snapcraft.io/t/snap-refresh-breaks-microk8s-cluster/15906
[2] https://docs.ubuntu.com/snap-store-proxy/en/

[eug48]

Thanks very much for raising that @ktsakalozos and correcting my incorrect assumption that refresh.hold would work long-term. I was misled by the lead sentence "Use refresh.hold to delay snap refreshes until a defined time and date." in snap docs (1) and by the command running without an error/warning.. Another lesson to not skim documentation..

[mvo5]

@eug48 sorry for the trouble and thanks for the report. The fact that it hangs during the copy-data phase is curious. I think you mentioned you have one node in the bad state?

It looks like the data in /var/snap/microk8s/ did not even got started to get copied, i.e. the new snaps data dir did not even get created, is this correct?

[eug48]

@mvo5 yes, /snap/microk8s/1254 got created but in /var/snap/microk8s/ there is only 1176.

Upon further investigation I've probably found the cause. I've been trying out rook-ceph and there is still a volume mounted with it:

/dev/rbd0 on /var/snap/microk8s/common/var/lib/kubelet/pods/4dbf852e-f740-4a9f-b72d-de1b50120983/volumes/kubernetes.io~csi/pvc-149ca422-8e37-48f4-b087-98cd31d06c43/mount type ext4 (rw,relatime,stripe=1024,data=ordered)

However trying to ls some sub-directories within it hangs forever and dmesg is full of errors like libceph: mon0 10.152.183.195:6789 socket error on read. So ceph is failing to connect to its service, which is running inside the cluster, but flanneld has been stopped.

sync also hangs forever and sure enough it looks like snapd has launched a sync on which it is presumably waiting.

So this is already a complex and therefore rather brittle set-up, and I think having snap auto-refreshes added to the mix makes failure much more likely. Having an option for it to be turned off permanently so that users can upgrade manually and fix these kinds of problems would be great for production use.

[ShadowJonathan]

For anyone reading this with the same issue, snapd currently doesnt allow any indefinite auto-update disabling, other than this suggestion through a forum thread with a bigger umbrella issue discussion about this; https://forum.snapcraft.io/t/disabling-automatic-refresh-for-snap-from-store/707/268

TL;DR: snap download foo ; snap install foo.snap --dangerous, replace foo with application in question.

Personally, the fact that snapd doesn't allow more comprehensive and cooperative options like (web)hooks on new snap version, and have an external system handle manual refreshes one-by-one (for example by draining a node first before refreshing it, running some canary checks on it, then doing the same one-by-one for the rest, reverting entirely on first error (+ autoemail describing failed upgrade)), would be of great help and would even be still within the ethos of keeping snaps up-to-date, but the system to trust sysadmins to make it so needs to be there.

[skobow]

I also have problems with my microk8s cluster that my be related to this issue. I am experiencing regular service failure that start almost exactly at 2am in a not yet discovered interval (some days). The exact service is a VerneMQ MQTT server that is using a MariaDB for authentication. The result is that authentication does not work after that (unknown) event happened. This event could relate to snap activities as I discovered some micro8ks restarting by snap around that time.
I also had this behavior with other services. My assumption is that the failure may be related to persistent network connections that fail on k8s level and the applications do not notice the failure. After rescheduling the corresponding pods everything works fine again.

I also would like to disable auto refresh for microk8s to further investigate the problem and to proof my assumption.
Does anyone have any other ideas?

[ktsakalozos]

Hi @skobow, is it possible you were following the latest/edge channel? What do you get from snap list | grep microk8s?

[skobow]

Hi @ktsakalozos, I am using 1.19/stable channel which currently installs v1.19.2

[ktsakalozos]

Nothing got released on 1.19/stable. You could attach the microk8s.inspect tarball so we can take a look.

[skobow]

Find the tarball attached.
The reason for my assumption is the output of snap changes that shows:

ID Status Spawn Ready Summary
166 Done today at 02:51 CEST today at 02:51 CEST Running service command for snap "microk8s"
167 Done today at 02:51 CEST today at 02:52 CEST Running service command for snap "microk8s"
168 Done today at 02:52 CEST today at 02:52 CEST Running service command for snap "microk8s"
169 Done today at 02:52 CEST today at 02:52 CEST Running service command for snap "microk8s"
170 Done today at 02:52 CEST today at 02:52 CEST Running service command for snap "microk8s"
171 Done today at 04:35 CEST today at 04:35 CEST Auto-refresh snaps "core", "snapd"
172 Done today at 04:51 CEST today at 04:51 CEST Running service command for snap "microk8s"
173 Done today at 04:51 CEST today at 04:52 CEST Running service command for snap "microk8s"
174 Done today at 04:52 CEST today at 04:52 CEST Running service command for snap "microk8s"
175 Done today at 04:52 CEST today at 04:52 CEST Running service command for snap "microk8s"
176 Done today at 04:52 CEST today at 04:52 CEST Running service command for snap "microk8s"
177 Done today at 05:08 CEST today at 05:08 CEST Running service command for snap "microk8s"
178 Done today at 05:08 CEST today at 05:08 CEST Running service command for snap "microk8s"
179 Done today at 05:08 CEST today at 05:08 CEST Running service command for snap "microk8s"
180 Done today at 05:08 CEST today at 05:08 CEST Running service command for snap "microk8s"
181 Done today at 05:08 CEST today at 05:08 CEST Running service command for snap "microk8s"
182 Error today at 10:27 CEST today at 10:27 CEST Change configuration of "core" snap
183 Done today at 10:29 CEST today at 10:29 CEST Change configuration of "core" snap

snap change 166then shows:

Status Spawn Ready Summary
Done today at 02:51 CEST today at 02:51 CEST restart of [microk8s.daemon-etcd]

The time stamps fit for the service stop working. Even though there might not be any updates something happens anyway. Could that be related?
inspection-report-20201014_103630.tar.gz

[skobow]

Hi! Fyi: exactly the same happened tonight at the same time. @ktsakalozos what are these service commands and why are they run?

[ktsakalozos]

I am not sure why snapd decides to restart MicroK8s. Could you attach the snapd log journalctl -u snapd -n 3000. If we do not see anything there we may need to ask over at https://forum.snapcraft.io/

[skobow]

@ktsakalozos find the log attached!

snapd.log

[skobow]

@ktsakalozos Any news on this topic?