Unable to create new lxd container, snapd init fail

Question

Unable to create new lxd container, snapd init fail

Opened this issue 24 days ago · 0 comments

Required information

Distribution: ArchLinux
Distribution version: N/A

The output of "snap list --all lxd core20 core22 core24 snapd":

In the container

Name   Version  Rev    Tracking       Publisher   Notes
snapd  2.66.1   23258  latest/stable  canonical✓  snapd

In the host

 checkbox (report_what_failed) >  snap list --all lxd core20 core22 core24 snapd
Name    Version      Rev    Tracking       Publisher   Notes
core20  20240705     2379   latest/stable  canonical✓ 
base,disabled
core20  20240911     2434   latest/stable  canonical✓  base
core22  20241001     1663   latest/stable  canonical✓  
base,disabled
core22  20241119     1722   latest/stable  canonical✓  base
core24  20241210     733    latest/edge    canonical✓  base,disabled
core24  20241217     739    latest/edge    canonical✓  base
lxd     6.1-78a3d8f  30130  latest/stable  canonical✓  disabled
lxd     6.2-afb00d0  31571  latest/stable  canonical✓  -
snapd   2.66.1       23258  latest/beta    canonical✓  snapd,disabled
snapd   2.67         23545  latest/beta    canonical✓  snapd

The output of "lxc info" or if that fails:
- Kernel version:
```
Linux h25 6.12.4-arch1-1 #1 SMP PREEMPT_DYNAMIC Mon, 09 Dec 2024 14:31:57 +0000 x86_64 GNU/Linux
```
- LXC version: 6.2
- LXD version: 6.2
- Storage backend in use: btrfs

Issue description

Initializing a lxd container never terminates on my personal machine. Cloud init doesn't seem to terminate remaining in the status running.

root@metabox-local-jammy-source-current:~# cloud-init status --long
status: running
extended_status: running
boot_status_code: enabled-by-generator
last_update: Thu, 01 Jan 1970 00:00:01 +0000
detail: DataSourceLXD
errors: []
recoverable_errors: {}

While this is happening it seems that snapd is restarting over and over trying to set up the lxd daemon (in the container) but it can't do it because lxd was never installed so the service it is trying to start fails

root@metabox-local-jammy-source-current:~# journalctl -u snapd
[...] #basically looping journal
Dec 19 16:22:41 metabox-local-jammy-source-current systemd[1]: Started Snap Daemon.
Dec 19 16:22:44 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:22:46 metabox-local-jammy-source-current snapd[100073]: daemon.go:548: gracefully waiting for running hooks
Dec 19 16:22:46 metabox-local-jammy-source-current snapd[100073]: daemon.go:550: done waiting for running hooks
Dec 19 16:22:49 metabox-local-jammy-source-current snapd[100073]: overlord.go:518: Released state lock file
Dec 19 16:22:49 metabox-local-jammy-source-current systemd[1]: snapd.service: Deactivated successfully.
Dec 19 16:22:49 metabox-local-jammy-source-current systemd[1]: snapd.service: Consumed 7.190s CPU time.
Dec 19 16:22:49 metabox-local-jammy-source-current systemd[1]: snapd.service: Scheduled restart job, restart counter is at 158.
Dec 19 16:22:49 metabox-local-jammy-source-current systemd[1]: Stopped Snap Daemon.
Dec 19 16:22:49 metabox-local-jammy-source-current systemd[1]: snapd.service: Consumed 7.190s CPU time.
Dec 19 16:22:49 metabox-local-jammy-source-current systemd[1]: Starting Snap Daemon...
Dec 19 16:22:49 metabox-local-jammy-source-current snapd[100551]: overlord.go:274: Acquiring state lock file
Dec 19 16:22:49 metabox-local-jammy-source-current snapd[100551]: overlord.go:279: Acquired state lock file
Dec 19 16:22:50 metabox-local-jammy-source-current snapd[100551]: daemon.go:250: started snapd/2.66.1+22.04 (series 16; classic; devmode) ubuntu/22.04 (amd64) linu>
Dec 19 16:22:50 metabox-local-jammy-source-current snapd[100551]: daemon.go:353: adjusting startup timeout by 35s (pessimistic estimate of 30s plus 5s per snap)
Dec 19 16:22:50 metabox-local-jammy-source-current snapd[100551]: backends.go:58: AppArmor status: apparmor is enabled but some kernel features are missing: dbus, >
Dec 19 16:22:50 metabox-local-jammy-source-current systemd[1]: Started Snap Daemon.
Dec 19 16:22:55 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:01 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:05 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:12 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:13 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:13 metabox-local-jammy-source-current snapd[100551]: taskrunner.go:299: Change 152 task (Start snap "lxd" (31333) services) failed: systemctl command >
Dec 19 16:23:13 metabox-local-jammy-source-current snapd[100551]: Job for snap.lxd.activate.service failed because the control process exited with error code.
Dec 19 16:23:13 metabox-local-jammy-source-current snapd[100551]: See "systemctl status snap.lxd.activate.service" and "journalctl -xeu snap.lxd.activate.service" >
Dec 19 16:23:18 metabox-local-jammy-source-current snapd[100551]: services.go:1128: RemoveSnapServices - socket snap.lxd.daemon.unix.socket
Dec 19 16:23:18 metabox-local-jammy-source-current snapd[100551]: services.go:1152: RemoveSnapServices - disabling snap.lxd.daemon.service
Dec 19 16:23:18 metabox-local-jammy-source-current snapd[100551]: services.go:1128: RemoveSnapServices - socket snap.lxd.user-daemon.unix.socket
Dec 19 16:23:18 metabox-local-jammy-source-current snapd[100551]: services.go:1152: RemoveSnapServices - disabling snap.lxd.user-daemon.service
Dec 19 16:23:18 metabox-local-jammy-source-current snapd[100551]: services.go:1152: RemoveSnapServices - disabling snap.lxd.activate.service
Dec 19 16:23:19 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:20 metabox-local-jammy-source-current snapd[100551]: copydata.go:98: Cannot remove common data directories for "lxd": unlinkat /var/snap/lxd/common/va>
Dec 19 16:23:20 metabox-local-jammy-source-current snapd[100551]: taskrunner.go:299: Change 152 task (Copy snap "lxd" data) failed: unlinkat /var/snap/lxd/common/v>
Dec 19 16:23:21 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:25 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:29 metabox-local-jammy-source-current snapd[100551]: daemon.go:548: gracefully waiting for running hooks
Dec 19 16:23:29 metabox-local-jammy-source-current snapd[100551]: daemon.go:550: done waiting for running hooks
Dec 19 16:23:30 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:31 metabox-local-jammy-source-current snapd[100551]: overlord.go:518: Released state lock file
Dec 19 16:23:31 metabox-local-jammy-source-current systemd[1]: snapd.service: Deactivated successfully.
Dec 19 16:23:31 metabox-local-jammy-source-current systemd[1]: snapd.service: Consumed 58.129s CPU time.
Dec 19 16:23:32 metabox-local-jammy-source-current systemd[1]: snapd.service: Scheduled restart job, restart counter is at 159.
Dec 19 16:23:32 metabox-local-jammy-source-current systemd[1]: Stopped Snap Daemon.
Dec 19 16:23:32 metabox-local-jammy-source-current systemd[1]: snapd.service: Consumed 58.129s CPU time.
Dec 19 16:23:32 metabox-local-jammy-source-current systemd[1]: Starting Snap Daemon...
Dec 19 16:23:32 metabox-local-jammy-source-current snapd[101368]: overlord.go:274: Acquiring state lock file
Dec 19 16:23:32 metabox-local-jammy-source-current snapd[101368]: overlord.go:279: Acquired state lock file
Dec 19 16:23:32 metabox-local-jammy-source-current snapd[101368]: daemon.go:250: started snapd/2.66.1+22.04 (series 16; classic; devmode) ubuntu/22.04 (amd64) linu>
Dec 19 16:23:32 metabox-local-jammy-source-current snapd[101368]: daemon.go:353: adjusting startup timeout by 30s (pessimistic estimate of 30s plus 5s per snap)
Dec 19 16:23:32 metabox-local-jammy-source-current snapd[101368]: backends.go:58: AppArmor status: apparmor is enabled but some kernel features are missing: dbus, >
Dec 19 16:23:33 metabox-local-jammy-source-current systemd[1]: Started Snap Daemon.
Dec 19 16:23:36 metabox-local-jammy-source-current systemd[1]: /lib/systemd/system/snapd.service:23: Unknown key name 'RestartMode' in section 'Service', ignoring.
Dec 19 16:23:39 metabox-local-jammy-source-current snapd[101368]: daemon.go:548: gracefully waiting for running hooks
Dec 19 16:23:39 metabox-local-jammy-source-current snapd[101368]: daemon.go:550: done waiting for running hooks
Dec 19 16:23:41 metabox-local-jammy-source-current snapd[101368]: overlord.go:518: Released state lock file
Dec 19 16:23:41 metabox-local-jammy-source-current systemd[1]: snapd.service: Deactivated successfully.
Dec 19 16:23:41 metabox-local-jammy-source-current systemd[1]: snapd.service: Consumed 7.602s CPU time.
Dec 19 16:23:42 metabox-local-jammy-source-current systemd[1]: snapd.service: Scheduled restart job, restart counter is at 160.
Dec 19 16:23:42 metabox-local-jammy-source-current systemd[1]: Stopped Snap Daemon.

root@metabox-local-jammy-source-current:~# journalctl -xeu snap.lxd.activate.service
[...] # looping
Dec 19 16:25:52 metabox-local-jammy-source-current systemd[1]: Starting Service for snap application lxd.activate...
Dec 19 16:25:52 metabox-local-jammy-source-current systemd[1]: snap.lxd.activate.service: Main process exited, code=exited, status=1/FAILURE
Dec 19 16:25:52 metabox-local-jammy-source-current systemd[1]: snap.lxd.activate.service: Failed with result 'exit-code'.
Dec 19 16:25:52 metabox-local-jammy-source-current systemd[1]: Failed to start Service for snap application lxd.activate.

Steps to reproduce

lxc launch ubuntu:jammy jammy
lxc shell jammy
cloud-init staus --long

Information to attach

Any relevant kernel output (dmesg)

Seems to be writing quite a few of these

[227873.581095] audit: type=1400 audit(1734625765.752:11080): apparmor="STATUS" operation="profile_replace" label="lxd-metabox-local-jammy-source-current_</var/snap/lxd/common/lxd>//&:lxd-metabox-local-jammy-source-current_<var-snap-lxd-common-lxd>:unconfined" name="snap.lxd.hook.remove" pid=1782851 comm="apparmor_parser"

Container log (lxc info NAME --show-log) (Not truncated, actually no logs)

(venv)  checkbox (report_what_failed) >  lxc info metabox-local-jammy-source-current --show-log
   Name: metabox-local-jammy-source-current
   Status: RUNNING
   Type: container
   Architecture: x86_64
   PID: 1622123
   Created: 2024/12/19 15:38 CET
   Last Used: 2024/12/19 16:27 CET
   
   Resources:
     Processes: 73
     CPU usage:
       CPU usage (in seconds): 5144
     Memory usage:
       Memory (current): 331.21MiB
     Network usage:
       eth0:
         Type: broadcast
         State: UP
         Host interface: vethc8ff13d1
         MAC address: 00:16:3e:8c:f8:85
         MTU: 1500
         Bytes received: 10.11kB
         Bytes sent: 5.72kB
         Packets received: 90
         Packets sent: 55
         IP addresses:
           inet:  10.191.126.243/24 (global)
           inet6: fd42:56bf:cbff:18c7:216:3eff:fe8c:f885/64 (global)
           inet6: fe80::216:3eff:fe8c:f885/64 (link)
       lo:
         Type: loopback
         State: UP
         MTU: 65536
         Bytes received: 396B
         Bytes sent: 396B
         Packets received: 4
         Packets sent: 4
         IP addresses:
           inet:  127.0.0.1/8 (local)
           inet6: ::1/128 (local)
   
   Log:

Container configuration (lxc config show NAME --expanded)

(venv)  checkbox (report_what_failed) >  lxc config show metabox-local-jammy-source-current --expanded
  architecture: x86_64
  config:
    environment.DISPLAY: :0
    image.architecture: amd64
    image.description: ubuntu 22.04 LTS amd64 (release) (20241217)
    image.label: release
    image.os: ubuntu
    image.release: jammy
    image.serial: "20241217"
    image.type: squashfs
    image.version: "22.04"
    raw.idmap: both 1000 1000
    user.user-data: |
      #cloud-config
      runcmd:
        - 'sed -i "s/; enable-shm = yes/enable-shm = no/g" /etc/pulse/client.conf'
        - "perl -i -p0e 's/(Unit.*?)\n\n/$1\nConditionVirtualization=!container\n\n/s' /lib/systemd/system/systemd-remount-fs.service"
        - 'echo export XAUTHORITY=/run/user/1000/gdm/Xauthority | tee --append /home/ubuntu/.profile'
      apt:
        sources:
          stable_ppa:
            source: "ppa:checkbox-dev/stable"
      packages:
        - jq
        - python3-jinja2
        - python3-markupsafe
        - python3-packaging
        - python3-pip
        - python3-psutil
        - python3-pyparsing
        - python3-requests-oauthlib
        - python3-urwid
        - python3-xlsxwriter
        - virtualenv
    volatile.base_image: 42ac4cf1ed33cb2de4c2582252786bd15f5bbeea79436af4ed010b81b2b45fb5
    volatile.cloud-init.instance-id: baa332ff-b01e-4581-9f7c-1bd1d5bbfce3
    volatile.eth0.host_name: vethc8ff13d1
    volatile.eth0.hwaddr: 00:16:3e:8c:f8:85
    volatile.idmap.base: "0"
    volatile.idmap.current: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000},{"Isuid":true,"Isgid":false,"Hostid":1000,"Nsid":1000,"Maprange":1},{"Isuid":true,"Isgid":false,"Hostid":1001001,"Nsid":1001,"Maprange":999998999},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000},{"Isuid":false,"Isgid":true,"Hostid":1000,"Nsid":1000,"Maprange":1},{"Isuid":false,"Isgid":true,"Hostid":1001001,"Nsid":1001,"Maprange":999998999}]'
    volatile.idmap.next: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000},{"Isuid":true,"Isgid":false,"Hostid":1000,"Nsid":1000,"Maprange":1},{"Isuid":true,"Isgid":false,"Hostid":1001001,"Nsid":1001,"Maprange":999998999},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000},{"Isuid":false,"Isgid":true,"Hostid":1000,"Nsid":1000,"Maprange":1},{"Isuid":false,"Isgid":true,"Hostid":1001001,"Nsid":1001,"Maprange":999998999}]'
    volatile.last_state.idmap: '[]'
    volatile.last_state.power: RUNNING
    volatile.last_state.ready: "false"
    volatile.uuid: 674ab049-01af-44d7-a10e-9366a3866a6a
    volatile.uuid.generation: 674ab049-01af-44d7-a10e-9366a3866a6a
  devices:
    eth0:
      name: eth0
      network: lxdbr0
      type: nic
    root:
      path: /
      pool: default
      type: disk
  ephemeral: false
  profiles:
  - default
  - checkbox
  stateful: false
  description: ""

Main daemon log (at /var/log/lxd/lxd.log or /var/snap/lxd/common/lxd/logs/lxd.log)

(venv)  checkbox (report_what_failed) >  sudo cat /var/snap/lxd/common/lxd/logs/lxd.log
time="2024-12-12T15:16:48+01:00" level=warning msg=" - Couldn't find the CGroup network priority controller, per-instance network priority will be ignored. Please use per-device limits.priority instead"
time="2024-12-19T15:30:16+01:00" level=warning msg="SFTP server stopped with error" err="signal: terminated" instance=metabox-local-jammy-source-current instanceType=container project=default stderr=

Output of the client with --debug
Output of the daemon with --debug (alternatively output of lxc monitor while reproducing the issue)