canonical / multipass

Multipass orchestrates virtual Ubuntu instances
https://multipass.run
GNU General Public License v3.0
7.95k stars 651 forks source link

Firewall randomly messing with Multipass networking on macOS #2387

Open milopersic opened 2 years ago

milopersic commented 2 years ago

Update: If you are using an unmanaged Mac and run across this issue, the following commands may fix this issue:

/usr/libexec/ApplicationFirewall/socketfilterfw --add /usr/libexec/bootpd
/usr/libexec/ApplicationFirewall/socketfilterfw --unblock /usr/libexec/bootpd

Original post

Multipass crashes unexpectedly, and all instances (including primary) will not restart. I am using multipass 1.8.1+mac, multipassd 1.8.1+mac. (multipass --version), on macOS Monterey 12.1, M1 Max, 32 GB RAM. I installed multipass for macOS directly from Canonical's website.

start failed: The following errors occurred:                                    
dbarn: timed out waiting for response

This has happened twice. The first time I uninstalled multipass, reinstalled, and re-built my instances thinking it was a fluke. Multipass performed fine for roughly a week, then crashed again and I lost some work. I am not able to determine what the cause is, or how to reproduce it. System restarts do not help. I'm hoping someone can spot the issue in the logs.

Logs here:

[2022-01-04T13:30:56.044] [warning] [qemu-system-aarch64] 
[2022-01-04T13:30:56.044] [debug] [dbarn] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2022-01-04T13:30:56.062] [debug] [dbarn] QMP: {"return": {}}

[2022-01-04T13:31:08.663] [debug] [dbarn] QMP: {"timestamp": {"seconds": 1641321068, "microseconds": 663550}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[7]/virtio-backend"}}

[2022-01-04T13:36:37.352] [debug] [dbarn] process working dir ''
[2022-01-04T13:36:37.353] [info] [dbarn] process program 'qemu-system-aarch64'
[2022-01-04T13:36:37.353] [info] [dbarn] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dbarn/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 2, -m, 4096M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/dbarn/cloud-init-config.iso'
[2022-01-04T13:36:37.353] [warning] [Qt] QProcess: Destroyed while process ("qemu-system-aarch64") is still running.
[2022-01-04T13:36:37.370] [error] [dbarn] process error occurred Crashed program: qemu-system-aarch64; error: Process crashed
[2022-01-04T13:36:37.371] [info] [dbarn] process state changed to NotRunning
[2022-01-04T13:36:37.371] [error] [dbarn] error: program: qemu-system-aarch64; error: Process crashed
[2022-01-04T13:36:37.372] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-01-04T13:36:37.372] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-01-04T13:36:37.372] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-01-04T13:36:37.372] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-01-04T13:36:37.372] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-01-04T13:36:37.372] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-01-04T13:36:38.572] [debug] [update] Latest Multipass release available is version 1.8.0
[2022-01-04T13:36:40.666] [info] [VMImageHost] Did not find any supported products in "appliance"
[2022-01-04T13:36:40.671] [info] [rpc] gRPC listening on unix:/var/run/multipass_socket, SSL:on
[2022-01-04T13:36:40.673] [debug] [qemu-img] [1300] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/tractorgeeks/ubuntu-20.04-server-cloudimg-arm64.img
[2022-01-04T13:36:40.677] [debug] [qemu-img] [1301] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/primary/ubuntu-20.04-server-cloudimg-arm64.img
[2022-01-04T13:36:40.681] [debug] [qemu-img] [1302] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/dbarn/ubuntu-20.04-server-cloudimg-arm64.img
[2022-01-04T13:36:40.686] [info] [daemon] Starting Multipass 1.8.1+mac
[2022-01-04T13:36:40.686] [info] [daemon] Daemon arguments: /Library/Application Support/com.canonical.multipass/bin/multipassd --verbosity debug
[2022-01-04T13:43:16.997] [debug] [dbarn] process working dir ''
[2022-01-04T13:43:16.998] [info] [dbarn] process program 'qemu-system-aarch64'
[2022-01-04T13:43:16.998] [info] [dbarn] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dbarn/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 2, -m, 4096M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/dbarn/cloud-init-config.iso'
[2022-01-04T13:43:17.004] [debug] [qemu-system-aarch64] [1384] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.pRWjeY
[2022-01-04T13:43:17.061] [info] [dbarn] process state changed to Starting
[2022-01-04T13:43:17.063] [info] [dbarn] process state changed to Running
[2022-01-04T13:43:17.063] [debug] [qemu-system-aarch64] [1385] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dbarn/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 2 -m 4096M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/dbarn/cloud-init-config.iso
[2022-01-04T13:43:17.063] [info] [dbarn] process started
[2022-01-04T13:43:17.063] [debug] [dbarn] Waiting for SSH to be up
[2022-01-04T13:43:17.347] [warning] [dbarn] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: MAC:              de:e5:9b:47:58:c4
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3: info: UUID:             9736AE0D-0FAE-4223-847E-517E35533FEA

[2022-01-04T13:43:17.348] [warning] [qemu-system-aarch64] 
[2022-01-04T13:43:17.351] [debug] [dbarn] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2022-01-04T13:43:17.399] [debug] [dbarn] QMP: {"return": {}}

[2022-01-04T13:43:29.746] [debug] [dbarn] QMP: {"timestamp": {"seconds": 1641321809, "microseconds": 746100}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[7]/virtio-backend"}}
townsend2010 commented 2 years ago

Hey @milopersic,

It's not clear to me at all why qemu crashes, but it looks like it does start again to the point where the instance's virtual network adapter comes up. If you don't mind, could you post the contents of /var/db/dhcpd_leases?

milopersic commented 2 years ago

Sure thing, thank you. This shows some of the other instances I created previously on the first installation of multipass. For what it's worth, I get "status unknown" on my instances after attempting a restart.

image

/var/db/dhcpd_leases below: (I'm assuming you wanted these from my host machine, the M1 mac)


        lease=0x61c9185c
}
{
        name=primary
        ip_address=192.168.64.6
        hw_address=1,52:54:0:9c:22:d7
        identifier=1,52:54:0:9c:22:d7
        lease=0x61c92dad
}
{
        name=dbarn
        ip_address=192.168.64.5
        hw_address=1,52:54:0:3b:85:37
        identifier=1,52:54:0:3b:85:37
        lease=0x61c77a3e
}
{
        name=tractorgeeks
        ip_address=192.168.64.4
        hw_address=1,52:54:0:1:e7:ff
        identifier=1,52:54:0:1:e7:ff
        lease=0x61b96210
}
{
        name=primary
        ip_address=192.168.64.3
        hw_address=1,52:54:0:5f:52:7a
        identifier=1,52:54:0:5f:52:7a
        lease=0x61c77eb3
}
{
        name=linus
        ip_address=192.168.64.2
        hw_address=1,52:54:0:2a:54:84
        identifier=1,52:54:0:2a:54:84
        lease=0x61a586f2
}
townsend2010 commented 2 years ago

Is that the full file contents? I ask because the top of what you posted looks wrong, ie, the

        lease=0x61c9185c
}

is a dangling entry and shows a corrupted leases file. Multipass only opens this file read-only, so if this is the case, then something in macOS is corrupting this file and causing us issues. If those two lines are truly like that in your file, please remove those two lines only and try again.

milopersic commented 2 years ago

My mistake, apologies! I didn't post the full file. Repost:


{
        name=tractorgeeks
        ip_address=192.168.64.12
        hw_address=1,52:54:0:db:19:c3
        identifier=1,52:54:0:db:19:c3
        lease=0x61d471ba
}
{
        name=dbarn
        ip_address=192.168.64.11
        hw_address=1,52:54:0:11:ff:d3
        identifier=1,52:54:0:11:ff:d3
        lease=0x61d54fea
}
{
        name=elon
        ip_address=192.168.64.10
        hw_address=1,52:54:0:76:78:7a
        identifier=1,52:54:0:76:78:7a
        lease=0x61c92fc4
}
{
        name=assuring-quetzal
        ip_address=192.168.64.9
        hw_address=1,52:54:0:3:b1:2f
        identifier=1,52:54:0:3:b1:2f
        lease=0x61c92e03
}
{
        name=profound-admiral
        ip_address=192.168.64.8
        hw_address=1,52:54:0:94:1b:4e
        identifier=1,52:54:0:94:1b:4e
        lease=0x61ca7da5
}
{
        name=venom
        ip_address=192.168.64.7
        hw_address=1,52:54:0:a7:65:ce
        identifier=1,52:54:0:a7:65:ce
        lease=0x61c9185c
}
{
        name=primary
        ip_address=192.168.64.6
        hw_address=1,52:54:0:9c:22:d7
        identifier=1,52:54:0:9c:22:d7
        lease=0x61c92dad
}
{
        name=dbarn
        ip_address=192.168.64.5
        hw_address=1,52:54:0:3b:85:37
        identifier=1,52:54:0:3b:85:37
        lease=0x61c77a3e
}
{
        name=tractorgeeks
        ip_address=192.168.64.4
        hw_address=1,52:54:0:1:e7:ff
        identifier=1,52:54:0:1:e7:ff
        lease=0x61b96210
}
{
        name=primary
        ip_address=192.168.64.3
        hw_address=1,52:54:0:5f:52:7a
        identifier=1,52:54:0:5f:52:7a
        lease=0x61c77eb3
}
{
        name=linus
        ip_address=192.168.64.2
        hw_address=1,52:54:0:2a:54:84
        identifier=1,52:54:0:2a:54:84
        lease=0x61a586f2
}
townsend2010 commented 2 years ago

Ok, that looks better as far as a corrupted leases file :wink:

But gah, stupid Apple's bootp has duplicate entries in the file and past experience shows that if there are entries with the same name, none of the entries work. Please remove any duplicate entries based in the name field and try again and see if that helps.

milopersic commented 2 years ago

:) thanks. I'll try it! To be clear, by "duplicates" you mean duplicates by name?

name=linus

No other info is relevant? Wait you just said that. Sorry, long day.

townsend2010 commented 2 years ago

Sorry, I mean the whole entry. For example, there are 2 entries for the dbarn instance:

{
        name=dbarn
        ip_address=192.168.64.11
        hw_address=1,52:54:0:11:ff:d3
        identifier=1,52:54:0:11:ff:d3
        lease=0x61d54fea
}

and

{
        name=dbarn
        ip_address=192.168.64.5
        hw_address=1,52:54:0:3b:85:37
        identifier=1,52:54:0:3b:85:37
        lease=0x61c77a3e
}

You will need to remove both of those full entries, from the { to the }.

milopersic commented 2 years ago

Okay, that helps. The instance you pasted in on top here (ip_address=192.168.64.11) is my latest instance and one that I was using. Can you confirm that I should remove that? What should be kept?

townsend2010 commented 2 years ago

Please stop any "running" instances, ie, dbarn and tractorgeeks, remove both of those entries I posted above (and any and all entries that have duplicates), then try starting an instance such as dbarn.

milopersic commented 2 years ago

Sadly still not able to start the instance. I stopped and exited multipass, edited out the duplicates and both entries for dbarn, restarted multipass, and attempted to restart dbarn:

start failed: The following errors occurred:                                    
dbarn: timed out waiting for response

Saving session...
...copying shared history...
...saving history...truncating history files...
...completed.

[Process completed]

At present, my dhcpd_leases file only has "primary" in it, which also does not start.


{
        name=primary
        ip_address=192.168.64.6
        hw_address=1,52:54:0:9c:22:d7
        identifier=1,52:54:0:9c:22:d7
        lease=0x61c92dad
}

Here are the latest logs (I think I'm going far back enough but let me know):

[2022-01-04T15:06:32.834] [warning] [qemu-system-aarch64] 
[2022-01-04T15:06:32.835] [debug] [dbarn] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2022-01-04T15:06:32.862] [debug] [dbarn] QMP: {"return": {}}

[2022-01-04T15:06:45.152] [debug] [dbarn] QMP: {"timestamp": {"seconds": 1641326805, "microseconds": 152154}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[7]/virtio-backend"}}

[2022-01-04T15:07:53.361] [debug] [primary] process working dir ''
[2022-01-04T15:07:53.361] [info] [primary] process program 'qemu-system-aarch64'
[2022-01-04T15:07:53.361] [info] [primary] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/primary/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/primary/cloud-init-config.iso'
[2022-01-04T15:07:53.367] [debug] [qemu-system-aarch64] [2165] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.SyUqRM
[2022-01-04T15:07:53.418] [info] [primary] process state changed to Starting
[2022-01-04T15:07:53.420] [info] [primary] process state changed to Running
[2022-01-04T15:07:53.420] [debug] [qemu-system-aarch64] [2166] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/primary/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/primary/cloud-init-config.iso
[2022-01-04T15:07:53.420] [info] [primary] process started
[2022-01-04T15:07:53.420] [debug] [primary] Waiting for SSH to be up
[2022-01-04T15:07:53.460] [warning] [primary] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: MAC:              a2:be:ac:c6:8b:70
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:9c:22:d7: info: UUID:             B4D9E973-5B01-40FF-AB23-95BC5CC96C22

[2022-01-04T15:07:53.460] [warning] [qemu-system-aarch64] 
[2022-01-04T15:07:53.460] [debug] [primary] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2022-01-04T15:07:53.479] [debug] [primary] QMP: {"return": {}}

[2022-01-04T15:08:05.750] [debug] [primary] QMP: {"timestamp": {"seconds": 1641326885, "microseconds": 750253}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[6]/virtio-backend"}}
townsend2010 commented 2 years ago

Ok, I'm betting the bootp has some entries cached in memory. The easiest way to clear that up is to restart the machine. Please let me know if that is not possible. Sorry for all of the headaches with this :frowning_face:

milopersic commented 2 years ago

Hey Chris, can't tell you how much I appreciate the help. I can get a reboot in. I'll do that now and retry starting the instance(s) and let you know what happens.

milopersic commented 2 years ago

Well, no luck after a restart:

start failed: The following errors occurred:                                    
dbarn: timed out waiting for response

Saving session...
...copying shared history...
...saving history...truncating history files...
...completed.

[Process completed]
townsend2010 commented 2 years ago

Ugh, and the dhcpd_leases file shows nothing for dbarn still?

Also, let's see if starting it by hand in a terminal will work. Try

$ sudo /Library/Application\ Support/com.canonical.multipass/bin/qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application\ Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:11:ff:d3 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application\ Support/multipassd/qemu/vault/instances/dbarn/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -cdrom /var/root/Library/Application\ Support/multipassd/qemu/vault/instances/dbarn/cloud-init-config.iso

I tried to escape spaces in the paths, but you may have to play around with those. In theory, this should open a QEMU window and you should be able to observe the boot process and see if there are any errors or that the instance is getting stuck booting.

milopersic commented 2 years ago

I think you escaped it correctly because no error was thrown in the terminal. However it launched a QEMU terminal window and locked my cursor. Tried alt+cmd+G (as indicated) and no luck. Also experienced some UI glitches. Had to perform two successive hard resets to get my input ability back. Weird stuff! After coming back up, I tried starting dbarn again via the menu bar app. No luck, still times out. Anything else I should try?

townsend2010 commented 2 years ago

Oh, good grief! Well, when the QEMU window was open, did you happen to see if it booted to a login prompt? Also, do you see a dbarn entry in the dhcpd_leases file?

I'm really running out of ideas here. I'll give it some thought and post anything I can think of tomorrow.

milopersic commented 2 years ago

I don't recall what was in the terminal. Sounds like a plan, thanks! In the meantime I can spool up a remote dev environment on my server and keep on truckin' with that.

ymka commented 2 years ago

Hi guys, I've faced the same issue. Try to disable macos firewall.

milopersic commented 2 years ago

Well what do you know. Completely disabling the firewall on macOS actually worked and I was able to start my instances normally. I didn't think this was the problem, as you can see I'm not blocking all incoming connections and I have checked "automatically allow built-in software to receive incoming connections" (I guess Multipass is not treated as built-in software?).

image

Canonical's troubleshooting page mentions that if the firewall is enabled, it should not "block all incoming connections" so I thought I was good. It does not say the firewall should be fully disabled.

https://multipass.run/docs/troubleshooting-networking-on-macos

Turning off the firewall completely doesn't seem like the ideal solution. I turned my firewall back on and added a rule for Multipass, to Allow all incoming connections. This did not work! Even with that rule the instances do not start. I'm nervous about using Multipass if I have to fully disable the firewall, but maybe I'm wrong.

townsend2010 commented 2 years ago

Hi @milopersic,

Glad you've made some progress on diagnosing what the problem is! Our guide is based more on macOS 10.x and it appears there have been changes surrounding the firewall in newer versions of macOS. I don't have a M1-based Mac at my disposal, but I do have an Intel Mac and will try to see if I can reproduce this and if so, determine what can be done aside from completely disabling the firewall. I agree, that is not an ideal solution.

milopersic commented 2 years ago

Thank you @townsend2010 ! M1 is still very new and we're all figuring out the quirks. Good luck on researching the issue and fix. If I can assist you by trying anything let me know. Multipass is an amazing application and this is just a bump in the road.

townsend2010 commented 2 years ago

Thanks for the kind words @milopersic :slightly_smiling_face: I'll definitely let you know if I find anything.

milopersic commented 2 years ago

Awesome! For what it's worth, I'll recap or add a few facts re: my experience in case any of this is relevant:

What's confusing to me is why it would work at all for any length of time if the firewall is the issue, but who knows what macOS is doing under the hood.

townsend2010 commented 2 years ago

Great summary @milopersic!

The macOS networking is certainly mysterious. I suppose no updates to Monterey happened around the time the firewall began to cause Multipass issues, right?

milopersic commented 2 years ago

You know, MacOS 12.1 was released December 13, 2021. I don't recall the exact day I had the first crash but it may well have been right after the update.

townsend2010 commented 2 years ago

Ok, good to know. I'm updating my Intel Mac to 12.1. We'll see what happens :wink:

rjoelnorgren commented 2 years ago

I would like to add I am also using a similar set up (M1 Pro, Monterey 12.0.1) and have encountered today what I believe is the same issue as @milopersic. Unfortunately this is a company issued machine that I do not have privileges to disable the firewall on. Brief description below and logs similar to what has already been reported follow:

Last night I had Multipass working just fine. Today after rebooting my machine my VMs failed to start. I tried clearing out entries for my VMs from /var/db/dhcpd_leases, but the issue persisted. After a full uninstall/reboot/install of Multipass, I could once again launch and run VMs. However, it seems that if I shutdown/restart my machine, my Multipass fails to launch new or start existing images:

rnorgren@Robins-MBP:~$ multipass launch -c 4 -m 8G -d 10G -n dev --cloud-init ~/multipass/localdev/cloud-init.yaml 
launch failed: The following errors occurred:                                   
dev: timed out waiting for response

I also confirmed a simple multipass launch will also fail. Logs from the above:

multipassd.log

2022-01-07T17:17:39.316] [info] [dev] VM shut down
[2022-01-07T17:17:39.323] [info] [dev] process state changed to NotRunning
[2022-01-07T17:17:39.323] [info] [dev] process finished with exit code 0
[2022-01-07T17:18:29.454] [debug] [update] Latest Multipass release available is version 1.8.0
[2022-01-07T17:18:31.478] [info] [VMImageHost] Did not find any supported products in "appliance"
[2022-01-07T17:18:31.504] [info] [rpc] gRPC listening on unix:/var/run/multipass_socket, SSL:on
[2022-01-07T17:18:31.515] [debug] [qemu-img] [786] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/dev/ubuntu-20.04-server-cloudimg-arm64.img
[2022-01-07T17:18:31.762] [info] [daemon] dev needs starting. Starting now...
[2022-01-07T17:18:31.766] [info] [daemon] Starting Multipass 1.8.1+mac
[2022-01-07T17:18:31.766] [info] [daemon] Daemon arguments: /Library/Application Support/com.canonical.multipass/bin/multipassd --verbosity debug
[2022-01-07T17:18:31.767] [debug] [dev] process working dir ''
[2022-01-07T17:18:31.767] [info] [dev] process program 'qemu-system-aarch64'
[2022-01-07T17:18:31.768] [info] [dev] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dev/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 4, -m, 8192M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/dev/cloud-init-config.iso'
[2022-01-07T17:18:31.832] [debug] [qemu-system-aarch64] [788] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.FtQGae
[2022-01-07T17:18:32.513] [info] [dev] process state changed to Starting
[2022-01-07T17:18:32.544] [info] [dev] process state changed to Running
[2022-01-07T17:18:32.544] [debug] [qemu-system-aarch64] [793] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dev/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 4 -m 8192M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/dev/cloud-init-config.iso
[2022-01-07T17:18:32.545] [info] [dev] process started
[2022-01-07T17:18:32.547] [debug] [dev] Waiting for SSH to be up
[2022-01-07T17:18:32.963] [warning] [dev] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: MAC:              ae:47:28:c2:2b:e4
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:4a:29:43: info: UUID:             19EE9E04-2641-4575-BA4E-C06F654CA7DA

[2022-01-07T17:18:32.963] [warning] [qemu-system-aarch64] 
[2022-01-07T17:18:32.964] [debug] [dev] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2022-01-07T17:18:33.015] [debug] [dev] QMP: {"return": {}}

[2022-01-07T17:18:46.323] [debug] [dev] QMP: {"timestamp": {"seconds": 1641604726, "microseconds": 323225}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[9]/virtio-backend"}}
morphologue commented 2 years ago

I'm in the same situation as @rjoelnorgren (work laptop) but I have been able to work around this by adding the following from /Library/Application Support/com.canonical.multipass/bin/multipass to my firewall settings:

image

I'm not sure which one did the trick but at least I can get on with my day now :)

rjoelnorgren commented 2 years ago

@morphologue, thank you for the suggestion. Unfortunately that did not resolve the issue on my end.

mstoffel-sag commented 2 years ago

Hi, any update on this? Multipass also stopped working for me after the latest Mac OS update.

Saviq commented 2 years ago

Anyone experiencing this would you please run sudo tcpdump -i bridge100 udp port 67 and port 68 immediately after starting an instance? This would tell us whether the instance got up (and requests IP via DHCP) at all. Just a reminder that disabling the firewall helps many.

vordenken commented 2 years ago

I think I have the same or a similar problem.... Worked fine just a few days ago.

Logs:

➜  ~ multipass start -vvv crowdsec-head-01
[2022-02-09T15:31:39.302] [debug] [crowdsec-head-01] process working dir ''
[2022-02-09T15:31:39.302] [info] [crowdsec-head-01] process program 'qemu-system-aarch64'
[2022-02-09T15:31:39.302] [info] [crowdsec-head-01] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:8f:bf:f9, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/crowdsec-head-01/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/crowdsec-head-01/cloud-init-config.iso'
[2022-02-09T15:31:39.302] [warning] [Qt] QProcess: Destroyed while process ("qemu-system-aarch64") is still running.
[2022-02-09T15:31:39.306] [error] [crowdsec-head-01] process error occurred Crashed program: qemu-system-aarch64; error: Process crashed
[2022-02-09T15:31:39.307] [info] [crowdsec-head-01] process state changed to NotRunning
[2022-02-09T15:31:39.307] [error] [crowdsec-head-01] error: program: qemu-system-aarch64; error: Process crashed
[2022-02-09T15:31:39.307] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-02-09T15:31:39.307] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-02-09T15:31:39.307] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-02-09T15:31:39.308] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-02-09T15:31:39.308] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2022-02-09T15:31:39.308] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
start failed: cannot connect to the multipass socket
Please ensure multipassd is running and '/var/run/multipass_socket' is accessible
➜  ~ multipass start -vvv crowdsec-head-01
[2022-02-09T15:35:14.382] [debug] [crowdsec-head-01] process working dir ''
[2022-02-09T15:35:14.382] [info] [crowdsec-head-01] process program 'qemu-system-aarch64'
[2022-02-09T15:35:14.382] [info] [crowdsec-head-01] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:8f:bf:f9, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/crowdsec-head-01/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/crowdsec-head-01/cloud-init-config.iso'
[2022-02-09T15:35:14.386] [debug] [qemu-system-aarch64] [18997] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.CGaaLm
[2022-02-09T15:35:14.429] [info] [crowdsec-head-01] process state changed to Starting
[2022-02-09T15:35:14.431] [info] [crowdsec-head-01] process state changed to Running
[2022-02-09T15:35:14.431] [debug] [qemu-system-aarch64] [18998] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:8f:bf:f9 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/crowdsec-head-01/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/crowdsec-head-01/cloud-init-config.iso
[2022-02-09T15:35:14.432] [info] [crowdsec-head-01] process started
start failed: The following errors occurred:
crowdsec-head-01: timed out waiting for response

The command sudo tcpdump -i bridge100 udp port 67 and port 68gives me this:

tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on bridge100, link-type EN10MB (Ethernet), capture size 262144 bytes
15:35:28.613971 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:35:31.733851 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:35:36.168101 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:35:45.084670 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:36:01.635889 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:36:32.726072 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:37:37.658265 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:38:41.881501 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:39:46.838150 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:40:50.569279 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:41:54.450206 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:42:59.494243 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:44:03.859061 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:45:07.686922 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:46:11.770182 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:47:15.359838 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:48:20.361939 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:49:24.551753 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:50:28.703777 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:51:32.020575 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:52:36.085425 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
15:53:39.938214 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:8f:bf:f9 (oui Unknown), length 300
Saviq commented 2 years ago

Thanks @vordenken this, unfortunately, confirms that it's Apple's own bootpd that stops replying to DHCP requests from our instances… We've not found a way to fix that so far, things like toggling Internet Sharing, ensuring Firewall is off are things to try.

What's worse, we've not found a way to reproduce so we have little chance at tracking down a solution.

bjonnh-work commented 2 years ago

Adding hyperkit to the firewall solved it for me.

aliofye commented 2 years ago

@Saviq its happening to me right now so I can help you debug and troubleshoot solutions, previously adding binaries to the whitelist on the macOS firewall worked but now it doesn't even though i've added everything under Library/Application Support/com.canonical.multipass/bin

Edit: usually happens after a restart or a mac update

Edit 2: disabling firewall did the trick but obviously not ideal, my offer to debug and fix this still stands @Saviq

milopersic commented 2 years ago

For what it's worth I've been using Multipass daily now since January 5th with the firewall disabled. I've gone through at least one MacOS update (now on Monterey 12.2.1) and it's stable. I'd like to have my firewall up again, but at least I can work. I hope Apple can assist Canonical on this one.

Saviq commented 2 years ago

@aliofye @milopersic thanks! We need to look into it from our side. Now that the firewall seems to surface as the common issue, we will hopefully be able to reproduce and find a way to detect / work around the problem.

milopersic commented 2 years ago

You're most welcome, and best of luck! Early hiccups are normal of course - Mulitpass is amazing and I love it. Just glad it exists!

bjonnh-work commented 2 years ago

It happened again to me. It worked when I added it to the firewall but it stopped working again. I also have issues with my regular qemu VMs so maybe there is something with qemu networking?

bjonnh-work commented 2 years ago

Also when starting I sometimes get:

[2022-02-28T09:56:40.154] [error] [vm1] process error occurred Crashed program: qemu-system-aarch64; error: Process crashed
[2022-02-28T09:56:40.156] [error] [vm1] error: program: qemu-system-aarch64; error: Process crashed
start failed: cannot connect to the multipass socket
Please ensure multipassd is running and '/var/run/multipass_socket' is accessible

Doing it another time makes it start but still no network.

chrisode commented 2 years ago

I can also verify this problem. After my company activated the firewall on my Macbook Pro M1 did multipass work for a few days but started to act a bit weird and then it completely stopped working, I have tried to add all binaries in the multipass bin folder but it has not resolved the problem for me with the vm not getting assigned an ip and therefor timesout and stays in a unknown state.

For me it seems like the problem is more likely to happen on an M1 than on an intel Macbook. I have tried running it on my personal Macbook Air with the firewall turned on. Multipass acts the same as on the M1 with no exceptions added, but adding all the binaries in the Multipass bin folder makes it work on that computer. Both Macbooks run Monterey 12.2.1. Running Qemu on both systems.

Launch output:

∫ multipass launch -vvv
[2022-03-01T09:05:37.629] [info] [VMImageHost] Did not find any supported products in "appliance"
[2022-03-01T09:05:37.632] [debug] [qemu-system-aarch64] [19935] started: qemu-system-aarch64 --version
[2022-03-01T09:05:38.017] [debug] [qemu-img] [19937] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20220207/ubuntu-20.04-server-cloudimg-arm64.img
[2022-03-01T09:05:38.151] [debug] [qemu-img] [19938] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/ubuntu-20.04-server-cloudimg-arm64.img 5368709120
[2022-03-01T09:05:38.166] [debug] [qemu-img] [19939] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/ubuntu-20.04-server-cloudimg-arm64.img
[2022-03-01T09:05:38.172] [debug] [civic-angelfish] process working dir ''
[2022-03-01T09:05:38.172] [info] [civic-angelfish] process program 'qemu-system-aarch64'
[2022-03-01T09:05:38.172] [info] [civic-angelfish] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/cloud-init-config.iso'
[2022-03-01T09:05:38.174] [debug] [qemu-system-aarch64] [19940] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.cBByVt
[2022-03-01T09:05:38.206] [info] [civic-angelfish] process state changed to Starting
[2022-03-01T09:05:38.208] [info] [civic-angelfish] process state changed to Running
[2022-03-01T09:05:38.209] [debug] [qemu-system-aarch64] [19941] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/cloud-init-config.iso
[2022-03-01T09:05:38.209] [info] [civic-angelfish] process started
launch failed: The following errors occurred:
civic-angelfish: timed out waiting for response

My multipassd log from the M1

[2022-03-01T09:05:38.172] [info] [civic-angelfish] process program 'qemu-system-aarch64'
[2022-03-01T09:05:38.172] [info] [civic-angelfish] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/cloud-init-config.iso'
[2022-03-01T09:05:38.174] [debug] [qemu-system-aarch64] [19940] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.cBByVt
[2022-03-01T09:05:38.206] [info] [civic-angelfish] process state changed to Starting
[2022-03-01T09:05:38.208] [info] [civic-angelfish] process state changed to Running
[2022-03-01T09:05:38.209] [debug] [qemu-system-aarch64] [19941] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/civic-angelfish/cloud-init-config.iso
[2022-03-01T09:05:38.209] [info] [civic-angelfish] process started
[2022-03-01T09:05:38.209] [debug] [civic-angelfish] Waiting for SSH to be up
[2022-03-01T09:05:38.900] [warning] [civic-angelfish] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: MAC:              e2:c9:43:ba:e0:b7
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e3:34:52: info: UUID:             3FF6CCD4-7600-4FFA-BBA4-35CF034F4292

[2022-03-01T09:05:38.900] [warning] [qemu-system-aarch64]
[2022-03-01T09:05:38.900] [debug] [civic-angelfish] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2022-03-01T09:05:39.001] [debug] [civic-angelfish] QMP: {"return": {}}

[2022-03-01T09:05:53.115] [debug] [civic-angelfish] QMP: {"timestamp": {"seconds": 1646121953, "microseconds": 115781}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[6]/virtio-backend"}}
milopersic commented 2 years ago

@chrisode It's very interesting about "working for a few days" - my experience exactly. I never determined why it would work with the firewall enabled, but only for a limited time, usually a few days.

bjonnh-work commented 2 years ago

Same thing for me. It stopped working a few days after I allowed multipass binaries.

Weirder thing, bootp was not running when I tried to start an existing VM. But then it started when I created a new one. With firewall off.

I cannot run that machine without a firewall so that's really blocking for me.

townsend2010 commented 2 years ago

Just an update from our side...

I updated my Intel Mac to 12.2.1 and have twice reproduced the issue. That said, I've really been unable to unearth anything meaningful as to what the root cause of this issue is. This is what I found though.

  1. The Apple Firewall refuses to log any information at all even though I ensured logging is enabled and turned on detailed logging. This seems to be a common issue with the firewall and is very unhelpful for this debugging.
  2. I tried running the firewall on the command line with debugging enabled via /usr/libexec/ApplicationFirewall/socketfilterfw -d. I could never get this to reproduce when running the firewall this way.
  3. I did get the QEMU crash one time and after that, it would get this failure. Again, I tried debugging, but in restarting the firewall, it cleared up. I have tried starting QEMU via the console with the output going to the console to see if I could reproduce the crash. I had no luck.
  4. I've since tried to reproduce the issue again and have not been able to. This has included restarting my Mac, enabling->disabling->enabling the firewall, "crashing" (via kill -9) the qemu process, etc. and still nothing.

If anyone else has any ideas on how better to reproduce this or finding a common trigger, that would be helpful. I'll continue trying to find a root cause...

mstoffel-sag commented 2 years ago

I reinstalled Multipass with the latest Monterey update 12.3. So far everything seems to work..... fingers crossed...

milopersic commented 2 years ago

@mstoffel-sag Cool! I upgraded to 12.3 last night but haven't been so brave. I'm assuming your firewall is active? It usually takes a day or two to start acting up :(

mstoffel-sag commented 2 years ago

Yes, firewall is active. Working fine so far. lets see how it goes..

cjermain commented 2 years ago

I was running into the same problems as above. Upgrading to the latest Monterey 12.3, keeping the firewall on, and re-installing multipass worked.

kalebheitzman commented 2 years ago

Upgrading to Monterey 12.3 fixed the issue for me as well. I didn't need to reinstall Multipass. I could reproduce the behavior every time on a M1. Turn the firewall on and I couldn't launch a container. Turn it off and it would work fine. I could consistently reproduce this behavior on the previous version of Monterey. A benefit of the upgrade is that it seems multipass starts the containers immediately instead of take several seconds like it did before on the previous version of Monterey.

tazle commented 2 years ago

I bumped from #2600 to here, and then noticed #2204. Which part of multipass should ensure that bootpd is up and running? It seems that after uprading to MacOS 12.4 it isn't running for me, possibly because "Internet Sharing" is "Off". The instructions at https://multipass.run/docs/troubleshooting-networking-on-macos say that "Internet Sharing" may appear disabled even in working configuration.

The instructions say that Hypervisor.framework should take care of setting up DHCP (bootpd) and DNS services, but is there some way to repeat that setup, since it has apparently gone missing for me?