Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Apple M1] Instance no longer get an IP address when it previously worked #2265

Closed
townsend2010 opened this issue Sep 29, 2021 · 30 comments
Closed

Comments

@townsend2010
Copy link
Contributor

This is separating out the ongoing issues seen in #1857 where for some reason, instances are no longer getting an IP address when it previously worked.

@townsend2010
Copy link
Contributor Author

Hi @adamcstephens & @lethargosapatheia,

I've moved the thread to this new issue. One thing I'd like for you to check is when there is a Multipass instance launched, do you see a bridge100 in the output of ifconfig? If so, could you post the output of ifconfig bridge100?

Thanks!

@lethargosapatheia
Copy link

Here it is:

$ multipass launch --name testing
Starting testing /
bridge100: flags=8a63<UP,BROADCAST,SMART,RUNNING,ALLMULTI,SIMPLEX,MULTICAST> mtu 1500
	options=3<RXCSUM,TXCSUM>
	ether 3e:06:30:20:54:64
	inet 192.168.64.1 netmask 0xffffff00 broadcast 192.168.64.255
	inet6 fe80::8ae:9486:dbeb:1196%bridge100 prefixlen 64 optimistic secured scopeid 0x14
	Configuration:
		id 0:0:0:0:0:0 priority 0 hellotime 0 fwddelay 0
		maxage 0 holdcnt 0 proto stp maxaddr 100 timeout 1200
		root id 0:0:0:0:0:0 priority 0 ifcost 0 port 0
		ipfilter disabled flags 0x0
	member: en7 flags=3<LEARNING,DISCOVER>
	        ifmaxaddr 0 port 19 priority 0 path cost 0
	nd6 options=201<PERFORMNUD,DAD>
	media: autoselect
	status: active

@adamcstephens
Copy link

I ran a tcpdump on that interface and the VM is requesting an IPv4 address:

─❯ sudo tcpdump -i bridge100 port bootpc or port bootps
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on bridge100, link-type EN10MB (Ethernet), capture size 262144 bytes
21:04:24.858843 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:b1:40:8f (oui Unknown), length 300
21:05:29.811132 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:b1:40:8f (oui Unknown), length 300
21:06:33.347818 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:b1:40:8f (oui Unknown), length 300
21:07:37.779799 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:b1:40:8f (oui Unknown), length 300

Also IPv6 seems to work, I assume this is the VM based off the tcpdump data:

─❯ ping6 fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f
PING6(56=40+8+8 bytes) fd33:5c04:3ba9:a6e2:1c8c:69bb:f02a:b1c7 --> fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f
16 bytes from fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f, icmp_seq=0 hlim=64 time=1.531 ms
16 bytes from fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f, icmp_seq=1 hlim=64 time=0.468 ms
16 bytes from fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f, icmp_seq=2 hlim=64 time=0.918 ms
^C
--- fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f ping6 statistics ---
3 packets transmitted, 3 packets received, 0.0% packet loss
round-trip min/avg/max/std-dev = 0.468/0.972/1.531/0.436 ms

~ took 2s 
─❯ ssh fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f           
The authenticity of host 'fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f (fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f)' can't be established.
ECDSA key fingerprint is SHA256:YZ3EfOyYhtG3g+8vRKmwDb/kf3caweRTnGRcYhQTrQg.
Are you sure you want to continue connecting (yes/no/[fingerprint])? yes
Warning: Permanently added 'fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f' (ECDSA) to the list of known hosts.
adam@fd33:5c04:3ba9:a6e2:5054:ff:feb1:408f: Permission denied (publickey).

Is InternetSharing providing DHCP for the VMs? Systems Preferences gives me the indication it's not fully configured:

image

I also pulled this out of my system.log in #1857. Could this be a relevant error?

Sep 27 15:34:16 mycomputer InternetSharing[11079]: DEPRECATED USE in libdispatch client: Setting timer interval to 0 requests a 1ns timer, did you mean FOREVER (a one-shot timer)?; set a breakpoint on _dispatch_bug_deprecated to debug

Is there somewhere I can learn more about how InternetSharing is configured? Does it need to be notified of the interface somehow?

@Saviq
Copy link
Collaborator

Saviq commented Sep 30, 2021

I ran a tcpdump on that interface and the VM is requesting an IPv4 address:

Also IPv6 seems to work, I assume this is the VM based off the tcpdump data:

All that shows that the network is set up correctly from our side. Thanks a lot for the dig!

Is InternetSharing providing DHCP for the VMs? Systems Preferences gives me the indication it's not fully configured:

Yes, but not in a way you can influence. If you enable Internet Sharing here it will actually prevent instances from starting altogether (the network interface will not start).

How it's set up is a bit of a black box - just starting the interface using the vmnet API is what triggers the InternetSharing process that should be serving DHCP. That's why we asked about vmcli and vftool, as they use the same networking API.

I also pulled this out of my system.log in #1857. Could this be a relevant error?

Sep 27 15:34:16 mycomputer InternetSharing[11079]: DEPRECATED USE in libdispatch client: Setting timer interval to 0 requests a 1ns timer, did you mean FOREVER (a one-shot timer)?; set a breakpoint on _dispatch_bug_deprecated to debug

Don't think so, no.

Is there somewhere I can learn more about how InternetSharing is configured? Does it need to be notified of the interface somehow?

And again, that's what QEMU is doing, but macOS seems to not be doing the right thing :/

@Saviq
Copy link
Collaborator

Saviq commented Sep 30, 2021

FWIW, the config of the DHCP lies in /etc/bootpd.list (even though bootpd itself isn't in play in Big Sur any more), my contents are:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
	<key>Subnets</key>
	<array>
		<dict>
			<key>_creator</key>
			<string>com.apple.NetworkSharing</string>
			<key>allocate</key>
			<true/>
			<key>dhcp_domain_name_server</key>
			<array>
				<string>192.168.65.1</string>
			</array>
			<key>dhcp_router</key>
			<string>192.168.65.1</string>
			<key>interface</key>
			<string>bridge100</string>
			<key>lease_max</key>
			<integer>86400</integer>
			<key>lease_min</key>
			<integer>86400</integer>
			<key>name</key>
			<string>192.168.65/24</string>
			<key>net_address</key>
			<string>192.168.65.0</string>
			<key>net_mask</key>
			<string>255.255.255.0</string>
			<key>net_range</key>
			<array>
				<string>192.168.65.2</string>
				<string>192.168.65.254</string>
			</array>
		</dict>
	</array>
	<key>bootp_enabled</key>
	<false/>
	<key>detect_other_dhcp_server</key>
	<array>
		<string>bridge100</string>
	</array>
	<key>dhcp_enabled</key>
	<array>
		<string>bridge100</string>
	</array>
	<key>dhcp_ignore_client_identifier</key>
	<true/>
	<key>ignore_allow_deny</key>
	<array>
		<string>bridge100</string>
	</array>
	<key>use_server_config_for_dhcp_options</key>
	<true/>
</dict>
</plist>

The file gets recreated if moved away, but maybe it's corrupted in your case somehow? Try killing InternetSharing and moving the file away, and see if Multipass instances work again?

@Saviq
Copy link
Collaborator

Saviq commented Oct 1, 2021

Hi @adamcstephens & @lethargosapatheia, did you have a chance to review what I wrote above? Maybe tried moving the file away to test?

@adamcstephens
Copy link

@Saviq yes I moved the file and it was recreated with the same contents. It looks similar to yours but with a different subnet.

@Saviq
Copy link
Collaborator

Saviq commented Oct 1, 2021

@adamcstephens …and it didn't help?

@townsend2010
Copy link
Contributor Author

Also @adamcstephens, what is the subnet listed in your file and does it match the vmnet info that is printed out in the multipassd log? The log info will look similar to:

[2021-09-27T15:13:14.340] [warning] [amazing-jerboa] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: MAC:              ca:5e:03:51:a5:84
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: UUID:             B7B80AF9-7FCC-4EFB-BBCE-C0B734029EA9

Thanks!

@adamcstephens
Copy link

@Saviq correct, it did not help.

@townsend2010 yes, it does match

─❯ tail -n 20 /Library/Logs/Multipass/multipassd.log
[2021-09-30T12:20:56.149] [info] [magical-phoenix] process state changed to Running
[2021-09-30T12:20:56.149] [debug] [qemu-system-aarch64] [96084] 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:21:39:c7 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/magical-phoenix/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/magical-phoenix/cloud-init-config.iso
[2021-09-30T12:20:56.149] [info] [magical-phoenix] process started
[2021-09-30T12:20:56.150] [debug] [magical-phoenix] Waiting for SSH to be up
[2021-09-30T12:20:56.720] [warning] [magical-phoenix] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: MAC:              da:ae:20:83:00:11
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:21:39:c7: info: UUID:             47DDB02F-3260-4F9C-8DF4-A5A1E70A7DA5

[2021-09-30T12:20:56.720] [warning] [qemu-system-aarch64] 
[2021-09-30T12:20:56.721] [debug] [magical-phoenix] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2021-09-30T12:20:56.758] [debug] [magical-phoenix] QMP: {"return": {}}

[2021-09-30T12:21:10.492] [debug] [magical-phoenix] QMP: {"timestamp": {"seconds": 1633018870, "microseconds": 492559}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[6]/virtio-backend"}}

─❯ cat /etc/bootpd.plist
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
	<key>Subnets</key>
	<array>
		<dict>
			<key>_creator</key>
			<string>com.apple.NetworkSharing</string>
			<key>allocate</key>
			<true/>
			<key>dhcp_domain_name_server</key>
			<array>
				<string>192.168.64.1</string>
			</array>
			<key>dhcp_router</key>
			<string>192.168.64.1</string>
			<key>interface</key>
			<string>bridge100</string>
			<key>lease_max</key>
			<integer>86400</integer>
			<key>lease_min</key>
			<integer>86400</integer>
			<key>name</key>
			<string>192.168.64/24</string>
			<key>net_address</key>
			<string>192.168.64.0</string>
			<key>net_mask</key>
			<string>255.255.255.0</string>
			<key>net_range</key>
			<array>
				<string>192.168.64.2</string>
				<string>192.168.64.254</string>
			</array>
		</dict>
	</array>
	<key>bootp_enabled</key>
	<false/>
	<key>detect_other_dhcp_server</key>
	<array>
		<string>bridge100</string>
	</array>
	<key>dhcp_enabled</key>
	<array>
		<string>bridge100</string>
	</array>
	<key>dhcp_ignore_client_identifier</key>
	<true/>
	<key>ignore_allow_deny</key>
	<array>
		<string>bridge100</string>
	</array>
	<key>use_server_config_for_dhcp_options</key>
	<true/>
</dict>
</plist>

@adamcstephens
Copy link

vmcli exhibits the same behavior of no DHCP responses. I couldn't get vftool working to see its results.

@adamcstephens
Copy link

I am currently not experiencing this issue. It's possible a reboot solved this but I am not sure.

I have launched and destroyed multiple VMs over the past couple days without problem.

@Saviq
Copy link
Collaborator

Saviq commented Oct 13, 2021

Thanks @adamcstephens, that's great news.

@lethargosapatheia are you still seeing this problem? Had you tried to reboot yet?

@lethargosapatheia
Copy link

lethargosapatheia commented Oct 14, 2021

@Saviq
Hello. Yes, I have the same problem. Also after reboot. The VM isn't starting. I now have this version installed (I'm not sure which one I had initially):

multipass   1.8.0-rc.849+gb6625c10.mac
multipassd  1.8.0-rc.849+gb6625c10.mac

By the way, is there such a thing as an uninstaller that cleans up everything if I wanted to install everything anew?

@Saviq
Copy link
Collaborator

Saviq commented Oct 15, 2021

By the way, is there such a thing as an uninstaller that cleans up everything if I wanted to install everything anew?

Follow https://multipass.run/docs/installing-on-macos:

$ sudo sh "/Library/Application Support/com.canonical.multipass/uninstall.sh"

Unfortunately it's quite unlikely it will help - as far we can tell, it's macOS not working well, not Multipass.

@lethargosapatheia
Copy link

lethargosapatheia commented Oct 15, 2021

I'm asking out of pure technical curiosity (wouldn't dare pointing any fingers :) ): why do you think Parallels works without any issues, for example? That is, if you happen to have any experience with it...

Reinstalling it didn't change anything, of course, as you've anticipated :)

@townsend2010
Copy link
Contributor Author

@lethargosapatheia,

I'm not privy to how Parallels handles virtual networking since it's closed source, but it's quite possible that it doesn't use vmnet, but instead has its own solution that is not dependent on the vmnet technology. There could also be some incompatibility to whatever virtual networking solution uses and vmnet and that is causing your issue. As you can probably tell, I'm just speculating here. 🙂

@lethargosapatheia
Copy link

just FYI: I've been trying this tool for virtualisation, and it seems to work consistently:
https://github.com/lima-vm/lima
But I haven't tested it it thoroughly yet. There are some things I still need to sort out.

@lucasnetau
Copy link

Purely observational, I have this issue crop up every now and then on Intel and now on my M1. Finding no process providing DHCP and instances cannot launch anymore when previously they were running.

lsof -iUDP:67 -n -P returns nothing instead of output similar to

COMMAND PID USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
launchd   1 root   10u  IPv4 0xXXXXXXXXXXXXX      0t0  UDP *:67
launchd   1 root   47u  IPv4 0xXXXXXXXXXXXXX      0t0  UDP *:67

Going into System Preferences -> Sharing, and enabling Internet Sharing, then disabling it again allows launchd to start the bootp server again and instances can launch again.

@Saviq
Copy link
Collaborator

Saviq commented Nov 3, 2021

Thanks a lot @lucasnetau! It looks like we may need to add a quirk for this case and inform the user of the possible workaround.

@Saviq
Copy link
Collaborator

Saviq commented Nov 3, 2021

@lethargosapatheia lima, by default, uses guest networking which does not allow IP traffic between the host and instances. If you enable vde_vmnet, you'd be in the same boat again (at least for that network).

@pavibhai
Copy link

pavibhai commented Nov 5, 2021

I have tried to use multipass on Apple M1 Max and have observed that if the Firewall is turned on (as per documentation without blocking all incoming connections) I get the timeout described above. If the Firewall is off, then I am able to launch instances, perform shell into them etc without any problems.

I am running 1.8.0

multipass   1.8.0+mac
multipassd  1.8.0+mac

Firewall On
Like I mentioned in the brief above, Block All Incoming Connections = Off

multipass start dvm -vvvv

Client Log

[2021-11-05T05:00:26.235] [debug] [dvm] process working dir ''
[2021-11-05T05:00:26.235] [info] [dvm] process program 'qemu-system-aarch64'
[2021-11-05T05:00:26.235] [info] [dvm] 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:b2:a5:46, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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, 6144M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso'
[2021-11-05T05:00:26.239] [debug] [qemu-system-aarch64] [4551] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.qgrFCj
[2021-11-05T05:00:26.299] [info] [dvm] process state changed to Starting
[2021-11-05T05:00:26.301] [info] [dvm] process state changed to Running
[2021-11-05T05:00:26.301] [debug] [qemu-system-aarch64] [4552] 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:b2:a5:46 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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 6144M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso
[2021-11-05T05:00:26.301] [info] [dvm] process started
start failed: The following errors occurred:
dvm: timed out waiting for response

multipass log

[2021-11-05T05:00:26.235] [debug] [dvm] process working dir ''
[2021-11-05T05:00:26.235] [info] [dvm] process program 'qemu-system-aarch64'
[2021-11-05T05:00:26.235] [info] [dvm] 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:b2:a5:46, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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, 6144M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso'
[2021-11-05T05:00:26.238] [debug] [qemu-system-aarch64] [4551] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.qgrFCj
[2021-11-05T05:00:26.299] [info] [dvm] process state changed to Starting
[2021-11-05T05:00:26.301] [info] [dvm] process state changed to Running
[2021-11-05T05:00:26.301] [debug] [qemu-system-aarch64] [4552] 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:b2:a5:46 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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 6144M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso
[2021-11-05T05:00:26.301] [info] [dvm] process started
[2021-11-05T05:00:26.302] [debug] [dvm] Waiting for SSH to be up
[2021-11-05T05:00:26.606] [warning] [dvm] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: MAC:              ae:1e:6a:fd:c0:f0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: UUID:             F067C046-6D9B-44C8-BF6D-F65CE0BF6F88

[2021-11-05T05:00:26.606] [warning] [qemu-system-aarch64]
[2021-11-05T05:00:26.607] [debug] [dvm] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2021-11-05T05:00:26.636] [debug] [dvm] QMP: {"return": {}}

[2021-11-05T05:00:39.517] [debug] [dvm] QMP: {"timestamp": {"seconds": 1636113639, "microseconds": 517362}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[9]/virtio-backend"}}

Firewall Off
I have also noticed that after I see this issue, I need to unload and load the service before I can work with instances.

sudo launchctl unload /Library/LaunchDaemons/com.canonical.multipassd.plist
sudo launchctl load /Library/LaunchDaemons/com.canonical.multipassd.plist
multipass start dvm -vvvv

Client Log

[2021-11-05T05:10:51.705] [debug] [dvm] process working dir ''
[2021-11-05T05:10:51.706] [info] [dvm] process program 'qemu-system-aarch64'
[2021-11-05T05:10:51.706] [info] [dvm] 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:b2:a5:46, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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, 6144M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso'
[2021-11-05T05:10:51.709] [debug] [qemu-system-aarch64] [5169] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.iGnoaI
[2021-11-05T05:10:51.768] [info] [dvm] process state changed to Starting
[2021-11-05T05:10:51.769] [info] [dvm] process state changed to Running
[2021-11-05T05:10:51.770] [debug] [qemu-system-aarch64] [5170] 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:b2:a5:46 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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 6144M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso
[2021-11-05T05:10:51.770] [info] [dvm] process started

multipass log

[2021-11-05T05:10:51.705] [debug] [dvm] process working dir ''
[2021-11-05T05:10:51.706] [info] [dvm] process program 'qemu-system-aarch64'
[2021-11-05T05:10:51.706] [info] [dvm] 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:b2:a5:46, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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, 6144M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso'
[2021-11-05T05:10:51.709] [debug] [qemu-system-aarch64] [5169] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.iGnoaI
[2021-11-05T05:10:51.768] [info] [dvm] process state changed to Starting
[2021-11-05T05:10:51.769] [info] [dvm] process state changed to Running
[2021-11-05T05:10:51.770] [debug] [qemu-system-aarch64] [5170] 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:b2:a5:46 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/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 6144M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/dvm/cloud-init-config.iso
[2021-11-05T05:10:51.770] [info] [dvm] process started
[2021-11-05T05:10:51.770] [debug] [dvm] Waiting for SSH to be up
[2021-11-05T05:10:51.883] [warning] [dvm] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: MAC:              ae:3f:ff:fe:75:4e
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:b2:a5:46: info: UUID:             9A43D8BA-4F07-4B49-9C3F-AB1D06B90717

[2021-11-05T05:10:51.883] [warning] [qemu-system-aarch64]
[2021-11-05T05:10:51.883] [debug] [dvm] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2021-11-05T05:10:51.910] [debug] [dvm] QMP: {"return": {}}

[2021-11-05T05:11:05.096] [debug] [dvm] QMP: {"timestamp": {"seconds": 1636114265, "microseconds": 96110}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[9]/virtio-backend"}}

This is reproducible for me. I have not yet zeroed down on what needs to be enabled on the Firewall for this to be successful with the Firewall turned on.

Any pointers are much appreciated.

@gluxon
Copy link

gluxon commented Dec 31, 2021

Just to add another data point, I'm seeing the same problem @pavibhai describes.

  • multipass launch times out consistently when the macOS Firewall is enabled.
  • Completely turning the firewall off makes multipass launch consistently work.

I think the binary multipass launch relies on isn't signed or properly requesting incoming network listening privileges. I set my firewall settings to allow everything and still consistently repro'ed timeouts.

Screen Shot 2021-12-30 at 10 13 00 PM

Happy to provide any additional logs or perform troubleshooting steps. My multipassd.log file looks identical to the comment above though.

@rmartins90
Copy link

same as @gluxon here.

@Saviq
Copy link
Collaborator

Saviq commented Jan 28, 2022

Can anyone with this issue please run this and start the instance in another terminal (tcpdump comes from brew)?

$ sudo tcpdump -i any udp port 67 and port 68
tcpdump: data link type PKTAP
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on any, link-type PKTAP (Apple DLT_PKTAP), capture size 262144 bytes
20:21:21.585940 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:05:a4:a7 (oui Unknown), length 295
20:21:21.585958 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:05:a4:a7 (oui Unknown), length 295
20:21:21.585978 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:05:a4:a7 (oui Unknown), length 295
20:21:21.586656 IP 192.168.66.1.bootps > 192.168.66.22.bootpc: BOOTP/DHCP, Reply, length 300
20:21:21.586660 IP 192.168.66.1.bootps > 192.168.66.22.bootpc: BOOTP/DHCP, Reply, length 300
20:21:21.586666 IP 192.168.66.1.bootps > 192.168.66.22.bootpc: BOOTP/DHCP, Reply, length 300
20:21:21.587795 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:05:a4:a7 (oui Unknown), length 307
20:21:21.587806 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:05:a4:a7 (oui Unknown), length 307
20:21:21.587816 IP 0.0.0.0.bootpc > broadcasthost.bootps: BOOTP/DHCP, Request from 52:54:00:05:a4:a7 (oui Unknown), length 307
20:21:21.589292 IP 192.168.66.1.bootps > 192.168.66.22.bootpc: BOOTP/DHCP, Reply, length 300
20:21:21.589301 IP 192.168.66.1.bootps > 192.168.66.22.bootpc: BOOTP/DHCP, Reply, length 300
20:21:21.589309 IP 192.168.66.1.bootps > 192.168.66.22.bootpc: BOOTP/DHCP, Reply, length 300

@Saviq
Copy link
Collaborator

Saviq commented Feb 28, 2022

Hey all, so I've tried to reproduce this through enabling firewall, both on the M1 (on macOS 11.6.4) and on x86 (latest macOS 12) and I couldn't get it to break…

Could any of you with this problem please post the result of defaults read /Library/Preferences/com.apple.alf.plist? If disabling firewall doesn't fix it for you, you could try resetting the firewall settings by way of copying /usr/libexec/ApplicationFirewall/com.apple.alf.plist to the above location (ref. Command Line Firewall Management…).

@pavibhai
Copy link

@Saviq Thanks for following up

Here is the output from my M1 Max running 12.2.1

{
    allowdownloadsignedenabled = 1;
    allowsignedenabled = 1;
    applications =     (
                {
            alias = {length = 659, bytes = 0x3c3f786d 6c207665 7273696f 6e3d2231 ... 2f706c69 73743e0a };
            bundleid = "com.apple.controlcenter";
            reqdata = {length = 52, bytes = 0xfade0c00 00000034 00000001 00000006 ... 74657200 00000003 };
            state = 0;
        },
                {
            alias = {length = 634, bytes = 0x3c3f786d 6c207665 7273696f 6e3d2231 ... 2f706c69 73743e0a };
            bundleid = "com.jetbrains.intellij.ce";
            reqdata = {length = 168, bytes = 0xfade0c00 000000a8 00000001 00000006 ... 41523854 48330000 };
            state = 0;
        },
                {
            alias = {length = 598, bytes = 0x3c3f786d 6c207665 7273696f 6e3d2231 ... 2f706c69 73743e0a };
            bundleid = "";
            state = 0;
        }
    );
    exceptions =     (
                {
            path = "/usr/libexec/configd";
            state = 3;
        },
                {
            path = "/usr/sbin/mDNSResponder";
            state = 3;
        },
                {
            path = "/usr/sbin/racoon";
            state = 3;
        },
                {
            path = "/usr/bin/nmblookup";
            state = 3;
        },
                {
            path = "/System/Library/PrivateFrameworks/Admin.framework/Versions/A/Resources/readconfig";
            state = 3;
        },
                {
            path = "/usr/libexec/discoveryd";
            state = 3;
        },
                {
            path = "/usr/libexec/bootpd";
            state = 3;
        },
                {
            path = "/usr/libexec/xartstorageremoted";
            state = 3;
        },
                {
            bundleid = "com.apple.EmbeddedOSInstallService";
            path = "/System/Library/PrivateFrameworks/EmbeddedOSInstall.framework/Versions/A/XPCServices/EmbeddedOSInstallService.xpc/";
            state = 3;
        }
    );
    explicitauths =     (
                {
            id = "org.python.python.app";
        },
                {
            id = "com.apple.ruby";
        },
                {
            id = "com.apple.a2p";
        },
                {
            id = "com.apple.javajdk16.cmd";
        },
                {
            id = "com.apple.php";
        },
                {
            id = "com.apple.nc";
        },
                {
            id = "com.apple.ksh";
        }
    );
    firewall =     {
        "Apple Remote Desktop" =         {
            proc = AppleVNCServer;
            state = 0;
        };
        "FTP Access" =         {
            proc = ftpd;
            state = 0;
        };
        ODSAgent =         {
            proc = ODSAgent;
            servicebundleid = "com.apple.ODSAgent";
            state = 0;
        };
        "Personal File Sharing" =         {
            proc = AppleFileServer;
            state = 0;
        };
        "Personal Web Sharing" =         {
            proc = httpd;
            state = 0;
        };
        "Printer Sharing" =         {
            proc = cupsd;
            state = 0;
        };
        "Remote Apple Events" =         {
            proc = AEServer;
            state = 0;
        };
        "Remote Login - SSH" =         {
            proc = "sshd-keygen-wrapper";
            state = 0;
        };
        "Samba Sharing" =         {
            proc = smbd;
            state = 0;
        };
    };
    firewallunload = 0;
    globalstate = 0;
    loggingenabled = 1;
    loggingoption = 0;
    previousonstate = 1;
    stealthenabled = 0;
    version = "1.6";
}

@Saviq
Copy link
Collaborator

Saviq commented Mar 1, 2022

Since the cause/effect seems the same on this one: #2265 I'll dupe this to the other so we have one place to collect all the information.

@Saviq
Copy link
Collaborator

Saviq commented Mar 1, 2022

Duplicate of #2265

@Saviq Saviq marked this as a duplicate of #2265 Mar 1, 2022
@Saviq Saviq closed this as completed Mar 1, 2022
@Saviq Saviq added duplicate and removed bug labels Mar 1, 2022
@Saviq
Copy link
Collaborator

Saviq commented Mar 1, 2022

Duplicate of #2387

@Saviq Saviq marked this as a duplicate of #2387 Mar 1, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants