[regression, virtualbox] Daemon removes mounts on startup & fails to start instance

[naturedamends]

Describe the bug
Hangs on the following screen after the update

Will try get some more logs tomorrow. But i'm assuming its the version change thats broke it. It was working before.

New containers start fine. I'm using --network en0 on macos latest os intel

Please just close if not an issue.

To Reproduce
How, and what happened?

1. update to *.11 from .10

Expected behavior
Expected container to boot

Logs
Please provide logs from the daemon, see accessing logs on where to find them on your platform.

Additional info

• OS: [e.g. macOS 10.15]
• multipass version
• multipass info --all
• multipass get local.driver

Additional context
Add any other context about the problem here.

[sharder996]

Hi @naturedamends, would you be able to attach the multipass logs?

[naturedamends]

[2023-01-31T21:15:57.897] [debug] [update] Latest Multipass release available is version 1.11.0
[2023-01-31T21:16:01.857] [info] [rpc] gRPC listening on unix:/var/run/multipass_socket
[2023-01-31T21:16:01.857] [debug] [test] Running: VBoxManage, showvminfo, test, --machinereadable
[2023-01-31T21:16:02.547] [debug] [test] Got VMState: poweroff
[2023-01-31T21:16:02.690] [debug] [test] Got VMState: poweroff
[2023-01-31T21:16:02.849] [debug] [test] Got VMState: poweroff
[2023-01-31T21:16:02.849] [info] [daemon] test needs starting. Starting now...
[2023-01-31T21:16:02.855] [debug] [test] Running: VBoxManage, startvm, test, --type, headless
[2023-01-31T21:16:05.953] [debug] [primary] Running: VBoxManage, showvminfo, primary, --machinereadable
[2023-01-31T21:16:05.953] [debug] [test] Waiting for SSH to be up
[2023-01-31T21:16:05.989] [debug] [test] Running: VBoxManage, controlvm, test, natpf1, delete, ssh
[2023-01-31T21:16:06.227] [debug] [test] Running: VBoxManage, controlvm, test, natpf1, ssh,tcp,,51184,,22
[2023-01-31T21:16:06.423] [debug] [primary] Got VMState: poweroff
[2023-01-31T21:16:06.423] [debug] [primary] Running: VBoxManage, controlvm, primary, natpf1, delete, ssh
[2023-01-31T21:16:06.534] [debug] [primary] VBoxManage failed - errorString: Unknown error, exitStatus: 0, exitCode: 1
[2023-01-31T21:16:06.534] [debug] [primary] Could not delete SSH port forwarding: VBoxManage: error: Machine 'primary' is not currently running.

[2023-01-31T21:16:06.535] [debug] [primary] Running: VBoxManage, controlvm, primary, natpf1, ssh,tcp,,51187,,22
[2023-01-31T21:16:06.675] [debug] [primary] VBoxManage failed - errorString: Unknown error, exitStatus: 0, exitCode: 1
[2023-01-31T21:16:06.675] [warning] [daemon] Removing mount "/Users/na" => "Home" from 'primary': Could not add SSH port forwarding: VBoxManage: error: Machine 'primary' is not currently running.

[2023-01-31T21:16:06.675] [debug] [main] Running: VBoxManage, showvminfo, main, --machinereadable
[2023-01-31T21:16:07.022] [debug] [main] Got VMState: poweroff
[2023-01-31T21:16:07.022] [debug] [empty] Running: VBoxManage, showvminfo, empty, --machinereadable
[2023-01-31T21:16:07.375] [debug] [empty] Got VMState: poweroff
[2023-01-31T21:16:07.380] [info] [daemon] Starting Multipass 1.11.0+mac
[2023-01-31T21:16:07.380] [info] [daemon] Daemon arguments: /Library/Application Support/com.canonical.multipass/bin/multipassd --verbosity debug
[2023-01-31T21:16:38.533] [debug] [empty] Got VMState: poweroff
[2023-01-31T21:16:38.662] [debug] [main] Got VMState: poweroff
[2023-01-31T21:16:38.801] [debug] [primary] Got VMState: poweroff
[2023-01-31T21:16:38.954] [debug] [test] Got VMState: running
[2023-01-31T21:16:39.100] [debug] [test] Got VMState: running
[2023-01-31T21:16:39.197] [debug] [ssh session] Executing 'ip -brief -family inet address show scope global'
[2023-01-31T21:16:40.588] [debug] [ssh process] /Users/cibot/actions-runner/_work/multipass-private/multipass-private/src/ssh/ssh_process.cpp:118 read_stream(type = 0, timeout = -1): 
[2023-01-31T21:16:40.588] [debug] [ssh process] /Users/cibot/actions-runner/_work/multipass-private/multipass-private/src/ssh/ssh_process.cpp:136 read_stream(): num_bytes = 118
[2023-01-31T21:16:40.588] [debug] [ssh process] /Users/cibot/actions-runner/_work/multipass-private/multipass-private/src/ssh/ssh_process.cpp:136 read_stream(): num_bytes = 0
[2023-01-31T21:16:49.639] [debug] [test] Got VMState: running
[2023-01-31T21:16:49.669] [debug] [ssh session] Executing 'wall The system is going down for poweroff now'
[2023-01-31T21:16:49.912] [debug] [test] Got VMState: running
[2023-01-31T21:16:49.913] [debug] [test] Running: VBoxManage, controlvm, test, acpipowerbutton
[2023-01-31T21:16:50.246] [debug] [test] Got VMState: running
[2023-01-31T21:16:50.410] [debug] [test] Got VMState: running
[2023-01-31T21:16:50.411] [debug] [test] Running: VBoxManage, controlvm, test, acpipowerbutton




[2023-01-31T21:17:19.384] [debug] [empty] Got VMState: poweroff
[2023-01-31T21:17:19.514] [debug] [main] Got VMState: poweroff
[2023-01-31T21:17:19.647] [debug] [primary] Got VMState: poweroff
[2023-01-31T21:17:19.784] [debug] [main] Got VMState: poweroff
[2023-01-31T21:17:19.917] [debug] [main] Got VMState: poweroff
[2023-01-31T21:17:20.049] [debug] [main] Got VMState: poweroff
[2023-01-31T21:17:20.050] [debug] [main] Running: VBoxManage, startvm, main, --type, headless
[2023-01-31T21:17:36.838] [debug] [main] Waiting for SSH to be up
[2023-01-31T21:17:36.839] [debug] [main] Running: VBoxManage, controlvm, main, natpf1, delete, ssh
[2023-01-31T21:17:36.976] [debug] [main] Running: VBoxManage, controlvm, main, natpf1, ssh,tcp,,51496,,22

multipass --version
multipass   1.11.0+mac
multipassd  1.11.0+mac

Driver is VirtualBox

[naturedamends]

@sharder996 logs attached - main is the vm failing to start - if the fix is easy - and you can point in the right direction - I would like to write some c++

[balboah]

similar issue, can't login to the instance after upgrade.

multipass   1.11.0+mac
multipassd  1.11.0+mac

logs says

 QMP: {"timestamp": {"seconds": 1675245237, "microseconds": 641245}, "event": "BLOCK_IO_ERROR", "data": {"device": "hda", "nospace": false, "node-name": "#block367", "r
eason": "Input/output error", "operation": "read", "action": "report"}}
{"timestamp": {"seconds": 1675245237, "microseconds": 641281}, "event": "BLOCK_IO_ERROR", "data": {"device": "hda", "nospace": false, "node-name": "#block367", "reason": "Input/output error", "operation": "read", "
action": "report"}}

[ricab]

Hi @naturedamends, I have been investigating and I believe I was able to reproduce. I will follow up with instructions and findings, but first you should be recover with:

multipass stop main
multipass start main
multipass mount ... main:... 

That third step is there because I believe you lost one (at least) mount in that instance correct? Your logs don't show that, but they do show primary loosing a mount:

[2023-01-31T21:16:06.675] [warning] [daemon] Removing mount "/Users/na" => "Home" from 'primary': Could not add SSH port forwarding: VBoxManage: error: Machine 'primary' is not currently running.

That is what I see too.

@balboah, yours is a different issue (you are using QEMU rather than VirtualBox as the OP). Could you please open a new issue, filling in the template please? Thank you.

[ricab]

I am afraid this is a regression (can't reproduce with 1.10). And it is not limited to the upgrade itself. It happens whenever restarting the daemon on 1.11 with VirtualBox and instances with mounts. To reproduce

1. Install Multipass 1.11
2. multipass set local.driver=virtualbox
3. multipass launch -n test
4. multipass mount foo test:foo
5. multipass stop test — this is not strictly necessary, but I am not sure if there are cases where the instance can otherwise start up fast enough to bypass the problem in the followin steps. I think I saw that once...
6. sudo launchctl unload /Library/LaunchDaemons/com.canonical.multipassd.plist
7. sudo launchctl load /Library/LaunchDaemons/com.canonical.multipassd.plist
8. multipass info test — observe the mount is gone
9. multipass start test — observe the instance does not manage to start (times out)
10. See in the logs
    1. the mount warning above, at the start of the daemon run (probably coming from somewhere within the Daemon ctor)
    2. After the message "Waiting for SSH to be up", no messages with VBoxManage, controlvm, test, natpf1, ..., which would be expected from the implementation of ssh_port for this backend.

I wouldn't be surprised if something is getting sunk in here... I suppose that's there to avoid exceptions flying through Qt connections? We should at least log something. But may be elsewhere too.

More investigation needed, but this looks like it is cascading from that first mount error, which should not happen just because the instance isn't running.