canonical / canonical/multipass
Multipass hanging after race stopping/starting an instance on the QEMU backend
- Dominant language
- C++
- Stars
- 9.2k
- Forks
- 828
- Avg merge
- 3d 1h
- Merged PRs (30d)
- 44
Description
**Describe the bug**
`multipass` is hanging on all commands since an instance couldn't be started up.
**To Reproduce**
How, and what happened?
1. I recommend to have a very heavy instace that's raching system capacity / limits. It may (or may not) trigger the syndrome. I mean I'm not convenienced that the syndrome is deterministc
2. `stop` the instance
3. make a attemtp to `start` the instance
**Logs**
```
Jul 18 10:05:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 10:20:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 10:35:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 10:50:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 11:05:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 11:20:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 11:20:34 pegasus multipassd[1494]: process working dir '/snap/multipass/12541/qemu'
Jul 18 11:20:34 pegasus multipassd[1494]: process program 'qemu-system-x86_64'
Jul 18 11:20:34 pegasus multipassd[1494]: process arguments '-bios, OVMF.fd, --enable-kvm, -cpu, host, -nic, tap,ifname=tap-35c685f5b33,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:70:53:3f, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd-testing/ubuntu-22.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 12, -m, 32768M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd-testing/cloud-init-config.iso'
Jul 18 11:20:34 pegasus multipassd[1494]: [187466] started: qemu-system-x86_64 -nographic -dump-vmstate /tmp/multipassd.fdfGEG
Jul 18 11:20:34 pegasus multipassd[1494]: Applied AppArmor policy: multipass.vm-lxd-testing.qemu-system-x86_64
Jul 18 11:20:34 pegasus multipassd[1494]: process state changed to Starting
Jul 18 11:20:34 pegasus multipassd[1494]: process state changed to Running
Jul 18 11:20:34 pegasus multipassd[1494]: [187468] started: qemu-system-x86_64 -bios OVMF.fd --enable-kvm -cpu host -nic tap,ifname=tap-35c685f5b33,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:70:53:3f -device virtio-scsi-pci,id=scsi0 -drive file=/var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd-testing/ubuntu-22.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 12 -m 32768M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd-testing/cloud-init-config.iso
Jul 18 11:20:34 pegasus multipassd[1494]: process started
Jul 18 11:20:34 pegasus multipassd[1494]: Waiting for SSH to be up
Jul 18 11:20:34 pegasus multipassd[1494]: QMP: {"QMP": {"version": {"qemu": {"micro": 1, "minor": 2, "major": 8}, "package": ""}, "capabilities": ["oob"]}}
Jul 18 11:20:34 pegasus multipassd[1494]: QMP: {"return": {}}
Jul 18 11:20:36 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294436, "microseconds": 325256}, "event": "RTC_CHANGE", "data": {"offset": -1, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:20:37 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294436, "microseconds": 356785}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:20:41 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294441, "microseconds": 959935}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[33]/virtio-backend"}}
Jul 18 11:20:41 pegasus dnsmasq-dhcp[1872]: DHCPDISCOVER(mpqemubr0) 52:54:00:70:53:3f
Jul 18 11:20:41 pegasus dnsmasq-dhcp[1872]: DHCPOFFER(mpqemubr0) 10.34.27.2 52:54:00:70:53:3f
Jul 18 11:20:41 pegasus dnsmasq-dhcp[1872]: DHCPREQUEST(mpqemubr0) 10.34.27.2 52:54:00:70:53:3f
Jul 18 11:20:41 pegasus dnsmasq-dhcp[1872]: DHCPACK(mpqemubr0) 10.34.27.2 52:54:00:70:53:3f vm-lxd-testing
Jul 18 11:20:44 pegasus multipassd[1494]: Executing 'which snap'
Jul 18 11:20:45 pegasus multipassd[1494]: Executing 'sudo snap list multipass-sshfs'
Jul 18 11:20:45 pegasus multipassd[1494]: The multipass-sshfs snap is already installed on 'vm-lxd-testing'
Jul 18 11:20:45 pegasus multipassd[1494]: process program '/snap/multipass/12541/bin/sshfs_server'
Jul 18 11:20:45 pegasus multipassd[1494]: process arguments '10.34.27.2, 22, ubuntu, /home/kaboca/repos, repos, 1001:-1,, 1001:-1,, 3'
Jul 18 11:20:45 pegasus multipassd[1494]: Applied AppArmor policy: multipass.vm-lxd-testing.300750e8.sshfs_server
Jul 18 11:20:45 pegasus multipassd[1494]: [187514] started: /snap/multipass/12541/bin/sshfs_server 10.34.27.2 22 ubuntu /home/kaboca/repos repos 1001:-1, 1001:-1, 3
Jul 18 11:20:45 pegasus sshfs_server[187514]: /build/multipass/parts/multipass/src/src/sshfs_mount/sshfs_mount.cpp:123 make_sftp_server(source = /home/kaboca/repos, target = repos, …):
Jul 18 11:20:45 pegasus sshfs_server[187514]: Executing 'snap run multipass-sshfs.env'
Jul 18 11:20:45 pegasus sshfs_server[187514]: Executing 'sudo env LD_LIBRARY_PATH=/snap/multipass-sshfs/145/lib /snap/multipass-sshfs/145/bin/sshfs -V'
Jul 18 11:20:45 pegasus sshfs_server[187514]: Executing 'echo $PWD/repos'
Jul 18 11:20:45 pegasus sshfs_server[187514]: Executing 'sudo /bin/bash -c 'P="/home/ubuntu/repos"; while [ ! -d "$P/" ]; do P="${P%/*}"; done; echo $P/''
Jul 18 11:20:45 pegasus sshfs_server[187514]: Executing 'id -u'
Jul 18 11:20:45 pegasus sshfs_server[187514]: /build/multipass/parts/multipass/src/src/sshfs_mount/sshfs_mount.cpp:132 make_sftp_server(): `id -u` = 1000
Jul 18 11:20:45 pegasus sshfs_server[187514]: Executing 'id -g'
Jul 18 11:20:45 pegasus sshfs_server[187514]: /build/multipass/parts/multipass/src/src/sshfs_mount/sshfs_mount.cpp:137 make_sftp_server(): `id -g` = 1000
Jul 18 11:20:45 pegasus sshfs_server[187514]: Executing 'sudo env LD_LIBRARY_PATH=/snap/multipass-sshfs/145/lib /snap/multipass-sshfs/145/bin/sshfs -o slave -o transform_symlinks -o allow_other -o Compression=no -o dcache_timeout=3 :"/home/kaboca/repos" "/home/ubuntu/repos/."'
Jul 18 11:20:52 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294452, "microseconds": 500453}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:27:04 pegasus multipassd[1494]: Executing 'wall The system is going down for poweroff now'
Jul 18 11:27:05 pegasus multipassd[1494]: Executing 'echo $PWD/repos'
Jul 18 11:27:05 pegasus multipassd[1494]: Executing 'findmnt --type fuse.sshfs | grep -E '^/home/ubuntu/repos +:/home/kaboca/repos''
Jul 18 11:27:05 pegasus multipassd[1494]: Stopping mount "repos" in instance 'vm-lxd-testing'
Jul 18 11:27:05 pegasus multipassd[1494]: Mount "repos" in instance 'vm-lxd-testing' has stopped
Jul 18 11:27:05 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294825, "microseconds": 412390}, "event": "POWERDOWN"}
Jul 18 11:27:05 pegasus multipassd[1494]: VM powering down
Jul 18 11:27:05 pegasus multipassd[1494]: QMP: {"return": {}}
Jul 18 11:27:18 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294838, "microseconds": 812348}, "event": "SHUTDOWN", "data": {"guest": true, "reason": "guest-shutdown"}}
Jul 18 11:27:18 pegasus multipassd[1494]: VM shut down
Jul 18 11:27:19 pegasus multipassd[1494]: process state changed to NotRunning
Jul 18 11:27:19 pegasus multipassd[1494]: process finished with exit code 0
Jul 18 11:27:30 pegasus multipassd[1494]: instance "vm-lxd" does not need stopping
Jul 18 11:27:35 pegasus multipassd[1494]: process working dir '/snap/multipass/12541/qemu'
Jul 18 11:27:35 pegasus multipassd[1494]: process program 'qemu-system-x86_64'
Jul 18 11:27:35 pegasus multipassd[1494]: process arguments '-bios, OVMF.fd, --enable-kvm, -cpu, host, -nic, tap,ifname=tap-1050f494706,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:a3:35:67, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd/ubuntu-22.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 12, -m, 32768M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd/cloud-init-config.iso'
Jul 18 11:27:35 pegasus multipassd[1494]: [187990] started: qemu-system-x86_64 -nographic -dump-vmstate /tmp/multipassd.ULIjju
Jul 18 11:27:35 pegasus multipassd[1494]: Applied AppArmor policy: multipass.vm-lxd.qemu-system-x86_64
Jul 18 11:27:35 pegasus multipassd[1494]: process state changed to Starting
Jul 18 11:27:35 pegasus multipassd[1494]: process state changed to Running
Jul 18 11:27:35 pegasus multipassd[1494]: [187992] started: qemu-system-x86_64 -bios OVMF.fd --enable-kvm -cpu host -nic tap,ifname=tap-1050f494706,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:a3:35:67 -device virtio-scsi-pci,id=scsi0 -drive file=/var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd/ubuntu-22.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 12 -m 32768M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/snap/multipass/common/data/multipassd/vault/instances/vm-lxd/cloud-init-config.iso
Jul 18 11:27:35 pegasus multipassd[1494]: process started
Jul 18 11:27:35 pegasus multipassd[1494]: Waiting for SSH to be up
Jul 18 11:27:35 pegasus multipassd[1494]: QMP: {"QMP": {"version": {"qemu": {"micro": 1, "minor": 2, "major": 8}, "package": ""}, "capabilities": ["oob"]}}
Jul 18 11:27:35 pegasus multipassd[1494]: QMP: {"return": {}}
Jul 18 11:27:37 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294857, "microseconds": 598353}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:27:38 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294857, "microseconds": 629502}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:27:43 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294863, "microseconds": 807466}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[33]/virtio-backend"}}
Jul 18 11:27:43 pegasus dnsmasq-dhcp[1872]: DHCPDISCOVER(mpqemubr0) 52:54:00:a3:35:67
Jul 18 11:27:43 pegasus dnsmasq-dhcp[1872]: DHCPOFFER(mpqemubr0) 10.34.27.75 52:54:00:a3:35:67
Jul 18 11:27:43 pegasus dnsmasq-dhcp[1872]: DHCPREQUEST(mpqemubr0) 10.34.27.75 52:54:00:a3:35:67
Jul 18 11:27:43 pegasus dnsmasq-dhcp[1872]: DHCPACK(mpqemubr0) 10.34.27.75 52:54:00:a3:35:67 vm-lxd
Jul 18 11:27:46 pegasus multipassd[1494]: Executing 'which snap'
Jul 18 11:27:46 pegasus multipassd[1494]: Executing 'sudo snap list multipass-sshfs'
Jul 18 11:27:46 pegasus multipassd[1494]: The multipass-sshfs snap is already installed on 'vm-lxd'
Jul 18 11:27:47 pegasus multipassd[1494]: process program '/snap/multipass/12541/bin/sshfs_server'
Jul 18 11:27:47 pegasus multipassd[1494]: process arguments '10.34.27.75, 22, ubuntu, /home/kaboca/repos, repos, 1001:-1,, 1001:-1,, 3'
Jul 18 11:27:47 pegasus multipassd[1494]: Applied AppArmor policy: multipass.vm-lxd.300750e8.sshfs_server
Jul 18 11:27:47 pegasus multipassd[188050]: Removing mount "repos" from 'vm-lxd': Failed to apply AppArmor policy multipass.vm-lxd.300750e8.sshfs_server: errno=2 (No such file or directory)
Jul 18 11:27:54 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721294874, "microseconds": 721540}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:35:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 11:38:53 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721295533, "microseconds": 497524}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:49:52 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721296192, "microseconds": 496933}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 11:50:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 12:00:51 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721296851, "microseconds": 493203}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 12:05:08 pegasus multipassd[1494]: fetch manifest periodically
Jul 18 12:11:50 pegasus multipassd[1494]: QMP: {"timestamp": {"seconds": 1721297510, "microseconds": 496499}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[15]/rtc"}}
Jul 18 12:15:15 pegasus multipassd[1494]: Executing 'wall The system is going down for poweroff now'
```
**Additional info**
- OS: `jammy`
Since the `multipass` command is haning on any attempt of execution, I cant provide details such as:
- `multipass version`
- `multipass info`
- `multipass get local.driver`
Instead:
```
kaboca@pegasus:~$ snap info multipass
[..]
services:
multipass.multipassd: simple, enabled, active
snap-id: mA11087v6dR3IEcQLgICQVjuvhUUBUKM
tracking: latest/stable
refresh-date: 43 days ago, at 19:58 CEST
hold: forever
channels:
latest/stable: 1.13.1 2024-06-28 (12829) 122MB -
latest/candidate: 1.13.1 2024-07-18 (12981) 122MB -
latest/beta: 1.14.0 2024-07-11 (12940) 64MB -
latest/edge: 1.15.0-dev.2328+g6ee0b4ed 2024-07-10 (12931) 64MB -
installed: 1.13.1 (12541) 122MB held
```
**Additional context**
NOTE: The 2nd command in the sequence (`multipass stop vm-lxd`) had no impact, as the `vm-lxd` instance was not running at that point.

Contributor guide
Research direction
Start with the QEMU backend startup and shutdown paths in multipassd, then inspect src/sshfs_mount/sshfs_mount.cpp around the logged lines 123 and 132. Reproduce the stop/start race with a resource-heavy instance and trace the failed AppArmor mount cleanup; done means subsequent multipass commands remain responsive and the mount lifecycle completes without the logged failure.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- cpp
- Domain
- backend, operating-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Quiet
- Clarity
- Mostly clear
- Newbie friendliness
- 45/100