`Multipass start` times out, VM state shown as "Unknown"

[yinchi]

Describe the bug

Multipass times out when starting a VM, and the VM ends up in the "Unknown" state. However, ssh'ing into the VM still works.

To Reproduce
How, and what happened?

1. multipass start -vvvv ycc39 --> Times out
2. multipass list --> Shows "ycc39" in the Unknown state
3. On another machine, ssh ycc39@10.123.1.1 -p 2201 -- netplan status -->

     Online state: online
    DNS Addresses: 127.0.0.53 (stub)
       DNS Search: .

●  1: lo ethernet UNKNOWN/UP (unmanaged)
      MAC Address: 00:00:00:00:00:00
        Addresses: 127.0.0.1/8
                   ::1/128

●  2: ens3 ethernet UP (networkd: default)
      MAC Address: 52:54:00:5c:d4:f7 (Red Hat, Inc.)
        Addresses: fe80::5054:ff:fe5c:d4f7/64 (link)
           Routes: fe80::/64 metric 256

●  3: ens4 ethernet UP (networkd: extra0)
      MAC Address: 02:ab:cd:ef:00:01 (Red Hat, Inc.)
        Addresses: 10.123.1.1/23
                   fe80::ab:cdff:feef:1/64 (link)
    DNS Addresses: 8.8.8.8
                   8.8.4.4
           Routes: default via 10.123.0.1 from 10.123.1.1 (static)
                   10.123.0.0/23 from 10.123.1.1 (link)
                   fe80::/64 metric 256

The ens3 network has no IPv4 address.

Expected behavior
The VM will start and be shown in multipass list as in the Running state.

Logs

[2024-11-23T13:15:42.401] [trace] [daemon] Loading AppArmor policy:

#include <tunables/global>
profile multipass.ycc39.qemu-system-x86_64 flags=(attach_disconnected) {
  #include <abstractions/base>
  #include <abstractions/consoles>
  #include <abstractions/nameservice>

  # required for reading disk images
  capability dac_override,
  capability dac_read_search,
  capability chown,

  # Enables modifying of file ownership and permissions
  capability fsetid,
  capability fowner,

  # needed to drop privileges
  capability setgid,
  capability setuid,

  network inet stream,
  network inet6 stream,

  # Allow multipassd send qemu signals
  signal (receive) peer=snap.multipass.multipassd,

  /dev/net/tun rw,
  /dev/kvm rw,
  /dev/ptmx rw,
  /dev/kqemu rw,
  @{PROC}/*/status r,
  # When qemu is signaled to terminate, it will read cmdline of signaling
  # process for reporting purposes. Allowing read access to a process
  # cmdline may leak sensitive information embedded in the cmdline.
  @{PROC}/@{pid}/cmdline r,
  # Per man(5) proc, the kernel enforces that a thread may
  # only modify its comm value or those in its thread group.
  owner @{PROC}/@{pid}/task/@{tid}/comm rw,
  @{PROC}/sys/kernel/cap_last_cap r,
  owner @{PROC}/*/auxv r,
  @{PROC}/sys/vm/overcommit_memory r,

  # access to firmware's etc (selectively chosen for multipass' usage)
  /snap/multipass/13698/qemu/* r,

  # for save and resume
  /{usr/,}bin/dash rmix,
  /{usr/,}bin/dd rmix,
  /{usr/,}bin/cat rmix,

  # to execute bridge helper
  /snap/multipass/13698/bin/bridge_helper,

  # for restore
  /{usr/,}bin/bash rmix,

  # for file-posix getting limits since 9103f1ce
  /sys/devices/**/block/*/queue/max_segments r,

  # for gathering information about available host resources
  /sys/devices/system/cpu/ r,
  /sys/devices/system/node/ r,
  /sys/devices/system/node/node[0-9]*/meminfo r,
  /sys/module/vhost/parameters/max_mem_regions r,

  # binary and its libs
  /snap/multipass/13698/usr/bin/qemu-system-x86_64 ixr,
  /snap/multipass/13698/{,usr/}lib/{,@{multiarch}/}{,**/}*.so* rm,

  # CLASSIC ONLY: need to specify required libs from core snap
  /{,var/lib/snapd/}snap/core18/*/{,usr/}lib/@{multiarch}/{,**/}*.so* rm,

  # Disk images
  /var/snap/multipass/common/data/multipassd/vault/instances/ycc39/ubuntu-24.04-server-cloudimg-amd64.img rwk,  # QCow2 filesystem image
  /var/snap/multipass/common/data/multipassd/vault/instances/ycc39/cloud-init-config.iso rk,   # cloud-init ISO

  # allow full access just to user-specified mount directories on the host
  
}
    
[2024-11-23T13:15:42.402] [warning] [apparmor] Failed to load AppArmor policy 
#include <tunables/global>
profile multipass.ycc39.qemu-system-x86_64 flags=(attach_disconnected) {
  #include <abstractions/base>
  #include <abstractions/consoles>
  #include <abstractions/nameservice>

  # required for reading disk images
  capability dac_override,
  capability dac_read_search,
  capability chown,

  # Enables modifying of file ownership and permissions
  capability fsetid,
  capability fowner,

  # needed to drop privileges
  capability setgid,
  capability setuid,

  network inet stream,
  network inet6 stream,

  # Allow multipassd send qemu signals
  signal (receive) peer=snap.multipass.multipassd,

  /dev/net/tun rw,
  /dev/kvm rw,
  /dev/ptmx rw,
  /dev/kqemu rw,
  @{PROC}/*/status r,
  # When qemu is signaled to terminate, it will read cmdline of signaling
  # process for reporting purposes. Allowing read access to a process
  # cmdline may leak sensitive information embedded in the cmdline.
  @{PROC}/@{pid}/cmdline r,
  # Per man(5) proc, the kernel enforces that a thread may
  # only modify its comm value or those in its thread group.
  owner @{PROC}/@{pid}/task/@{tid}/comm rw,
  @{PROC}/sys/kernel/cap_last_cap r,
  owner @{PROC}/*/auxv r,
  @{PROC}/sys/vm/overcommit_memory r,

  # access to firmware's etc (selectively chosen for multipass' usage)
  /snap/multipass/13698/qemu/* r,

  # for save and resume
  /{usr/,}bin/dash rmix,
  /{usr/,}bin/dd rmix,
  /{usr/,}bin/cat rmix,

  # to execute bridge helper
  /snap/multipass/13698/bin/bridge_helper,

  # for restore
  /{usr/,}bin/bash rmix,

  # for file-posix getting limits since 9103f1ce
  /sys/devices/**/block/*/queue/max_segments r,

  # for gathering information about available host resources
  /sys/devices/system/cpu/ r,
  /sys/devices/system/node/ r,
  /sys/devices/system/node/node[0-9]*/meminfo r,
  /sys/module/vhost/parameters/max_mem_regions r,

  # binary and its libs
  /snap/multipass/13698/usr/bin/qemu-system-x86_64 ixr,
  /snap/multipass/13698/{,usr/}lib/{,@{multiarch}/}{,**/}*.so* rm,

  # CLASSIC ONLY: need to specify required libs from core snap
  /{,var/lib/snapd/}snap/core18/*/{,usr/}lib/@{multiarch}/{,**/}*.so* rm,

  # Disk images
  /var/snap/multipass/common/data/multipassd/vault/instances/ycc39/ubuntu-24.04-server-cloudimg-amd64.img rwk,  # QCow2 filesystem image
  /var/snap/multipass/common/data/multipassd/vault/instances/ycc39/cloud-init-config.iso rk,   # cloud-init ISO

  # allow full access just to user-specified mount directories on the host
  
}
    : errno=10 ()
[2024-11-23T13:15:42.402] [debug] [ycc39] process working dir '/snap/multipass/13698/qemu'
[2024-11-23T13:15:42.402] [info] [ycc39] process program 'qemu-system-x86_64'
[2024-11-23T13:15:42.403] [info] [ycc39] process arguments '-bios, OVMF.fd, --enable-kvm, -cpu, host, -nic, tap,ifname=tap-ef2b6d13241,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:5c:d4:f7, -nic, bridge,br=br-multipass,model=virtio-net-pci,mac=02:ab:cd:ef:00:01,helper=/snap/multipass/13698/bin/bridge_helper, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/ycc39/ubuntu-24.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 2, -m, 2048M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/snap/multipass/common/data/multipassd/vault/instances/ycc39/cloud-init-config.iso'
[2024-11-23T13:15:42.415] [debug] [qemu-system-x86_64] [298216] started: qemu-system-x86_64 -nographic -dump-vmstate /tmp/multipassd.kgFUlR
[2024-11-23T13:15:42.464] [info] [ycc39] process state changed to Starting
[2024-11-23T13:15:42.480] [info] [ycc39] process state changed to Running
[2024-11-23T13:15:42.480] [debug] [qemu-system-x86_64] [298220] started: qemu-system-x86_64 -bios OVMF.fd --enable-kvm -cpu host -nic tap,ifname=tap-ef2b6d13241,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:5c:d4:f7 -nic bridge,br=br-multipass,model=virtio-net-pci,mac=02:ab:cd:ef:00:01,helper=/snap/multipass/13698/bin/bridge_helper -device virtio-scsi-pci,id=scsi0 -drive file=/var/snap/multipass/common/data/multipassd/vault/instances/ycc39/ubuntu-24.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 2 -m 2048M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/snap/multipass/common/data/multipassd/vault/instances/ycc39/cloud-init-config.iso
[2024-11-23T13:15:42.480] [info] [ycc39] process started
start failed: The following errors occurred:
ycc39: timed out waiting for response

Additional info

• OS: [Ubuntu 24.04LTS]

• multipass version
  multipass 1.15.0-dev.692+g2f0097baa
  multipassd 1.15.0-dev.692+g2f0097baa

• multipass info

Name:           primary
State:          Stopped
Snapshots:      0
IPv4:           --
Release:        --
Image hash:     b63f266fa4bd (Ubuntu 24.04 LTS)
CPU(s):         --
Load:           --
Disk usage:     --
Memory usage:   --
Mounts:         /home/serveradmin => Home
                    UID map: 1003:default
                    GID map: 1003:default

Name:           ycc39
State:          Unknown
Snapshots:      0
IPv4:           --
Release:        --
Image hash:     b63f266fa4bd (Ubuntu 24.04 LTS)
CPU(s):         --
Load:           --
Disk usage:     --
Memory usage:   --
Mounts:         --

• multipass get local.driver
  qemu

Additional context
Output of sudo iptables -t nat -S:

[sudo] password for serveradmin: 
-P PREROUTING ACCEPT
-P INPUT ACCEPT
-P OUTPUT ACCEPT
-P POSTROUTING ACCEPT
-N DOCKER
-A PREROUTING -p tcp -m tcp --dport 2201 -j DNAT --to-destination 10.123.1.1:22
-A PREROUTING -m addrtype --dst-type LOCAL -j DOCKER
-A OUTPUT ! -d 127.0.0.0/8 -m addrtype --dst-type LOCAL -j DOCKER
-A POSTROUTING -s 10.252.50.0/24 ! -d 10.252.50.0/24 -m comment --comment "generated for Multipass network mpqemubr0" -j MASQUERADE
-A POSTROUTING -s 10.252.50.0/24 ! -d 10.252.50.0/24 -p udp -m comment --comment "generated for Multipass network mpqemubr0" -j MASQUERADE --to-ports 1024-65535
-A POSTROUTING -s 10.252.50.0/24 ! -d 10.252.50.0/24 -p tcp -m comment --comment "generated for Multipass network mpqemubr0" -j MASQUERADE --to-ports 1024-65535
-A POSTROUTING -s 10.252.50.0/24 -d 255.255.255.255/32 -m comment --comment "generated for Multipass network mpqemubr0" -j RETURN
-A POSTROUTING -s 10.252.50.0/24 -d 224.0.0.0/24 -m comment --comment "generated for Multipass network mpqemubr0" -j RETURN
-A POSTROUTING -s 172.21.0.0/16 ! -o br-76a36f661624 -j MASQUERADE
-A POSTROUTING -s 172.17.0.0/16 ! -o docker0 -j MASQUERADE
-A POSTROUTING -s 172.19.0.0/16 ! -o br-3dc6563572e8 -j MASQUERADE
-A POSTROUTING -s 10.123.0.0/23 ! -d 10.123.0.0/23 -j MASQUERADE
-A POSTROUTING -s 172.18.0.0/16 ! -o br-f8d72d0efac3 -j MASQUERADE
-A POSTROUTING -s 172.20.0.0/16 ! -o br-6d17bcb2aabe -j MASQUERADE
-A POSTROUTING -s 172.17.0.2/32 -d 172.17.0.2/32 -p tcp -m tcp --dport 1883 -j MASQUERADE
-A POSTROUTING -s 172.19.0.2/32 -d 172.19.0.2/32 -p tcp -m tcp --dport 80 -j MASQUERADE
-A POSTROUTING -s 172.18.0.2/32 -d 172.18.0.2/32 -p tcp -m tcp --dport 9443 -j MASQUERADE
-A POSTROUTING -s 172.20.0.2/32 -d 172.20.0.2/32 -p tcp -m tcp --dport 1883 -j MASQUERADE
-A POSTROUTING -s 172.21.0.2/32 -d 172.21.0.2/32 -p tcp -m tcp --dport 8086 -j MASQUERADE
-A DOCKER -i br-76a36f661624 -j RETURN
-A DOCKER -i docker0 -j RETURN
-A DOCKER -i br-f8d72d0efac3 -j RETURN
-A DOCKER -i br-6d17bcb2aabe -j RETURN
-A DOCKER -i br-3dc6563572e8 -j RETURN
-A DOCKER ! -i br-3dc6563572e8 -p tcp -m tcp --dport 80 -j DNAT --to-destination 172.19.0.2:80
-A DOCKER ! -i br-f8d72d0efac3 -p tcp -m tcp --dport 9443 -j DNAT --to-destination 172.18.0.2:9443
-A DOCKER ! -i br-6d17bcb2aabe -p tcp -m tcp --dport 1883 -j DNAT --to-destination 172.20.0.2:1883
-A DOCKER ! -i br-76a36f661624 -p tcp -m tcp --dport 8086 -j DNAT --to-destination 172.21.0.2:8086

[andrei-toterman]

Hey, @yinchi! Sorry to hear that you are having this issue. Take a look at our troubleshooting guide to see if anything from there is helpful for you.

[k3wals]

I'm having the same problem with Failed to load AppArmor policy error suddenly on vm launch and start.

I'm also following the issue here: #3911

Could it be related to #3871 ?

Much older OS, but newest multipass. I wonder if I should just downgrade to 1.14.0 if possible.

OS: Ubuntu 18.04
Multipass: 1.15.0