lima: Alpine doesn't work with `vmType: vz` on macOS 13.2.1 / aarch64 (anymore?)

I know this used to work for me, but now I can no longer use Alpine with the vz vmType. I observed this in the current 0.15 release, so I went back to 0.14.2 and 0.14.1, and all fail the same way.

I know this used to work on the same machine before, so I wonder if this is due to a macOS update (I may have been on 13.1 the last time I tested).

Failure looks like this (all I’m doing is adding a line with vmType: vz to the template):

$ l --debug start template://alpine
DEBU[0000] interpreting argument "template://alpine" as a template name "alpine"
? Creating an instance "alpine" Open an editor to review or modify the current configuration
DEBU[0003] opening editor "/opt/homebrew/bin/emacsclient" for a file "/var/folders/h6/d884sl8915j_xt2fs42bztb00000gn/T/lima-editor-1708077455"
Waiting for Emacs...
WARN[0014] `vmType: vz` is experimental
DEBU[0014] Make sure "shared" network is stopped
DEBU[0014] Make sure "bridged" network is stopped
DEBU[0014] Make sure "host" network is stopped
INFO[0014] Attempting to download the image from "https://github.com/lima-vm/alpine-lima/releases/download/v0.2.27/alpine-lima-std-3.17.0-aarch64.iso"  digest="sha512:b8028c96385ea5be499e37c142cb9e9d9c861f2647ff7f8cceaf867961ef8878e34a8ba0e8cfe2e01ac082191048e7acc30534782b13c5ec4bea53dad5919c33"
DEBU[0014] file "/Users/jan/.lima/alpine/basedisk" is cached as "/Users/jan/Library/Caches/lima/download/by-url-sha256/c53b1c3f6137c7378edfd6d113f3a63f758b8af6090d8611445331f907966aac/data"
DEBU[0014] Comparing digest "sha512:b8028c96385ea5be499e37c142cb9e9d9c861f2647ff7f8cceaf867961ef8878e34a8ba0e8cfe2e01ac082191048e7acc30534782b13c5ec4bea53dad5919c33" with the cached digest file "/Users/jan/Library/Caches/lima/download/by-url-sha256/c53b1c3f6137c7378edfd6d113f3a63f758b8af6090d8611445331f907966aac/sha512.digest", not computing the actual digest of "/Users/jan/Library/Caches/lima/download/by-url-sha256/c53b1c3f6137c7378edfd6d113f3a63f758b8af6090d8611445331f907966aac/data"
DEBU[0014] res.ValidatedDigest=true
INFO[0014] Using cache "/Users/jan/Library/Caches/lima/download/by-url-sha256/c53b1c3f6137c7378edfd6d113f3a63f758b8af6090d8611445331f907966aac/data"
DEBU[0014] [hostagent] Creating iso file /Users/jan/.lima/alpine/cidata.iso
DEBU[0014] [hostagent] Using /var/folders/h6/d884sl8915j_xt2fs42bztb00000gn/T/diskfs_iso1838456468 as workspace
DEBU[0014] [hostagent] Failed to detect CPU features. Assuming that AES acceleration is available on this Apple silicon.
DEBU[0014] [hostagent] OpenSSH version 9.0.1 detected
DEBU[0014] [hostagent] AES accelerator seems available, prioritizing aes128-gcm@openssh.com and aes256-gcm@openssh.com
INFO[0014] [hostagent] Starting VZ (hint: to watch the boot progress, see "/Users/jan/.lima/alpine/serial.log")
DEBU[0014] [hostagent] Start udp server listening on: 127.0.0.1:49855
DEBU[0014] [hostagent] Start tcp server listening on: 127.0.0.1:50037
DEBU[0015] [hostagent] Using search domains: [home]
DEBU[0015] [hostagent] [VZ] - vm state change: "VirtualMachineStateStarting"
DEBU[0015] received an event                             event="{2023-03-01 17:23:29.62845 -0800 PST {false false false [] 50036}}"
INFO[0015] SSH Local Port: 50036
INFO[0015] [hostagent] new connection from  to
INFO[0015] [hostagent] Waiting for the essential requirement 1 of 5: "ssh"
INFO[0015] [hostagent] [VZ] - vm state change: running
DEBU[0015] [hostagent] executing script "ssh"
DEBU[0015] [hostagent] executing ssh for script "ssh": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/jan/.lima/_config/user" -o IdentityFile="/Users/jan/.ssh/jan@jandubois.com" -o IdentityFile="/Users/jan/.ssh/jdubois@suse.com" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o GSSAPIAuthentication=no -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=jan -o ControlMaster=auto -o ControlPath="/Users/jan/.lima/alpine/ssh.sock" -o ControlPersist=5m -p 50036 127.0.0.1 -- /bin/bash]
INFO[0018] [hostagent] 2023/03/01 17:23:32 tcpproxy: for incoming conn 127.0.0.1:50038, error dialing "192.168.5.15:22": connect tcp 192.168.5.15:22: no route to host
DEBU[0018] [hostagent] stdout="", stderr="kex_exchange_identification: read: Connection reset by peer\r\nConnection reset by 127.0.0.1 port 50036\r\n", err=failed to execute script "ssh": stdout="", stderr="kex_exchange_identification: read: Connection reset by peer\r\nConnection reset by 127.0.0.1 port 50036\r\n": exit status 255
INFO[0028] [hostagent] Waiting for the essential requirement 1 of 5: "ssh"
DEBU[0028] [hostagent] executing script "ssh"
DEBU[0028] [hostagent] executing ssh for script "ssh": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/jan/.lima/_config/user" -o IdentityFile="/Users/jan/.ssh/jan@jandubois.com" -o IdentityFile="/Users/jan/.ssh/jdubois@suse.com" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o GSSAPIAuthentication=no -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=jan -o ControlMaster=auto -o ControlPath="/Users/jan/.lima/alpine/ssh.sock" -o ControlPersist=5m -p 50036 127.0.0.1 -- /bin/bash]
INFO[0031] [hostagent] 2023/03/01 17:23:45 tcpproxy: for incoming conn 127.0.0.1:50039, error dialing "192.168.5.15:22": connect tcp 192.168.5.15:22: no route to host
DEBU[0031] [hostagent] stdout="", stderr="kex_exchange_identification: read: Connection reset by peer\r\nConnection reset by 127.0.0.1 port 50036\r\n", err=failed to execute script "ssh": stdout="", stderr="kex_exchange_identification: read: Connection reset by peer\r\nConnection reset by 127.0.0.1 port 50036\r\n": exit status 255
INFO[0041] [hostagent] Waiting for the essential requirement 1 of 5: "ssh"
DEBU[0041] [hostagent] executing script "ssh"
DEBU[0041] [hostagent] executing ssh for script "ssh": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/jan/.lima/_config/user" -o IdentityFile="/Users/jan/.ssh/jan@jandubois.com" -o IdentityFile="/Users/jan/.ssh/jdubois@suse.com" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o GSSAPIAuthentication=no -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=jan -o ControlMaster=auto -o ControlPath="/Users/jan/.lima/alpine/ssh.sock" -o ControlPersist=5m -p 50036 127.0.0.1 -- /bin/bash]
^C

Can anybody else repro?

Any thoughts on how to debug this, given we have no video support?

$ ssh -o 'IdentityFile="/Users/jan/.lima/_config/user"' -o 'IdentityFile="/Users/jan/.ssh/jan@jandubois.com"' -o 'IdentityFile="/Users/jan/.ssh/jdubois@suse.com"' -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o GSSAPIAuthentication=no -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o 'Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com"' -o User=jan -o ControlMaster=auto -o 'ControlPath="/Users/jan/.lima/alpine/ssh.sock"' -o ControlPersist=5m -o Hostname=127.0.0.1 -o Port=49360 lima-alpine
kex_exchange_identification: read: Connection reset by peer
Connection reset by 127.0.0.1 port 49360

There doesn’t seem to be anything helpful in ha.stderr.log:

$ cat ~/.lima/alpine/ha.stderr.log
{"level":"debug","msg":"Creating iso file /Users/jan/.lima/alpine/cidata.iso","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"Using /var/folders/h6/d884sl8915j_xt2fs42bztb00000gn/T/diskfs_iso1838456468 as workspace","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"Failed to detect CPU features. Assuming that AES acceleration is available on this Apple silicon.","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"OpenSSH version 9.0.1 detected","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"AES accelerator seems available, prioritizing aes128-gcm@openssh.com and aes256-gcm@openssh.com","time":"2023-03-01T17:23:29-08:00"}
{"level":"info","msg":"Starting VZ (hint: to watch the boot progress, see \"/Users/jan/.lima/alpine/serial.log\")","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"Start udp server listening on: 127.0.0.1:49855","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"Start tcp server listening on: 127.0.0.1:50037","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"Using search domains: [home]","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"[VZ] - vm state change: \"VirtualMachineStateStarting\"","time":"2023-03-01T17:23:29-08:00"}
{"level":"info","msg":"new connection from  to ","time":"2023-03-01T17:23:29-08:00"}
{"level":"info","msg":"Waiting for the essential requirement 1 of 5: \"ssh\"","time":"2023-03-01T17:23:29-08:00"}
{"level":"info","msg":"[VZ] - vm state change: running","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"executing script \"ssh\"","time":"2023-03-01T17:23:29-08:00"}
{"level":"debug","msg":"executing ssh for script \"ssh\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/jan/.lima/_config/user\" -o IdentityFile=\"/Users/jan/.ssh/jan@jandubois.com\" -o IdentityFile=\"/Users/jan/.ssh/jdubois@suse.com\" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o GSSAPIAuthentication=no -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o Ciphers=\"^aes128-gcm@openssh.com,aes256-gcm@openssh.com\" -o User=jan -o ControlMaster=auto -o ControlPath=\"/Users/jan/.lima/alpine/ssh.sock\" -o ControlPersist=5m -p 50036 127.0.0.1 -- /bin/bash]","time":"2023-03-01T17:23:29-08:00"}
2023/03/01 17:23:32 tcpproxy: for incoming conn 127.0.0.1:50038, error dialing "192.168.5.15:22": connect tcp 192.168.5.15:22: no route to host
{"level":"debug","msg":"stdout=\"\", stderr=\"kex_exchange_identification: read: Connection reset by peer\\r\\nConnection reset by 127.0.0.1 port 50036\\r\\n\", err=failed to execute script \"ssh\": stdout=\"\", stderr=\"kex_exchange_identification: read: Connection reset by peer\\r\\nConnection reset by 127.0.0.1 port 50036\\r\\n\": exit status 255","time":"2023-03-01T17:23:32-08:00"}
[...]

Both experimental/vz and default (with added vmType: vz) work fine on the same machine with the same Lima version.