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.

Sign up for GitHub

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

Jump to bottom

mounts fail after lima reboot (fuse: mountpoint is not empty) #584

Open
bcollard opened this issue Jan 24, 2022 · 5 comments
Open

mounts fail after lima reboot (fuse: mountpoint is not empty) #584

bcollard opened this issue Jan 24, 2022 · 5 comments
Labels
component/sshfs

Comments

@bcollard
Copy link

Hi! I have a few mounts configured like the following:

mounts:
  - location: "~"
    writable: false
  - location: "/tmp/lima"
    writable: true
  - location: "/opt/lima"
    writable: true

When the VM is restarted, then the mounts fail with this error message in the ha.stderr.log file:
sshfs does not seem to be mounted on ${dir}

Full logs:

{"level":"debug","msg":"firmware candidates = [/usr/local/share/qemu/edk2-x86_64-code.fd /usr/share/OVMF/OVMF_CODE.fd /usr/share/qemu/ovmf-x86_64-code.bin]","time":"2022-01-24T10:38:21+01:00"}
{"level":"debug","msg":"OpenSSH version 8.6.1 detected","time":"2022-01-24T10:38:21+01:00"}
{"level":"debug","msg":"AES accelerator seems available, prioritizing aes128-gcm@openssh.com and aes256-gcm@openssh.com","time":"2022-01-24T10:38:21+01:00"}
{"level":"info","msg":"Starting QEMU (hint: to watch the boot progress, see \"/Users/bapt/.lima/docker/serial.log\")","time":"2022-01-24T10:38:21+01:00"}
{"level":"debug","msg":"qCmd.Args: [/usr/local/bin/qemu-system-x86_64 -cpu host -machine q35,accel=hvf -smp 8,sockets=1,cores=8,threads=1 -m 24576 -drive if=pflash,format=raw,readonly=on,file=/usr/local/share/qemu/edk2-x86_64-code.fd -boot order=c,splash-time=0,menu=on -drive file=/Users/bapt/.lima/docker/diffdisk,if=virtio -cdrom /Users/bapt/.lima/docker/cidata.iso -netdev user,id=net0,net=192.168.5.0/24,dhcpstart=192.168.5.15,hostfwd=tcp:127.0.0.1:60006-:22 -device virtio-net-pci,netdev=net0,mac=52:55:55:08:7d:a3 -netdev vde,id=net1,sock=/private/var/run/lima/shared.ctl -device virtio-net-pci,netdev=net1,mac=52:55:55:79:c2:11 -device virtio-rng-pci -display none -device virtio-vga -device virtio-keyboard-pci -device virtio-mouse-pci -parallel none -chardev socket,id=char-serial,path=/Users/bapt/.lima/docker/serial.sock,server=on,wait=off,logfile=/Users/bapt/.lima/docker/serial.log -serial chardev:char-serial -chardev socket,id=char-qmp,path=/Users/bapt/.lima/docker/qmp.sock,server=on,wait=off -qmp chardev:char-qmp -name lima-docker -pidfile /Users/bapt/.lima/docker/qemu.pid]","time":"2022-01-24T10:38:21+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 1 of 5: \"ssh\"","time":"2022-01-24T10:38:21+01:00"}
{"level":"debug","msg":"executing script \"ssh\"","time":"2022-01-24T10:38:21+01:00"}
{"level":"debug","msg":"executing ssh for script \"ssh\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:38:21+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"\", err=\u003cnil\u003e","time":"2022-01-24T10:38:40+01:00"}
{"level":"info","msg":"The essential requirement 1 of 5 is satisfied","time":"2022-01-24T10:38:40+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 2 of 5: \"user session is ready for ssh\"","time":"2022-01-24T10:38:40+01:00"}
{"level":"debug","msg":"executing script \"user session is ready for ssh\"","time":"2022-01-24T10:38:41+01:00"}
{"level":"debug","msg":"executing ssh for script \"user session is ready for ssh\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:38:41+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until sudo diff -q /run/lima-ssh-ready /mnt/lima-cidata/meta-data 2\u003e/dev/null; do sleep 3; done'\\n\", err=failed to execute script \"user session is ready for ssh\": stdout=\"\", stderr=\"+ timeout 30s bash -c 'until sudo diff -q /run/lima-ssh-ready /mnt/lima-cidata/meta-data 2\u003e/dev/null; do sleep 3; done'\\n\": exit status 255","time":"2022-01-24T10:38:43+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 2 of 5: \"user session is ready for ssh\"","time":"2022-01-24T10:38:53+01:00"}
{"level":"debug","msg":"executing script \"user session is ready for ssh\"","time":"2022-01-24T10:38:53+01:00"}
{"level":"debug","msg":"executing ssh for script \"user session is ready for ssh\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:38:53+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until sudo diff -q /run/lima-ssh-ready /mnt/lima-cidata/meta-data 2\u003e/dev/null; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T10:38:54+01:00"}
{"level":"info","msg":"The essential requirement 2 of 5 is satisfied","time":"2022-01-24T10:38:54+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 3 of 5: \"sshfs binary to be installed\"","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"executing script \"sshfs binary to be installed\"","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"executing ssh for script \"sshfs binary to be installed\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"stdout=\"/usr/bin/sshfs\\n\", stderr=\"+ timeout 30s bash -c 'until command -v sshfs; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T10:38:54+01:00"}
{"level":"info","msg":"The essential requirement 3 of 5 is satisfied","time":"2022-01-24T10:38:54+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 4 of 5: \"/etc/fuse.conf to contain \\\"user_allow_other\\\"\"","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"executing script \"/etc/fuse.conf to contain \\\"user_allow_other\\\"\"","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"executing ssh for script \"/etc/fuse.conf to contain \\\"user_allow_other\\\"\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until grep -q ^user_allow_other /etc/fuse.conf; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T10:38:54+01:00"}
{"level":"info","msg":"The essential requirement 4 of 5 is satisfied","time":"2022-01-24T10:38:54+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 5 of 5: \"the guest agent to be running\"","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"executing script \"the guest agent to be running\"","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"executing ssh for script \"the guest agent to be running\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:38:54+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ sock=/run/lima-guestagent.sock\\n+ timeout 30s bash -c 'until [ -S \\\"/run/lima-guestagent.sock\\\" ]; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T10:38:55+01:00"}
{"level":"info","msg":"The essential requirement 5 of 5 is satisfied","time":"2022-01-24T10:38:55+01:00"}
{"level":"info","msg":"Mounting \"/Users/bapt\"","time":"2022-01-24T10:38:55+01:00"}
{"level":"debug","msg":"executing ssh for preparing sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- mkdir -p /Users/bapt]","time":"2022-01-24T10:38:55+01:00"}
{"level":"debug","msg":"executing ssh for remote sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- sshfs :/Users/bapt /Users/bapt -o slave -o ro -o allow_other]","time":"2022-01-24T10:38:55+01:00"}
{"level":"debug","msg":"starting sftp server for /Users/bapt","time":"2022-01-24T10:38:55+01:00"}
fuse: mountpoint is not empty
fuse: if you are sure this is safe, use the 'nonempty' mount option
{"level":"debug","msg":"generated script \"wait-for-remote-ready\" with map map[Dir:/Users/bapt MaxTrial:30]: \"#!/bin/sh\\nset -eu\\ndir=\\\"/Users/bapt\\\"\\nmax_trial=\\\"30\\\"\\nLANG=C\\nLC_ALL=C\\nexport LANG LC_ALL\\ni=0\\nwhile : ; do\\n  # FIXME: not really robust\\n  if mount | grep \\\"on ${dir}\\\" | egrep -qw \\\"fuse.sshfs|osxfuse\\\"; then\\n    echo '{\\\"return\\\":{}}'\\n    exit 0\\n  fi\\n  sleep 1\\n  if [ $i -ge ${max_trial} ]; then\\n    echo \u003e\u00262 \\\"sshfs does not seem to be mounted on ${dir}\\\"\\n    exit 1\\n  fi\\n  i=$((i + 1))\\ndone\\n\"","time":"2022-01-24T10:38:55+01:00"}
{"error":"EOF","level":"debug","msg":"sftp server for /Users/bapt exited with EOF (negligible)","time":"2022-01-24T10:38:55+01:00"}
{"level":"debug","msg":"executing ssh for script \"wait-for-remote-ready\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/sh]","time":"2022-01-24T10:38:55+01:00"}
{"level":"debug","msg":"executed script \"wait-for-remote-ready\", stdout=\"\", stderr=\"sshfs does not seem to be mounted on /Users/bapt\\n\", err=failed to execute script \"wait-for-remote-ready\": stdout=\"\", stderr=\"sshfs does not seem to be mounted on /Users/bapt\\n\": exit status 1","time":"2022-01-24T10:39:26+01:00"}
{"error":"failed to execute script \"wait-for-remote-ready\": stdout=\"\", stderr=\"sshfs does not seem to be mounted on /Users/bapt\\n\": exit status 1","level":"warning","msg":"failed to confirm whether /Users/bapt [remote] is successfully mounted","time":"2022-01-24T10:39:26+01:00"}
{"level":"info","msg":"Mounting \"/tmp/lima\"","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executing ssh for preparing sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- mkdir -p /tmp/lima]","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executing ssh for remote sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- sshfs :/tmp/lima /tmp/lima -o slave -o allow_other]","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"starting sftp server for /tmp/lima","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"generated script \"wait-for-remote-ready\" with map map[Dir:/tmp/lima MaxTrial:30]: \"#!/bin/sh\\nset -eu\\ndir=\\\"/tmp/lima\\\"\\nmax_trial=\\\"30\\\"\\nLANG=C\\nLC_ALL=C\\nexport LANG LC_ALL\\ni=0\\nwhile : ; do\\n  # FIXME: not really robust\\n  if mount | grep \\\"on ${dir}\\\" | egrep -qw \\\"fuse.sshfs|osxfuse\\\"; then\\n    echo '{\\\"return\\\":{}}'\\n    exit 0\\n  fi\\n  sleep 1\\n  if [ $i -ge ${max_trial} ]; then\\n    echo \u003e\u00262 \\\"sshfs does not seem to be mounted on ${dir}\\\"\\n    exit 1\\n  fi\\n  i=$((i + 1))\\ndone\\n\"","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executing ssh for script \"wait-for-remote-ready\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/sh]","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executed script \"wait-for-remote-ready\", stdout=\"{\\\"return\\\":{}}\\n\", stderr=\"\", err=\u003cnil\u003e","time":"2022-01-24T10:39:26+01:00"}
{"level":"info","msg":"Mounting \"/opt/lima\"","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executing ssh for preparing sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- mkdir -p /opt/lima]","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executing ssh for remote sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- sshfs :/opt/lima /opt/lima -o slave -o allow_other]","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"starting sftp server for /opt/lima","time":"2022-01-24T10:39:26+01:00"}
fuse: mountpoint is not empty
fuse: if you are sure this is safe, use the 'nonempty' mount option
{"level":"debug","msg":"generated script \"wait-for-remote-ready\" with map map[Dir:/opt/lima MaxTrial:30]: \"#!/bin/sh\\nset -eu\\ndir=\\\"/opt/lima\\\"\\nmax_trial=\\\"30\\\"\\nLANG=C\\nLC_ALL=C\\nexport LANG LC_ALL\\ni=0\\nwhile : ; do\\n  # FIXME: not really robust\\n  if mount | grep \\\"on ${dir}\\\" | egrep -qw \\\"fuse.sshfs|osxfuse\\\"; then\\n    echo '{\\\"return\\\":{}}'\\n    exit 0\\n  fi\\n  sleep 1\\n  if [ $i -ge ${max_trial} ]; then\\n    echo \u003e\u00262 \\\"sshfs does not seem to be mounted on ${dir}\\\"\\n    exit 1\\n  fi\\n  i=$((i + 1))\\ndone\\n\"","time":"2022-01-24T10:39:26+01:00"}
{"error":"EOF","level":"debug","msg":"sftp server for /opt/lima exited with EOF (negligible)","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executing ssh for script \"wait-for-remote-ready\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/sh]","time":"2022-01-24T10:39:26+01:00"}
{"level":"debug","msg":"executed script \"wait-for-remote-ready\", stdout=\"\", stderr=\"sshfs does not seem to be mounted on /opt/lima\\n\", err=failed to execute script \"wait-for-remote-ready\": stdout=\"\", stderr=\"sshfs does not seem to be mounted on /opt/lima\\n\": exit status 1","time":"2022-01-24T10:39:58+01:00"}
{"error":"failed to execute script \"wait-for-remote-ready\": stdout=\"\", stderr=\"sshfs does not seem to be mounted on /opt/lima\\n\": exit status 1","level":"warning","msg":"failed to confirm whether /opt/lima [remote] is successfully mounted","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Waiting for the optional requirement 1 of 1: \"user probe 1/1\"","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"executing script \"user probe 1/1\"","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"Forwarding unix sockets","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"executing ssh for script \"user probe 1/1\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding \"/run/docker.sock\" (guest) to \"/Users/bapt/docker.sock\" (host)","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until command -v docker \u003e/dev/null 2\u003e\u00261; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"The optional requirement 1 of 1 is satisfied","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding \"/run/lima-guestagent.sock\" (guest) to \"/Users/bapt/.lima/docker/ga.sock\" (host)","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Waiting for the final requirement 1 of 1: \"boot scripts must have finished\"","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"executing script \"boot scripts must have finished\"","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"guest agent info: \u0026{LocalPorts:[{IP:127.0.0.53 Port:53} {IP:0.0.0.0 Port:22} {IP:0.0.0.0 Port:7002} {IP:0.0.0.0 Port:7003} {IP:0.0.0.0 Port:7004} {IP:127.0.0.1 Port:55848} {IP:127.0.0.1 Port:55914} {IP:127.0.0.1 Port:55885} {IP::: Port:22}]}","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"executing ssh for script \"boot scripts must have finished\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"guest agent event: {Time:2022-01-24 09:39:58.612773844 +0000 UTC LocalPortsAdded:[{IP:127.0.0.53 Port:53} {IP:0.0.0.0 Port:22} {IP:0.0.0.0 Port:7002} {IP:0.0.0.0 Port:7003} {IP:0.0.0.0 Port:7004} {IP:127.0.0.1 Port:55848} {IP:127.0.0.1 Port:55914} {IP:127.0.0.1 Port:55885} {IP::: Port:22}] LocalPortsRemoved:[] Errors:[]}","time":"2022-01-24T10:39:58+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until sudo diff -q /run/lima-boot-done /mnt/lima-cidata/meta-data 2\u003e/dev/null; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Not forwarding TCP 127.0.0.53:53","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Not forwarding TCP 0.0.0.0:22","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"The final requirement 1 of 1 is satisfied","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding TCP from 0.0.0.0:7002 to 127.0.0.1:7002","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding TCP from 0.0.0.0:7003 to 127.0.0.1:7003","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding TCP from 0.0.0.0:7004 to 127.0.0.1:7004","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding TCP from 127.0.0.1:55848 to 127.0.0.1:55848","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding TCP from 127.0.0.1:55914 to 127.0.0.1:55914","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Forwarding TCP from 127.0.0.1:55885 to 127.0.0.1:55885","time":"2022-01-24T10:39:58+01:00"}
{"level":"info","msg":"Not forwarding TCP [::]:22","time":"2022-01-24T10:39:58+01:00"}

See also the serial.log: https://gist.github.com/bcollard/d2c6f179ad1eef080e22954e01997504

I'm running LIma v0.8.0. I tried out v0.8.1 but I felt something was unstable (my macbook crashed twice in the same period of time).
@AkihiroSuda
Copy link
Member

Please try cleaning up /opt/lima inside the guest

@AkihiroSuda AkihiroSuda changed the title mounts fail after lima reboot mounts fail after lima reboot (fuse: mountpoint is not empty) Jan 24, 2022
@bcollard
Copy link
Author

ok, so I cleaned it:

bapt@lima-docker:/Users/bapt$ tree /opt/lima/
/opt/lima/
├── docker-registry-dockerio
├── docker-registry-gcrio
└── docker-registry-quayio

3 directories, 0 files
bapt@lima-docker:/Users/bapt$ rmdir /opt/lima/docker-registry-dockerio/
bapt@lima-docker:/Users/bapt$ rmdir /opt/lima/docker-registry-gcrio/
bapt@lima-docker:/Users/bapt$ rmdir /opt/lima/docker-registry-quayio/
bapt@lima-docker:/Users/bapt$ ll /opt/lima/
total 8
drwxr-xr-x 2 bapt bapt 4096 Jan 24 10:00 ./
drwxr-xr-x 4 root root 4096 Jan 19 09:54 ../

Then I restarted Lima:

stop logs:

INFO[0000] Sending SIGINT to hostagent process 11562
INFO[0000] Waiting for the host agent and the qemu processes to shut down
INFO[0000] [hostagent] fuse: mountpoint is not empty
INFO[0000] [hostagent] fuse: if you are sure this is safe, use the 'nonempty' mount option
INFO[0000] [hostagent] fuse: mountpoint is not empty
INFO[0000] [hostagent] fuse: if you are sure this is safe, use the 'nonempty' mount option
INFO[0000] [hostagent] Received SIGINT, shutting down the host agent
INFO[0000] [hostagent] Shutting down the host agent
INFO[0000] [hostagent] Stopping forwarding "/run/docker.sock" (guest) to "/Users/bapt/docker.sock" (host)
INFO[0000] [hostagent] Stopping forwarding "/run/lima-guestagent.sock" (guest) to "/Users/bapt/.lima/docker/ga.sock" (host)
INFO[0000] [hostagent] Unmounting "/Users/bapt"
INFO[0000] [hostagent] Unmounting "/tmp/lima"
INFO[0000] [hostagent] Unmounting "/opt/lima"
INFO[0000] [hostagent] Shutting down QEMU with ACPI
INFO[0000] [hostagent] Sending QMP system_powerdown command
INFO[0012] [hostagent] QEMU has exited
INFO[0012] Stopping vmnet daemon for "shared" network
INFO[0012] Stopping switch daemon for "shared" network

start logs:

INFO[0000] Using the existing instance "docker"
INFO[0000] Starting switch daemon for "shared" network
INFO[0000] Starting vmnet daemon for "shared" network
INFO[0000] [hostagent] Starting QEMU (hint: to watch the boot progress, see "/Users/bapt/.lima/docker/serial.log")
INFO[0000] SSH Local Port: 60006
INFO[0000] [hostagent] Waiting for the essential requirement 1 of 5: "ssh"
INFO[0020] [hostagent] The essential requirement 1 of 5 is satisfied
INFO[0020] [hostagent] Waiting for the essential requirement 2 of 5: "user session is ready for ssh"
INFO[0031] [hostagent] Waiting for the essential requirement 2 of 5: "user session is ready for ssh"
INFO[0033] [hostagent] The essential requirement 2 of 5 is satisfied
INFO[0033] [hostagent] Waiting for the essential requirement 3 of 5: "sshfs binary to be installed"
INFO[0033] [hostagent] The essential requirement 3 of 5 is satisfied
INFO[0033] [hostagent] Waiting for the essential requirement 4 of 5: "/etc/fuse.conf to contain \"user_allow_other\""
INFO[0033] [hostagent] The essential requirement 4 of 5 is satisfied
INFO[0033] [hostagent] Waiting for the essential requirement 5 of 5: "the guest agent to be running"
INFO[0033] [hostagent] The essential requirement 5 of 5 is satisfied
INFO[0033] [hostagent] Mounting "/Users/bapt"
INFO[0033] [hostagent] fuse: mountpoint is not empty
INFO[0033] [hostagent] fuse: if you are sure this is safe, use the 'nonempty' mount option
WARN[0065] [hostagent] failed to confirm whether /Users/bapt [remote] is successfully mounted
INFO[0065] [hostagent] Mounting "/tmp/lima"
INFO[0065] [hostagent] Mounting "/opt/lima"
INFO[0065] [hostagent] fuse: mountpoint is not empty
INFO[0065] [hostagent] fuse: if you are sure this is safe, use the 'nonempty' mount option
WARN[0096] [hostagent] failed to confirm whether /opt/lima [remote] is successfully mounted
INFO[0096] [hostagent] Waiting for the optional requirement 1 of 1: "user probe 1/1"
INFO[0096] [hostagent] Forwarding "/run/docker.sock" (guest) to "/Users/bapt/docker.sock" (host)
INFO[0096] [hostagent] Forwarding "/run/lima-guestagent.sock" (guest) to "/Users/bapt/.lima/docker/ga.sock" (host)
INFO[0096] [hostagent] The optional requirement 1 of 1 is satisfied
INFO[0096] [hostagent] Waiting for the final requirement 1 of 1: "boot scripts must have finished"
INFO[0097] [hostagent] Not forwarding TCP [::]:22
INFO[0097] [hostagent] Forwarding TCP from 127.0.0.1:55848 to 127.0.0.1:55848
INFO[0097] [hostagent] The final requirement 1 of 1 is satisfied
INFO[0097] [hostagent] Forwarding TCP from 127.0.0.1:55914 to 127.0.0.1:55914
INFO[0097] READY. Run `limactl shell docker` to open the shell.

Same result!
In the VM, I find again the same empty directories (which are not empty on the host, they act as docker registry caches):

bapt@lima-docker:/Users/bapt$ ll /opt/lima/
total 20
drwxr-xr-x 5 bapt bapt 4096 Jan 24 10:00 ./
drwxr-xr-x 4 root root 4096 Jan 19 09:54 ../
drwxr-xr-x 2 root root 4096 Jan 24 10:00 docker-registry-dockerio/
drwxr-xr-x 2 root root 4096 Jan 24 10:00 docker-registry-gcrio/
drwxr-xr-x 2 root root 4096 Jan 24 10:00 docker-registry-quayio/
bapt@lima-docker:/Users/bapt$ ll /opt/lima/docker-registry-dockerio/
total 8
drwxr-xr-x 2 root root 4096 Jan 24 10:00 ./
drwxr-xr-x 5 bapt bapt 4096 Jan 24 10:00 ../

@bcollard
Copy link
Author

the current workaround is to delete the VM and re-create it.
Normal logs are like this:

{"level":"debug","msg":"firmware candidates = [/usr/local/share/qemu/edk2-x86_64-code.fd /usr/share/OVMF/OVMF_CODE.fd /usr/share/qemu/ovmf-x86_64-code.bin]","time":"2022-01-24T12:19:53+01:00"}
{"level":"debug","msg":"OpenSSH version 8.6.1 detected","time":"2022-01-24T12:19:53+01:00"}
{"level":"debug","msg":"AES accelerator seems available, prioritizing aes128-gcm@openssh.com and aes256-gcm@openssh.com","time":"2022-01-24T12:19:53+01:00"}
{"level":"info","msg":"Starting QEMU (hint: to watch the boot progress, see \"/Users/bapt/.lima/docker/serial.log\")","time":"2022-01-24T12:19:53+01:00"}
{"level":"debug","msg":"qCmd.Args: [/usr/local/bin/qemu-system-x86_64 -cpu host -machine q35,accel=hvf -smp 8,sockets=1,cores=8,threads=1 -m 24576 -drive if=pflash,format=raw,readonly=on,file=/usr/local/share/qemu/edk2-x86_64-code.fd -boot order=c,splash-time=0,menu=on -drive file=/Users/bapt/.lima/docker/diffdisk,if=virtio -cdrom /Users/bapt/.lima/docker/cidata.iso -netdev user,id=net0,net=192.168.5.0/24,dhcpstart=192.168.5.15,hostfwd=tcp:127.0.0.1:60006-:22 -device virtio-net-pci,netdev=net0,mac=52:55:55:08:7d:a3 -netdev vde,id=net1,sock=/private/var/run/lima/shared.ctl -device virtio-net-pci,netdev=net1,mac=52:55:55:79:c2:11 -device virtio-rng-pci -display none -device virtio-vga -device virtio-keyboard-pci -device virtio-mouse-pci -parallel none -chardev socket,id=char-serial,path=/Users/bapt/.lima/docker/serial.sock,server=on,wait=off,logfile=/Users/bapt/.lima/docker/serial.log -serial chardev:char-serial -chardev socket,id=char-qmp,path=/Users/bapt/.lima/docker/qmp.sock,server=on,wait=off -qmp chardev:char-qmp -name lima-docker -pidfile /Users/bapt/.lima/docker/qemu.pid]","time":"2022-01-24T12:19:54+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 1 of 5: \"ssh\"","time":"2022-01-24T12:19:54+01:00"}
{"level":"debug","msg":"executing script \"ssh\"","time":"2022-01-24T12:19:54+01:00"}
{"level":"debug","msg":"executing ssh for script \"ssh\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:19:54+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"mux_client_request_session: read from master failed: Broken pipe\\r\\nFailed to connect to new control master\\r\\n\", err=failed to execute script \"ssh\": stdout=\"\", stderr=\"mux_client_request_session: read from master failed: Broken pipe\\r\\nFailed to connect to new control master\\r\\n\": exit status 255","time":"2022-01-24T12:20:13+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 1 of 5: \"ssh\"","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"executing script \"ssh\"","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"executing ssh for script \"ssh\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"\", err=\u003cnil\u003e","time":"2022-01-24T12:20:23+01:00"}
{"level":"info","msg":"The essential requirement 1 of 5 is satisfied","time":"2022-01-24T12:20:23+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 2 of 5: \"user session is ready for ssh\"","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"executing script \"user session is ready for ssh\"","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"executing ssh for script \"user session is ready for ssh\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until sudo diff -q /run/lima-ssh-ready /mnt/lima-cidata/meta-data 2\u003e/dev/null; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T12:20:23+01:00"}
{"level":"info","msg":"The essential requirement 2 of 5 is satisfied","time":"2022-01-24T12:20:23+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 3 of 5: \"sshfs binary to be installed\"","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"executing script \"sshfs binary to be installed\"","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"executing ssh for script \"sshfs binary to be installed\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:20:23+01:00"}
{"level":"debug","msg":"stdout=\"/usr/bin/sshfs\\n\", stderr=\"+ timeout 30s bash -c 'until command -v sshfs; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"The essential requirement 3 of 5 is satisfied","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 4 of 5: \"/etc/fuse.conf to contain \\\"user_allow_other\\\"\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing script \"/etc/fuse.conf to contain \\\"user_allow_other\\\"\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for script \"/etc/fuse.conf to contain \\\"user_allow_other\\\"\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until grep -q ^user_allow_other /etc/fuse.conf; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"The essential requirement 4 of 5 is satisfied","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Waiting for the essential requirement 5 of 5: \"the guest agent to be running\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing script \"the guest agent to be running\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for script \"the guest agent to be running\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ sock=/run/lima-guestagent.sock\\n+ timeout 30s bash -c 'until [ -S \\\"/run/lima-guestagent.sock\\\" ]; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"The essential requirement 5 of 5 is satisfied","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Mounting \"/Users/bapt\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for preparing sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- mkdir -p /Users/bapt]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for remote sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- sshfs :/Users/bapt /Users/bapt -o slave -o ro -o allow_other]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"starting sftp server for /Users/bapt","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"generated script \"wait-for-remote-ready\" with map map[Dir:/Users/bapt MaxTrial:30]: \"#!/bin/sh\\nset -eu\\ndir=\\\"/Users/bapt\\\"\\nmax_trial=\\\"30\\\"\\nLANG=C\\nLC_ALL=C\\nexport LANG LC_ALL\\ni=0\\nwhile : ; do\\n  # FIXME: not really robust\\n  if mount | grep \\\"on ${dir}\\\" | egrep -qw \\\"fuse.sshfs|osxfuse\\\"; then\\n    echo '{\\\"return\\\":{}}'\\n    exit 0\\n  fi\\n  sleep 1\\n  if [ $i -ge ${max_trial} ]; then\\n    echo \u003e\u00262 \\\"sshfs does not seem to be mounted on ${dir}\\\"\\n    exit 1\\n  fi\\n  i=$((i + 1))\\ndone\\n\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for script \"wait-for-remote-ready\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/sh]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executed script \"wait-for-remote-ready\", stdout=\"{\\\"return\\\":{}}\\n\", stderr=\"\", err=\u003cnil\u003e","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Mounting \"/tmp/lima\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for preparing sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- mkdir -p /tmp/lima]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for remote sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- sshfs :/tmp/lima /tmp/lima -o slave -o allow_other]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"starting sftp server for /tmp/lima","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"generated script \"wait-for-remote-ready\" with map map[Dir:/tmp/lima MaxTrial:30]: \"#!/bin/sh\\nset -eu\\ndir=\\\"/tmp/lima\\\"\\nmax_trial=\\\"30\\\"\\nLANG=C\\nLC_ALL=C\\nexport LANG LC_ALL\\ni=0\\nwhile : ; do\\n  # FIXME: not really robust\\n  if mount | grep \\\"on ${dir}\\\" | egrep -qw \\\"fuse.sshfs|osxfuse\\\"; then\\n    echo '{\\\"return\\\":{}}'\\n    exit 0\\n  fi\\n  sleep 1\\n  if [ $i -ge ${max_trial} ]; then\\n    echo \u003e\u00262 \\\"sshfs does not seem to be mounted on ${dir}\\\"\\n    exit 1\\n  fi\\n  i=$((i + 1))\\ndone\\n\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for script \"wait-for-remote-ready\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/sh]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executed script \"wait-for-remote-ready\", stdout=\"{\\\"return\\\":{}}\\n\", stderr=\"\", err=\u003cnil\u003e","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Mounting \"/opt/lima\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for preparing sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- mkdir -p /opt/lima]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for remote sshfs: /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- sshfs :/opt/lima /opt/lima -o slave -o allow_other]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"starting sftp server for /opt/lima","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"generated script \"wait-for-remote-ready\" with map map[Dir:/opt/lima MaxTrial:30]: \"#!/bin/sh\\nset -eu\\ndir=\\\"/opt/lima\\\"\\nmax_trial=\\\"30\\\"\\nLANG=C\\nLC_ALL=C\\nexport LANG LC_ALL\\ni=0\\nwhile : ; do\\n  # FIXME: not really robust\\n  if mount | grep \\\"on ${dir}\\\" | egrep -qw \\\"fuse.sshfs|osxfuse\\\"; then\\n    echo '{\\\"return\\\":{}}'\\n    exit 0\\n  fi\\n  sleep 1\\n  if [ $i -ge ${max_trial} ]; then\\n    echo \u003e\u00262 \\\"sshfs does not seem to be mounted on ${dir}\\\"\\n    exit 1\\n  fi\\n  i=$((i + 1))\\ndone\\n\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for script \"wait-for-remote-ready\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/sh]","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executed script \"wait-for-remote-ready\", stdout=\"{\\\"return\\\":{}}\\n\", stderr=\"\", err=\u003cnil\u003e","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Waiting for the optional requirement 1 of 1: \"user probe 1/1\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"Forwarding unix sockets","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing script \"user probe 1/1\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Forwarding \"/run/docker.sock\" (guest) to \"/Users/bapt/docker.sock\" (host)","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for script \"user probe 1/1\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Forwarding \"/run/lima-guestagent.sock\" (guest) to \"/Users/bapt/.lima/docker/ga.sock\" (host)","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until command -v docker \u003e/dev/null 2\u003e\u00261; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"The optional requirement 1 of 1 is satisfied","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"guest agent info: \u0026{LocalPorts:[{IP:127.0.0.53 Port:53} {IP:0.0.0.0 Port:22} {IP::: Port:22}]}","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Waiting for the final requirement 1 of 1: \"boot scripts must have finished\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing script \"boot scripts must have finished\"","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"guest agent event: {Time:2022-01-24 11:20:25.217939937 +0000 UTC LocalPortsAdded:[{IP:127.0.0.53 Port:53} {IP:0.0.0.0 Port:22} {IP::: Port:22}] LocalPortsRemoved:[] Errors:[]}","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Not forwarding TCP 127.0.0.53:53","time":"2022-01-24T12:20:24+01:00"}
{"level":"debug","msg":"executing ssh for script \"boot scripts must have finished\": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile=\"/Users/bapt/.lima/_config/user\" -o IdentityFile=\"/Users/bapt/.ssh/id_rsa\" -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=bapt -o ControlMaster=auto -o ControlPath=\"/Users/bapt/.lima/docker/ssh.sock\" -o ControlPersist=5m -p 60006 127.0.0.1 -- /bin/bash]","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Not forwarding TCP 0.0.0.0:22","time":"2022-01-24T12:20:24+01:00"}
{"level":"info","msg":"Not forwarding TCP [::]:22","time":"2022-01-24T12:20:25+01:00"}
{"level":"debug","msg":"stdout=\"\", stderr=\"+ timeout 30s bash -c 'until sudo diff -q /run/lima-boot-done /mnt/lima-cidata/meta-data 2\u003e/dev/null; do sleep 3; done'\\n\", err=\u003cnil\u003e","time":"2022-01-24T12:20:43+01:00"}
{"level":"info","msg":"The final requirement 1 of 1 is satisfied","time":"2022-01-24T12:20:43+01:00"}

@XanderXAJ
Copy link

I can reproduce this issue with a Docker VM from the Lima Docker example when one of my containers has a bind mount to the host file system and automatically restarts when the daemon restarts (e.g. restart: always).

INFO[0032] [hostagent] fuse: mountpoint is not empty
INFO[0032] [hostagent] fuse: if you are sure this is safe, use the 'nonempty' mount option

What appears to be happening in my case is that the Docker daemon -- with containers that automatically restart -- is starting before the SSHFS mount has occurred. When Docker is asked to bind mount to a directory that doesn't exist, it automatically creates it. This now means that the mount directory is no longer empty, resulting in the error above.

The easy workaround is to use the nonempty option as recommended in the error, but this could potentially have side-effects as Docker containers starting with the daemon may not be able to find the files they require for a brief period, causing unexpected behaviour of those containers. But it might be good enough temporarily.

A more complete fix would be to ensure that Docker starts after the SSHFS mount has occurred. This might be possible with systemd targets (Rootful docker.service waits for containerd.service which in turn waits for local-fs.target), but it doesn't look like the SSHFS mount ties in to this (I'm actually not sure when or how the SSHFS mount occurs exactly). Rootless Docker as provided in Lima's example docker.yaml would need a similar solution.

@ngetahun-aclu
Copy link

@XanderXAJ 's explanation was the case for us too, our quick but not perfect fix was to be explicit in our docker-compose mounts that it's a bind mount (which won't create the underlying directories) docker/compose#2781 (comment) . It's not perfect solution since it doesn't seem to consistently restart successfully on a failed mount, but for a dev environment it was a working solution.

@ngetahun-aclu ngetahun-aclu mentioned this issue Feb 14, 2022
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
component/sshfs
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@XanderXAJ @AkihiroSuda @bcollard @ngetahun-aclu