panic: assignment to entry in nil map

[Lutchy Horace (lhprojects)]

This morning I was tinkering with LXD snap and attempting to enable shiftfs with the following 'snap set lxd shiftfs.enable=true' which eventually failed with error: 'cannot communicate with server: Get "http://localhost/v2/changes/184": dial unix /run/snapd.socket: connect: connection refused.'. I attempted to launch snapd manually, but that to failed as well:

AppArmor status: apparmor is enabled but some kernel features are missing: dbus, network
2021/03/17 11:38:45.553940 patch.go:64: Patching system state level 6 to sublevel 1...
2021/03/17 11:38:45.565885 patch.go:64: Patching system state level 6 to sublevel 2...
2021/03/17 11:38:45.575843 patch.go:64: Patching system state level 6 to sublevel 3...
2021/03/17 11:38:45.597315 daemon.go:347: started snapd/2.49-1.12 (series 16; classic; devmode) opensuse-tumbleweed/20210219 (amd64) linux/5.11.2-1-default.
2021/03/17 11:38:45.703533 daemon.go:440: adjusting startup timeout by 1m55s (pessimistic estimate of 30s plus 5s per snap)
2021/03/17 11:38:46.983230 stateengine.go:150: state ensure error: cannot sections: got unexpected HTTP status code 403 via GET to "https://api.snapcraft.io/api/v1/snaps/sections"
panic: assignment to entry in nil map

goroutine 28 [running]:
github.com/snapcore/snapd/overlord/configstate/config.applyChanges(0x0, 0xc0008ab230)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/configstate/config/transaction.go:306 +0x146
github.com/snapcore/snapd/overlord/configstate/config.(*Transaction).Commit(0xc00055fa80)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/configstate/config/transaction.go:293 +0x1f4
github.com/snapcore/snapd/overlord/configstate.ContextTransaction.func1(0x4500000003, 0x7467fef0971e)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/configstate/hooks.go:53 +0x35
github.com/snapcore/snapd/overlord/hookstate.(*Context).Done(0xc0001dd960, 0x0, 0x0)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/hookstate/context.go:264 +0x84
github.com/snapcore/snapd/overlord/hookstate.(*HookManager).runHook(0xc0004961e0, 0xc0001dd960, 0xc0004e4700, 0xc000822400, 0xc000715d10, 0x0, 0x0)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/hookstate/hookmgr.go:416 +0x650
github.com/snapcore/snapd/overlord/hookstate.(*HookManager).runHookForTask(0xc0004961e0, 0xc0003d2c60, 0xc000715d10, 0xc0004e4700, 0xc000822400, 0x0, 0x0)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/hookstate/hookmgr.go:312 +0xba
github.com/snapcore/snapd/overlord/hookstate.(*HookManager).doRunHook(0xc0004961e0, 0xc0003d2c60, 0xc000715d10, 0x228f178, 0x7467f72ccb0b)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/hookstate/hookmgr.go:264 +0x168
github.com/snapcore/snapd/overlord/state.(*TaskRunner).run.func1(0x0, 0x0)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/state/taskrunner.go:203 +0xe3
github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc000715d10, 0xc00083e030)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x3a
created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xbc

I'm not sure if the 403 forbidden with 'https://api.snapcraft.io/api/v1/snaps/sections' is contributing to this crash, if it's the case, this seems like a hard dependency is it not? Is there anything I can do to workaround this problem permanently?

Is removing/re-isntalling snapd would fix this? If so, how would this affect LXD?

[Lutchy Horace (lhprojects) (lhprojects)]

Additional information:

AppArmor status: apparmor is enabled but some kernel features are missing: dbus, network
2021/03/18 04:01:31.987438 tool_linux.go:68: DEBUG: re-exec not supported on distro "opensuse-tumbleweed" yet
2021/03/18 04:01:32.009203 activation.go:64: DEBUG: socket "/run/snapd.socket" was not activated; listening
2021/03/18 04:01:32.009235 activation.go:64: DEBUG: socket "/run/snapd-snap.socket" was not activated; listening
2021/03/18 04:01:32.009565 daemon.go:347: started snapd/2.49-1.12 (series 16; classic; devmode) opensuse-tumbleweed/20210219 (amd64) linux/5.11.2-1-default.
2021/03/18 04:01:32.067532 daemon.go:440: adjusting startup timeout by 1m55s (pessimistic estimate of 30s plus 5s per snap)
2021/03/18 04:01:32.118220 standby.go:96: DEBUG: will consider standby after: 5s
2021/03/18 04:01:32.118257 main.go:149: DEBUG: activation done in 131ms
2021/03/18 04:01:32.118996 autorefresh.go:281: DEBUG: Next refresh scheduled for 2021-03-18T11:50:39-04:00.
2021/03/18 04:01:32.171611 taskrunner.go:439: DEBUG: Running task 5210 on Doing: Run configure hook of "lxd" snap
2021/03/18 04:01:32.208239 daemon.go:317: DEBUG: pid=2770;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 5.327179ms 200
2021/03/18 04:01:32.216307 daemon.go:317: DEBUG: pid=2784;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.581301ms 200
2021/03/18 04:01:32.224490 daemon.go:317: DEBUG: pid=2797;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.781967ms 200
2021/03/18 04:01:32.232189 daemon.go:317: DEBUG: pid=2906;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.048712ms 200
2021/03/18 04:01:32.239438 daemon.go:317: DEBUG: pid=2922;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.371767ms 200
2021/03/18 04:01:32.246775 daemon.go:317: DEBUG: pid=2929;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.309491ms 200
2021/03/18 04:01:32.255246 daemon.go:317: DEBUG: pid=2959;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.397896ms 200
2021/03/18 04:01:32.263233 daemon.go:317: DEBUG: pid=2972;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.381776ms 200
2021/03/18 04:01:32.270966 daemon.go:317: DEBUG: pid=2989;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.419637ms 200
2021/03/18 04:01:32.278735 daemon.go:317: DEBUG: pid=3047;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.081965ms 200
2021/03/18 04:01:32.286999 daemon.go:317: DEBUG: pid=3058;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.831018ms 200
2021/03/18 04:01:32.295576 daemon.go:317: DEBUG: pid=3114;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 5.043768ms 200
2021/03/18 04:01:32.303833 daemon.go:317: DEBUG: pid=3127;uid=0;socket=/run/snapd-snap.socket; POST /v2/snapctl 4.886243ms 200
panic: assignment to entry in nil map

goroutine 58 [running]:
github.com/snapcore/snapd/overlord/configstate/config.applyChanges(0x0, 0xc000253b90)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/snapcore/snapd/overlord/configstate/config/transaction.go:306 +0x146
github.com/snapcore/snapd/overlord/configstate/config.(*Transaction).Commit(0xc00085e8a0)
        /home/abuild/rpmbuild/BUILD/snapd-2.49/gopath/src/github.com/sn...

[Paweł Stołowski (stolowski)]

Hi, thanks for the report.

Question: did you use snapshots for lxd snap and restored it at any point (i.e. `snap restore ...`) before hitting this? We had a bug around that fixed just a few days ago with https://github.com/snapcore/snapd/pull/10007 and I wonder if this is the same root cause.

[Paweł Stołowski (stolowski)]

Regarding your question about remove/reinstall, `snap remove lxd` would remove /var/snap/lxd/common which is where all your container data is kept (we do create automatic snapshot of it on remove though, which you can later restore, although you would still hit the above bug).

One way of working around this:
1. When snapd is not running, do:
sudo snap debug state /var/lib/snapd/state.json
and note the ID of a latest "configure-snap" change that is in progress.

2. Restart snapd with `sudo systemctl restart snapd` and quickly execute `snap abort ID` (use the ID from step 1); repeat this step as necessary if it hangs before you execute abort.

Sorry about the inconvenience caused by this bug.

[Lutchy Horace (lhprojects) (lhprojects)]

If I'm not mistaken, I recall asking a question surrounding the functionality of 'snap snapshots' in the past. IIRC, those are done automatically?

Technically speaking, I've actually saw that PR but unfortunately I can't view the LP bug report, so I'm unable to determine if the code path is the same. The cursory look at the code, I would wager is likely the fix to my problem.

As far as 'snapd', I just nuked it completely and re-installed it with lxd.

[Paweł Stołowski (stolowski)]

Snapshots are done automatically on snap removal - yes, but to trigger the bug that https://github.com/snapcore/snapd/pull/10007 fixes you would need at some point to restore such snapshot (which is a manual action), after which snap set ... would cause the panic.

Would be great to know if you ever restored a lxd snapshot manually, because if not, then this may mean we have another potential trigger for the problem elsewhere in the code (but it will still be covered by the above fix).