canonical / canonical/multipass

Multipass hanging after race stopping/starting an instance on the QEMU backend

Open
#3,592 9 comments 0 reactions 0 assignees View on GitHub
CLI linux needs-info
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.

![image](https://github.com/user-attachments/assets/fb6eb9b0-2d87-4966-bb72-d60b3db19fbe)

Contributor guide

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.