Skip to content

SSH times out during VM start/provisioning (docker-rootful, user probe 1/1) #4517

@torarnv

Description

@torarnv

Description

I can reproduce this fairly consistently, but not all the time. Symptoms are:

  • Waiting for the essential requirement 2 of 3 and Waiting for the essential requirement 3 of 3: takes a long time
  • Waiting for the optional requirement 1 of 1: "user probe 1/1" takes a long time

See https://asciinema.org/a/cbVrF787KpHFq0Nx for full log.

With --log-level debug I'm seeing

INFO[0013] [hostagent] The essential requirement 1 of 3 is satisfied
INFO[0013] [hostagent] Waiting for the essential requirement 2 of 3: "user session is ready for ssh"
DEBU[0013] [hostagent] executing script "user session is ready for ssh"
DEBU[0013] [hostagent] executing ssh for script "user session is ready for ssh": /usr/bin/ssh [ssh -o ControlMaster=no -o ControlPath=none -o ControlPersist=no -F /dev/null -o IdentityFile="/Users/torarne/.lima/_config/user" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o GSSAPIAuthentication=no -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=torarne -p 52635 127.0.0.1 -- /bin/bash -c "$(printf 'param_env="$(sudo cat /mnt/lima-cidata/param.env)"; while read -r line; do [ -n "$line" ] && export "$line"; done<<EOF\n${param_env}\nEOF\n/bin/bash')"]
DEBU[0133] [hostagent] Stopping udp proxy (read udp 185.125.190.57:123: i/o timeout)
DEBU[0134] [hostagent] stdout="", stderr="+ timeout 30s bash -c 'until sudo diff -q /run/lima-ssh-ready /mnt/lima-cidata/meta-data 2>/dev/null; do sleep 3; done'\n", err=<nil>
INFO[0134] [hostagent] The essential requirement 2 of 3 is satisfied
INFO[0134] [hostagent] Waiting for the essential requirement 3 of 3: "Explicitly start ssh ControlMaster"
DEBU[0134] [hostagent] executing script "Explicitly start ssh ControlMaster"
DEBU[0134] [hostagent] executing ssh for script "Explicitly start ssh ControlMaster": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/torarne/.lima/_config/user" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o GSSAPIAuthentication=no -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=torarne -o ControlMaster=auto -o ControlPath="/Users/torarne/.lima/test/ssh.sock" -o ControlPersist=yes -p 52635 127.0.0.1 -- /bin/bash -c "$(printf 'param_env="$(sudo cat /mnt/lima-cidata/param.env)"; while read -r line; do [ -n "$line" ] && export "$line"; done<<EOF\n${param_env}\nEOF\n/bin/bash')"]
DEBU[0198] [hostagent] Stopping udp proxy (read udp 185.125.190.57:123: i/o timeout)
DEBU[0254] [hostagent] stdout="", stderr="", err=<nil>
INFO[0254] [hostagent] The essential requirement 3 of 3 is satisfied

and

INFO[0415] [hostagent] Waiting for the optional requirement 1 of 1: "user probe 1/1"
DEBU[0415] [hostagent] executing script "user probe 1/1"
DEBU[0415] [hostagent] executing ssh for script "user probe 1/1": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/torarne/.lima/_config/user" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o GSSAPIAuthentication=no -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=torarne -o ControlMaster=auto -o ControlPath="/Users/torarne/.lima/test/ssh.sock" -o ControlPersist=yes -p 52635 127.0.0.1 -- /bin/bash -c "$(printf 'param_env="$(sudo cat /mnt/lima-cidata/param.env)"; while read -r line; do [ -n "$line" ] && export "$line"; done<<EOF\n${param_env}\nEOF\n/bin/bash')"]
DEBU[0445] [hostagent] stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n", err=failed to execute script "user probe 1/1": stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n": exit status 1
INFO[0455] [hostagent] Waiting for the optional requirement 1 of 1: "user probe 1/1"
DEBU[0455] [hostagent] executing script "user probe 1/1"
DEBU[0455] [hostagent] executing ssh for script "user probe 1/1": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/torarne/.lima/_config/user" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o GSSAPIAuthentication=no -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=torarne -o ControlMaster=auto -o ControlPath="/Users/torarne/.lima/test/ssh.sock" -o ControlPersist=yes -p 52635 127.0.0.1 -- /bin/bash -c "$(printf 'param_env="$(sudo cat /mnt/lima-cidata/param.env)"; while read -r line; do [ -n "$line" ] && export "$line"; done<<EOF\n${param_env}\nEOF\n/bin/bash')"]
DEBU[0485] [hostagent] stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n", err=failed to execute script "user probe 1/1": stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n": exit status 1
DEBU[0492] [hostagent] guest agent event: time:{seconds:1768062735 nanos:515217875} added_local_ports:{protocol:"udp" ip:"0.0.0.0" port:40687}
INFO[0492] [hostagent] Forwarding UDP from 0.0.0.0:40687 to 127.0.0.1:40687
DEBU[0494] [hostagent] guest agent event: time:{seconds:1768062737 nanos:238450977} removed_local_ports:{protocol:"udp" ip:"0.0.0.0" port:40687}
DEBU[0494] [hostagent] removing listener for hostAddress: 127.0.0.1:40687, guestAddress: 0.0.0.0:40687
DEBU[0494] [hostagent] udp proxy for guestAddr: 0.0.0.0:40687 closed
DEBU[0494] [hostagent] removing listener for hostAddress: 127.0.0.1:40687, guestAddress: 0.0.0.0:40687
DEBU[0494] [hostagent] Port forwarding closed proto:udp host:127.0.0.1:40687 guest:0.0.0.0:40687
INFO[0495] [hostagent] Waiting for the optional requirement 1 of 1: "user probe 1/1"
DEBU[0495] [hostagent] executing script "user probe 1/1"
DEBU[0495] [hostagent] executing ssh for script "user probe 1/1": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/torarne/.lima/_config/user" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o GSSAPIAuthentication=no -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=torarne -o ControlMaster=auto -o ControlPath="/Users/torarne/.lima/test/ssh.sock" -o ControlPersist=yes -p 52635 127.0.0.1 -- /bin/bash -c "$(printf 'param_env="$(sudo cat /mnt/lima-cidata/param.env)"; while read -r line; do [ -n "$line" ] && export "$line"; done<<EOF\n${param_env}\nEOF\n/bin/bash')"]
DEBU[0525] [hostagent] stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n", err=failed to execute script "user probe 1/1": stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n": exit status 1
INFO[0535] [hostagent] Waiting for the optional requirement 1 of 1: "user probe 1/1"
DEBU[0535] [hostagent] executing script "user probe 1/1"
DEBU[0535] [hostagent] executing ssh for script "user probe 1/1": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/torarne/.lima/_config/user" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o GSSAPIAuthentication=no -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=torarne -o ControlMaster=auto -o ControlPath="/Users/torarne/.lima/test/ssh.sock" -o ControlPersist=yes -p 52635 127.0.0.1 -- /bin/bash -c "$(printf 'param_env="$(sudo cat /mnt/lima-cidata/param.env)"; while read -r line; do [ -n "$line" ] && export "$line"; done<<EOF\n${param_env}\nEOF\n/bin/bash')"]
DEBU[0565] [hostagent] stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n", err=failed to execute script "user probe 1/1": stdout="", stderr="+ timeout 30s bash -c 'until command -v docker >/dev/null 2>&1; do sleep 3; done'\n+ echo 'docker is not installed yet'\ndocker is not installed yet\n+ exit 1\n": exit status 1
INFO[0575] [hostagent] Waiting for the optional requirement 1 of 1: "user probe 1/1"
DEBU[0575] [hostagent] executing script "user probe 1/1"
DEBU[0575] [hostagent] executing ssh for script "user probe 1/1": /usr/bin/ssh [ssh -F /dev/null -o IdentityFile="/Users/torarne/.lima/_config/user" -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o NoHostAuthenticationForLocalhost=yes -o PreferredAuthentications=publickey -o Compression=no -o BatchMode=yes -o IdentitiesOnly=yes -o GSSAPIAuthentication=no -o Ciphers="^aes128-gcm@openssh.com,aes256-gcm@openssh.com" -o User=torarne -o ControlMaster=auto -o ControlPath="/Users/torarne/.lima/test/ssh.sock" -o ControlPersist=yes -p 52635 127.0.0.1 -- /bin/bash -c "$(printf 'param_env="$(sudo cat /mnt/lima-cidata/param.env)"; while read -r line; do [ -n "$line" ] && export "$line"; done<<EOF\n${param_env}\nEOF\n/bin/bash')"]
DEBU[0582] [hostagent] Stopping udp proxy (read udp 185.125.190.57:123: i/o timeout)
FATA[0603] did not receive an event with the "running" status

Lima 2.0.3 with template:docker-rootful and no override.yaml

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions