Error: websocket: close 1006 (abnormal closure): unexpected EOF - Can't launch or exec containers

dlanced · June 29, 2023, 3:46pm

I’m suddenly unable to start, exec, or stop LXD containers on my Ubuntu 22.04 system. Here’s what I’m seeing (base is my container name):

$ lxd --version
5.15
$ lxc stop base
Error: Put "http://unix.socket/1.0/instances/base/state": EOF
$ lxc exec base /bin/bash
root@base:~# Error: websocket: close 1006 (abnormal closure): unexpected EOF

When I run lxc ls I’m shown that only one of my four containers is running, but even that one can’t be executed etc.
Running journalctl -u snap.lxd.daemon -n 300 gives me output including this:

Jun 29 10:40:05 workstation lxd.daemon[1975976]: main.main()
Jun 29 10:40:05 workstation lxd.daemon[1975976]:         /build/lxd/parts/lxd/src/lxd/main.go:220 +0x1b05
Jun 29 10:40:05 workstation lxd.daemon[1975799]: Killed
Jun 29 10:40:05 workstation lxd.daemon[1975799]: => LXD failed to start
Jun 29 10:40:05 workstation systemd[1]: snap.lxd.daemon.service: Main process exited, code=exited, status=1/FAILURE
Jun 29 10:40:05 workstation systemd[1]: snap.lxd.daemon.service: Failed with result 'exit-code'.

Running systemctl stop snap.lxd.daemon.service snap.lxd.daemon.unix.socket and then lxd --debug --group lxd ends with a crash, but does produce this output:

DEBUG  [2023-06-29T11:44:27-04:00] Connecting to a local LXD over a Unix socket 
DEBUG  [2023-06-29T11:44:27-04:00] Sending request to LXD                        etag= method=GET url="http://unix.socket/1.0"
INFO   [2023-06-29T11:44:27-04:00] LXD is starting                               mode=normal path=/var/snap/lxd/common/lxd version=5.15
INFO   [2023-06-29T11:44:27-04:00] Kernel uid/gid map:                          
INFO   [2023-06-29T11:44:27-04:00]  - u 0 0 4294967295                          
INFO   [2023-06-29T11:44:27-04:00]  - g 0 0 4294967295                          
INFO   [2023-06-29T11:44:27-04:00] Configured LXD uid/gid map:                  
INFO   [2023-06-29T11:44:27-04:00]  - u 0 1000000 1000000000                    
INFO   [2023-06-29T11:44:27-04:00]  - g 0 1000000 1000000000                    
INFO   [2023-06-29T11:44:27-04:00] Kernel features:                             
INFO   [2023-06-29T11:44:27-04:00]  - closing multiple file descriptors efficiently: yes 
INFO   [2023-06-29T11:44:27-04:00]  - netnsid-based network retrieval: yes      
INFO   [2023-06-29T11:44:27-04:00]  - pidfds: yes                               
INFO   [2023-06-29T11:44:27-04:00]  - core scheduling: no                       
INFO   [2023-06-29T11:44:27-04:00]  - uevent injection: yes                     
INFO   [2023-06-29T11:44:27-04:00]  - seccomp listener: yes                     
INFO   [2023-06-29T11:44:27-04:00]  - seccomp listener continue syscalls: yes   
INFO   [2023-06-29T11:44:27-04:00]  - seccomp listener add file descriptors: yes 
INFO   [2023-06-29T11:44:27-04:00]  - attach to namespaces via pidfds: yes      
INFO   [2023-06-29T11:44:27-04:00]  - safe native terminal allocation : yes     
INFO   [2023-06-29T11:44:27-04:00]  - unprivileged file capabilities: yes       
INFO   [2023-06-29T11:44:27-04:00]  - cgroup layout: cgroup2                    
WARNING[2023-06-29T11:44:27-04:00]  - Couldn't find the CGroup hugetlb controller, hugepage limits will be ignored 
WARNING[2023-06-29T11:44:27-04:00]  - Couldn't find the CGroup network priority controller, network priority will be ignored 
INFO   [2023-06-29T11:44:27-04:00]  - shiftfs support: yes                      
INFO   [2023-06-29T11:44:27-04:00]  - idmapped mounts kernel support: yes       
INFO   [2023-06-29T11:44:27-04:00] Instance type operational                     driver=lxc features="map[]" type=container
WARNING[2023-06-29T11:44:27-04:00] Instance type not operational                 driver=qemu err="KVM support is missing (no /dev/kvm)" type=virtual-machine
INFO   [2023-06-29T11:44:27-04:00] Initializing local database                  
DEBUG  [2023-06-29T11:44:27-04:00] Refreshing local trusted certificate cache   
INFO   [2023-06-29T11:44:27-04:00] Set client certificate to server certificate  fingerprint=95fa00b3e78c7e854bf018c08dd8714495a3123cfdefbf7783e3768b4d551221
DEBUG  [2023-06-29T11:44:27-04:00] Initializing database gateway                
INFO   [2023-06-29T11:44:27-04:00] Starting database node                        id=1 local=1 role=voter
INFO   [2023-06-29T11:44:28-04:00] Loading daemon configuration                 
DEBUG  [2023-06-29T11:44:28-04:00] Connecting to a local LXD over a Unix socket 
DEBUG  [2023-06-29T11:44:28-04:00] Sending request to LXD                        etag= method=GET url="http://unix.socket/1.0"
DEBUG  [2023-06-29T11:44:28-04:00] Detected stale unix socket, deleting         
DEBUG  [2023-06-29T11:44:28-04:00] Detected stale unix socket, deleting         
INFO   [2023-06-29T11:44:28-04:00] Binding socket                                socket="[::]:8443" type="REST API TCP socket"
INFO   [2023-06-29T11:44:28-04:00] Binding socket                                socket=/var/snap/lxd/common/lxd/unix.socket type="REST API Unix socket"
INFO   [2023-06-29T11:44:28-04:00] Binding socket                                socket=/var/snap/lxd/common/lxd/devlxd/sock type="devlxd socket"
INFO   [2023-06-29T11:44:28-04:00] Initializing global database                 
INFO   [2023-06-29T11:44:28-04:00] Connecting to global database                
DEBUG  [2023-06-29T11:44:28-04:00] Dqlite: attempt 1: server 1: connected       
INFO   [2023-06-29T11:44:28-04:00] Connected to global database                 
INFO   [2023-06-29T11:44:28-04:00] Initialized global database                  
INFO   [2023-06-29T11:44:28-04:00] Firewall loaded driver                        driver=nftables
INFO   [2023-06-29T11:44:28-04:00] Initializing storage pools                   
DEBUG  [2023-06-29T11:44:28-04:00] Initializing storage pool                     pool=default
DEBUG  [2023-06-29T11:44:28-04:00] Mount started                                 driver=zfs pool=default
DEBUG  [2023-06-29T11:44:28-04:00] Mount finished                                driver=zfs pool=default
INFO   [2023-06-29T11:44:28-04:00] Initialized storage pool                      pool=default
INFO   [2023-06-29T11:44:28-04:00] All storage pools initialized                
INFO   [2023-06-29T11:44:28-04:00] Initializing daemon storage mounts           
INFO   [2023-06-29T11:44:28-04:00] Initializing networks                        
DEBUG  [2023-06-29T11:44:28-04:00] Start                                         driver=bridge network=lxdbr0 project=default
DEBUG  [2023-06-29T11:44:28-04:00] Setting up network                            driver=bridge network=lxdbr0 project=default
DEBUG  [2023-06-29T11:44:28-04:00] Stable MAC generated                          driver=bridge hwAddr="00:16:3e:40:f5:6d" network=lxdbr0 project=default seed=95fa00b3e78c7e854bf018c08dd8714495a3123cfdefbf7783e3768b4d551221.0.1
DEBUG  [2023-06-29T11:44:28-04:00] Clearing firewall                             driver=bridge network=lxdbr0 project=default
DEBUG  [2023-06-29T11:44:29-04:00] Setting up firewall                           driver=bridge network=lxdbr0 project=default
INFO   [2023-06-29T11:44:29-04:00] Initialized network                           name=lxdbr0 project=default
INFO   [2023-06-29T11:44:29-04:00] All networks initialized                     
DEBUG  [2023-06-29T11:44:29-04:00] New operation                                 class=task description="Pruning leftover image files" operation=e3cd1f57-a891-4219-b95d-806f46124af6 project=
DEBUG  [2023-06-29T11:44:29-04:00] Acquiring image task lock                    
DEBUG  [2023-06-29T11:44:29-04:00] Acquired image task lock                     
INFO   [2023-06-29T11:44:29-04:00] Cleaning up leftover image files             
DEBUG  [2023-06-29T11:44:29-04:00] Started operation                             class=task description="Pruning leftover image files" operation=e3cd1f57-a891-4219-b95d-806f46124af6 project=
INFO   [2023-06-29T11:44:29-04:00] Done cleaning up leftover image files        
DEBUG  [2023-06-29T11:44:29-04:00] Success for operation                         class=task description="Pruning leftover image files" operation=e3cd1f57-a891-4219-b95d-806f46124af6 project=
INFO   [2023-06-29T11:44:29-04:00] Starting device monitor                      
INFO   [2023-06-29T11:44:29-04:00] Initialized filesystem monitor                driver=fanotify path=/dev
DEBUG  [2023-06-29T11:44:29-04:00] Registering running instances                
DEBUG  [2023-06-29T11:44:29-04:00] Initialising mounted disk ref counter         device=root driver=disk instance=base project=default
DEBUG  [2023-06-29T11:44:29-04:00] MountInstance started                         driver=zfs instance=base pool=default project=default
DEBUG  [2023-06-29T11:44:29-04:00] MountInstance finished                        driver=zfs instance=base pool=default project=default
INFO   [2023-06-29T11:44:29-04:00] Started seccomp handler                       path=/var/snap/lxd/common/lxd/seccomp.socket
DEBUG  [2023-06-29T11:44:29-04:00] Refreshing trusted certificate cache         
DEBUG  [2023-06-29T11:44:29-04:00] New operation                                 class=task description="Cleaning up expired images" operation=77b299cc-f86c-4173-a923-a80c9cd444dd project=
DEBUG  [2023-06-29T11:44:29-04:00] Acquiring image task lock                    
DEBUG  [2023-06-29T11:44:29-04:00] Acquired image task lock                     
INFO   [2023-06-29T11:44:29-04:00] Pruning expired images                       
DEBUG  [2023-06-29T11:44:29-04:00] Started operation                             class=task description="Cleaning up expired images" operation=77b299cc-f86c-4173-a923-a80c9cd444dd project=
DEBUG  [2023-06-29T11:44:29-04:00] Success for operation                         class=task description="Cleaning up expired images" operation=77b299cc-f86c-4173-a923-a80c9cd444dd project=
INFO   [2023-06-29T11:44:29-04:00] Done pruning expired images                  
DEBUG  [2023-06-29T11:44:29-04:00] New operation                                 class=task description="Cleaning up expired instance backups" operation=1cc8a122-f656-44c2-b816-0d3c89daf34b project=
INFO   [2023-06-29T11:44:29-04:00] Pruning expired instance backups             
DEBUG  [2023-06-29T11:44:29-04:00] Started operation                             class=task description="Cleaning up expired instance backups" operation=1cc8a122-f656-44c2-b816-0d3c89daf34b project=
DEBUG  [2023-06-29T11:44:29-04:00] Success for operation                         class=task description="Cleaning up expired instance backups" operation=1cc8a122-f656-44c2-b816-0d3c89daf34b project=
INFO   [2023-06-29T11:44:29-04:00] Done pruning expired instance backups        
DEBUG  [2023-06-29T11:44:29-04:00] Start started                                 instance=container instanceType=virtual-machine project=default stateful=false
DEBUG  [2023-06-29T11:44:29-04:00] Instance operation lock created               action=start instance=container project=default reusable=false
DEBUG  [2023-06-29T11:44:29-04:00] New operation                                 class=task description="Updating instance types" operation=6bc28300-ae56-4b1d-9497-81126470fec3 project=
INFO   [2023-06-29T11:44:29-04:00] Updating instance types                      
DEBUG  [2023-06-29T11:44:29-04:00] Started operation                             class=task description="Updating instance types" operation=6bc28300-ae56-4b1d-9497-81126470fec3 project=
DEBUG  [2023-06-29T11:44:29-04:00] New operation                                 class=task description="Updating images" operation=bc526969-386a-47f5-b6a0-0c7e5e6b061f project=
DEBUG  [2023-06-29T11:44:29-04:00] Acquiring image task lock                    
DEBUG  [2023-06-29T11:44:29-04:00] Acquired image task lock                     
INFO   [2023-06-29T11:44:29-04:00] Updating images                              
DEBUG  [2023-06-29T11:44:29-04:00] Started operation                             class=task description="Updating images" operation=bc526969-386a-47f5-b6a0-0c7e5e6b061f project=
DEBUG  [2023-06-29T11:44:29-04:00] New operation                                 class=task description="Expiring log files" operation=df47118e-01f4-4726-b2d3-c8d69c52caaa project=
INFO   [2023-06-29T11:44:29-04:00] Expiring log files                           
DEBUG  [2023-06-29T11:44:29-04:00] Started operation                             class=task description="Expiring log files" operation=df47118e-01f4-4726-b2d3-c8d69c52caaa project=
DEBUG  [2023-06-29T11:44:29-04:00] Success for operation                         class=task description="Updating images" operation=bc526969-386a-47f5-b6a0-0c7e5e6b061f project=
INFO   [2023-06-29T11:44:29-04:00] Done updating images                         
DEBUG  [2023-06-29T11:44:29-04:00] MountInstance started                         driver=zfs instance=container pool=default project=default
INFO   [2023-06-29T11:44:29-04:00] Done expiring log files                      
DEBUG  [2023-06-29T11:44:29-04:00] Success for operation                         class=task description="Expiring log files" operation=df47118e-01f4-4726-b2d3-c8d69c52caaa project=
DEBUG  [2023-06-29T11:44:29-04:00] New operation                                 class=task description="Pruning resolved warnings" operation=0f6f9c0f-b581-4928-9b4d-fb8f2a10fa03 project=
INFO   [2023-06-29T11:44:29-04:00] Pruning resolved warnings                    
DEBUG  [2023-06-29T11:44:29-04:00] Started operation                             class=task description="Pruning resolved warnings" operation=0f6f9c0f-b581-4928-9b4d-fb8f2a10fa03 project=
DEBUG  [2023-06-29T11:44:29-04:00] Success for operation                         class=task description="Pruning resolved warnings" operation=0f6f9c0f-b581-4928-9b4d-fb8f2a10fa03 project=
INFO   [2023-06-29T11:44:29-04:00] Done pruning resolved warnings               
DEBUG  [2023-06-29T11:44:29-04:00] Success for operation                         class=task description="Updating instance types" operation=6bc28300-ae56-4b1d-9497-81126470fec3 project=
INFO   [2023-06-29T11:44:29-04:00] Done updating instance types                 
DEBUG  [2023-06-29T11:44:30-04:00] Activated ZFS volume                          dev=default/virtual-machines/container.block driver=zfs pool=default volName=container
DEBUG  [2023-06-29T11:44:30-04:00] Mounted ZFS dataset                           dev=default/virtual-machines/container driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/default/virtual-machines/container pool=default volName=container
DEBUG  [2023-06-29T11:44:30-04:00] MountInstance finished                        driver=zfs instance=container pool=default project=default
DEBUG  [2023-06-29T11:44:30-04:00] UnmountInstance started                       driver=zfs instance=container pool=default project=default
DEBUG  [2023-06-29T11:44:30-04:00] Unmounted ZFS dataset                         dev=default/virtual-machines/container driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/default/virtual-machines/container pool=default volName=container
DEBUG  [2023-06-29T11:44:30-04:00] Deactivated ZFS volume                        dev=default/virtual-machines/container.block driver=zfs pool=default volName=container
DEBUG  [2023-06-29T11:44:30-04:00] UnmountInstance finished                      driver=zfs instance=container pool=default project=default
DEBUG  [2023-06-29T11:44:30-04:00] Instance operation lock finished              action=start err="<nil>" instance=container project=default reusable=false
DEBUG  [2023-06-29T11:44:30-04:00] Start finished                                instance=container instanceType=virtual-machine project=default stateful=false
INFO   [2023-06-29T11:44:30-04:00] Daemon stopped                               
panic: interface conversion: interface {} is nil, not int

goroutine 1 [running]:
github.com/lxc/lxd/lxd/instance/drivers.(*qemu).vsockID(...)
	/build/lxd/parts/lxd/src/lxd/instance/drivers/driver_qemu.go:7437
github.com/lxc/lxd/lxd/instance/drivers.(*qemu).start(0xc000385380, 0x0, 0x0)
	/build/lxd/parts/lxd/src/lxd/instance/drivers/driver_qemu.go:1156 +0x5289
github.com/lxc/lxd/lxd/instance/drivers.(*qemu).Start(0xc000385380, 0x80?)
	/build/lxd/parts/lxd/src/lxd/instance/drivers/driver_qemu.go:1072 +0x68
main.instancesStart(0xc00087aa90, {0xc000936080?, 0x5, 0x2e4c260?})
	/build/lxd/parts/lxd/src/lxd/instances.go:280 +0x8fd
main.(*Daemon).init(0xc0003c7000)
	/build/lxd/parts/lxd/src/lxd/daemon.go:1590 +0x51b4
main.(*Daemon).Init(0xc0003c7000)
	/build/lxd/parts/lxd/src/lxd/daemon.go:728 +0x68
main.(*cmdDaemon).Run(0xc000478e28, 0x0?, {0xc000473590, 0x0, 0x0?})
	/build/lxd/parts/lxd/src/lxd/main_daemon.go:77 +0x56f
github.com/spf13/cobra.(*Command).execute(0xc000004f00, {0xc000040090, 0x3, 0x3})
	/build/lxd/parts/lxd/src/.go/pkg/mod/github.com/spf13/cobra@v1.7.0/command.go:940 +0x862
github.com/spf13/cobra.(*Command).ExecuteC(0xc000004f00)
	/build/lxd/parts/lxd/src/.go/pkg/mod/github.com/spf13/cobra@v1.7.0/command.go:1068 +0x3bd
github.com/spf13/cobra.(*Command).Execute(...)
	/build/lxd/parts/lxd/src/.go/pkg/mod/github.com/spf13/cobra@v1.7.0/command.go:992
main.main()
	/build/lxd/parts/lxd/src/lxd/main.go:220 +0x1b05

I’ve seen similar topics (including this one) but they haven’t helped for me.
Any ideas?
Thanks!

tomp · June 29, 2023, 4:41pm

What does

snap info lxd

Show?

dlanced · June 29, 2023, 4:52pm

Here:

$ snap info lxd
name:      lxd
summary:   LXD - container and VM manager
publisher: Canonical✓
store-url: https://snapcraft.io/lxd
contact:   https://github.com/lxc/lxd/issues
license:   unset
[...]
commands:
  - lxd.benchmark
  - lxd.buginfo
  - lxd.check-kernel
  - lxd.lxc
  - lxd.lxc-to-lxd
  - lxd
  - lxd.migrate
services:
  lxd.activate:    oneshot, enabled, inactive
  lxd.daemon:      simple, enabled, inactive
  lxd.user-daemon: simple, enabled, inactive
snap-id:      J60k4JY0HppjwOjW8dZdYc8obXKxujRu
tracking:     latest/stable
refresh-date: 2 days ago, at 17:04 EDT
channels:
  latest/stable:    5.15-3fe7435  2023-06-28 (25086) 181MB -
  latest/candidate: 5.15-3fe7435  2023-06-26 (25086) 181MB -
  latest/beta:      ↑                                      
  latest/edge:      git-46a660e   2023-06-29 (25101) 181MB -
  5.15/stable:      5.15-3fe7435  2023-06-28 (25086) 181MB -
  5.15/candidate:   5.15-3fe7435  2023-06-28 (25086) 181MB -
  5.15/beta:        ↑                                      
  5.15/edge:        ↑                                      
  5.14/stable:      –                                      
  5.14/candidate:   5.14-7072c7b  2023-05-31 (24918) 178MB -
  5.14/beta:        ↑                                      
  5.14/edge:        ↑                                      
  5.13/stable:      5.13-8e2d7eb  2023-05-31 (24846) 174MB -
  5.13/candidate:   ↑                                      
  5.13/beta:        ↑                                      
  5.13/edge:        ↑                                      
  5.0/stable:       5.0.2-838e1b2 2023-01-25 (24322) 117MB -
  5.0/candidate:    5.0.2-838e1b2 2023-01-18 (24322) 117MB -
  5.0/beta:         ↑                                      
  5.0/edge:         git-2a04cf3   2023-04-15 (24732) 118MB -
  4.0/stable:       4.0.9-a29c6f1 2022-12-04 (24061)  96MB -
  4.0/candidate:    4.0.9-a29c6f1 2022-12-02 (24061)  96MB -
  4.0/beta:         ↑                                      
  4.0/edge:         git-407205d   2022-11-22 (23988)  96MB -
  3.0/stable:       3.0.4         2019-10-10 (11348)  55MB -
  3.0/candidate:    3.0.4         2019-10-10 (11348)  55MB -
  3.0/beta:         ↑                                      
  3.0/edge:         git-81b81b9   2019-10-10 (11362)  55MB -
installed:          5.15-3fe7435             (25086) 181MB -

Thanks!

tomp · June 29, 2023, 6:05pm

Is your “container” instance actually a vm?

dlanced · June 29, 2023, 6:18pm

At least three of them are regular containers. It’s possible that the fourth is a VM - I can’t remember and lxc config show base | grep 'config:/n image' doesn’t work right now.

tomp · June 30, 2023, 7:19am

I have reproduced this issue.
It looks like at one point in time you had /dev/kvm (so VM support) on your system and so were able to create a VM (called “container” in this case ) but now your system doesn’t have /dev/kvm support but the VM still exists and when it is started it is causing LXD to crash rather than give an error about the lack of VM support.

This is what has changed in LXD 5.15.

I am working on a fix.

tomp · June 30, 2023, 8:15am

I’m going to cherry-pick the changes from https://github.com/lxc/lxd/pull/11896 into latest/* as this will fix the issue (in that LXD will be able to start, but the VM itself will still be not startable until you get /dev/kvm available again).

dlanced · June 30, 2023, 1:30pm

I upgraded LXD with:

snap refresh lxd --edge

…and everything is working beautifully again.
Thanks so much!

tomp · June 30, 2023, 2:02pm

Great, I’m going to push to latest/stable on Monday.