'profile list' spends ~1m15s waiting per profile/cluster when they are not running

[jlucktay]

Steps to reproduce the issue:

1. minikube --driver=hyperkit --profile=demo1 start
2. minikube --driver=hyperkit --profile=demo2 start
3. minikube --profile=demo1 stop
4. minikube --profile=demo2 stop
5. minikube profile list

This fifth command list will take about ~2m30s as it tries to dial into each cluster and times out on each in sequence.

Full output of failed command:

$ make && time ./out/minikube profile list --add_dir_header --logtostderr --stderrthreshold=0 --v=1
make: 'out/minikube' is up to date.
I1025 16:29:00.739045   23404 oci/cli_runner.go:110] Run: docker ps -a --filter label=name.minikube.sigs.k8s.io --format {{.Names}}
I1025 16:29:01.079660   23404 machine/host.go:66] Checking if "demo1" exists ...
I1025 16:29:01.080638   23404 minikube/main.go:119] libmachine: Found binary path at /Users/jameslucktaylor/.minikube/bin/docker-machine-driver-hyperkit
I1025 16:29:01.081063   23404 minikube/main.go:119] libmachine: Launching plugin server for driver hyperkit
I1025 16:29:01.092708   23404 minikube/main.go:119] libmachine: Plugin server listening at address 127.0.0.1:54956
I1025 16:29:01.093871   23404 minikube/main.go:119] libmachine: () Calling .GetVersion
I1025 16:29:01.096087   23404 minikube/main.go:119] libmachine: Using API Version  1
I1025 16:29:01.096104   23404 minikube/main.go:119] libmachine: () Calling .SetConfigRaw
I1025 16:29:01.096385   23404 minikube/main.go:119] libmachine: () Calling .GetMachineName
I1025 16:29:01.096536   23404 minikube/main.go:119] libmachine: (demo1) Calling .DriverName
I1025 16:29:01.097228   23404 kverify/api_server.go:146] Checking apiserver status ...
I1025 16:29:01.097381   23404 command/ssh_runner.go:148] Run: sudo pgrep -xnf kube-apiserver.*minikube.*
I1025 16:29:01.097403   23404 minikube/main.go:119] libmachine: (demo1) Calling .GetSSHHostname
I1025 16:29:01.097571   23404 minikube/main.go:119] libmachine: (demo1) Calling .GetSSHPort
I1025 16:29:01.097741   23404 minikube/main.go:119] libmachine: (demo1) Calling .GetSSHKeyPath
I1025 16:29:01.097869   23404 minikube/main.go:119] libmachine: (demo1) Calling .GetSSHUsername
I1025 16:29:01.098010   23404 sshutil/sshutil.go:45] new ssh client: &{IP:192.168.64.49 Port:22 SSHKeyPath:/Users/jameslucktaylor/.minikube/machines/demo1/id_rsa Username:docker}
W1025 16:30:16.192761   23404 sshutil/sshutil.go:56] dial failure (will retry): dial tcp 192.168.64.49:22: connect: operation timed out
W1025 16:30:16.193967   23404 kverify/api_server.go:150] stopped: unable to get apiserver pid: NewSession: new client: new client: dial tcp 192.168.64.49:22: connect: operation timed out
I1025 16:30:16.194009   23404 machine/host.go:66] Checking if "demo2" exists ...
I1025 16:30:16.194454   23404 minikube/main.go:119] libmachine: Found binary path at /Users/jameslucktaylor/.minikube/bin/docker-machine-driver-hyperkit
I1025 16:30:16.194498   23404 minikube/main.go:119] libmachine: Launching plugin server for driver hyperkit
I1025 16:30:16.206024   23404 minikube/main.go:119] libmachine: Plugin server listening at address 127.0.0.1:54963
I1025 16:30:16.206503   23404 minikube/main.go:119] libmachine: () Calling .GetVersion
I1025 16:30:16.206996   23404 minikube/main.go:119] libmachine: Using API Version  1
I1025 16:30:16.207013   23404 minikube/main.go:119] libmachine: () Calling .SetConfigRaw
I1025 16:30:16.207355   23404 minikube/main.go:119] libmachine: () Calling .GetMachineName
I1025 16:30:16.207513   23404 minikube/main.go:119] libmachine: (demo2) Calling .DriverName
I1025 16:30:16.207632   23404 kverify/api_server.go:146] Checking apiserver status ...
I1025 16:30:16.207772   23404 command/ssh_runner.go:148] Run: sudo pgrep -xnf kube-apiserver.*minikube.*
I1025 16:30:16.207788   23404 minikube/main.go:119] libmachine: (demo2) Calling .GetSSHHostname
I1025 16:30:16.207907   23404 minikube/main.go:119] libmachine: (demo2) Calling .GetSSHPort
I1025 16:30:16.208021   23404 minikube/main.go:119] libmachine: (demo2) Calling .GetSSHKeyPath
I1025 16:30:16.208138   23404 minikube/main.go:119] libmachine: (demo2) Calling .GetSSHUsername
I1025 16:30:16.208253   23404 sshutil/sshutil.go:45] new ssh client: &{IP:192.168.64.50 Port:22 SSHKeyPath:/Users/jameslucktaylor/.minikube/machines/demo2/id_rsa Username:docker}
W1025 16:31:31.316773   23404 sshutil/sshutil.go:56] dial failure (will retry): dial tcp 192.168.64.50:22: connect: operation timed out
W1025 16:31:31.316890   23404 kverify/api_server.go:150] stopped: unable to get apiserver pid: NewSession: new client: new client: dial tcp 192.168.64.50:22: connect: operation timed out
I1025 16:31:31.316960   23404 minikube/main.go:119] libmachine: Making call to close driver server
I1025 16:31:31.316991   23404 minikube/main.go:119] libmachine: (demo1) Calling .Close
I1025 16:31:31.317365   23404 minikube/main.go:119] libmachine: (demo1) DBG | Closing plugin on server side
I1025 16:31:31.317394   23404 minikube/main.go:119] libmachine: Successfully made call to close driver server
I1025 16:31:31.317474   23404 minikube/main.go:119] libmachine: Making call to close connection to plugin binary
I1025 16:31:31.317512   23404 minikube/main.go:119] libmachine: Making call to close driver server
I1025 16:31:31.317529   23404 minikube/main.go:119] libmachine: (demo2) Calling .Close
I1025 16:31:31.317791   23404 minikube/main.go:119] libmachine: (demo2) DBG | Closing plugin on server side
I1025 16:31:31.317813   23404 minikube/main.go:119] libmachine: Successfully made call to close driver server
I1025 16:31:31.317839   23404 minikube/main.go:119] libmachine: Making call to close connection to plugin binary
|---------|-----------|---------|---------------|------|---------|---------|
| Profile | VM Driver | Runtime |      IP       | Port | Version | Status  |
|---------|-----------|---------|---------------|------|---------|---------|
| demo1   | hyperkit  | docker  | 192.168.64.49 | 8443 | v1.19.2 | Stopped |
| demo2   | hyperkit  | docker  | 192.168.64.50 | 8443 | v1.19.2 | Stopped |
|---------|-----------|---------|---------------|------|---------|---------|

real	2m30.747s
user	0m0.178s
sys	0m0.187s

Full output of minikube start command used, if not already included:

$ minikube --driver=hyperkit --profile=demo2 start
😄  [demo2] minikube v1.14.1 on Darwin 10.15.7
✨  Using the hyperkit driver based on user configuration
👍  Starting control plane node demo2 in cluster demo2
🔥  Creating hyperkit VM (CPUs=2, Memory=4000MB, Disk=20000MB) ...
🐳  Preparing Kubernetes v1.19.2 on Docker 19.03.12 ...
🔎  Verifying Kubernetes components...
🌟  Enabled addons: storage-provisioner, default-storageclass
🏄  Done! kubectl is now configured to use "demo2" by default

Optional: Full output of minikube logs command:
N/A

[medyagh]

yeah that could be side efffect of this PR that we had, that added Pause status to profile list

possible side effect of #8978

[medyagh]

confirm it happens when one of the profiles is is stopped
stuck at

1026 10:50:31.814685    7812 sshutil.go:45] new ssh client: &{IP:192.168.64.2 Port:22 SSHKeyPath:/Users/medya/.minikube/machines/p1/id_rsa Username:docker}

medya@~/workspace/minikube (master) $ time minikube profile list --alsologtostderr
I1026 10:50:31.573563    7812 cli_runner.go:110] Run: docker ps -a --filter label=name.minikube.sigs.k8s.io --format {{.Names}}
I1026 10:50:31.687635    7812 host.go:66] Checking if "minikube" exists ...
I1026 10:50:31.688123    7812 cli_runner.go:110] Run: docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" minikube
W1026 10:50:31.802235    7812 cli_runner.go:148] docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" minikube returned with exit code 1
W1026 10:50:31.802759    7812 profile_list.go:108] error loading profiles: get port 8443 for "minikube": docker container inspect -f "'{{(index (index .NetworkSettings.Ports "8443/tcp") 0).HostPort}}'" minikube: exit status 1
stdout:


stderr:
Template parsing error: template: :1:4: executing "" at <index (index .NetworkSettings.Ports "8443/tcp") 0>: error calling index: index of untyped nil
I1026 10:50:31.802777    7812 host.go:66] Checking if "p1" exists ...
I1026 10:50:31.803165    7812 main.go:119] libmachine: Found binary path at /Users/medya/.minikube/bin/docker-machine-driver-hyperkit
I1026 10:50:31.803223    7812 main.go:119] libmachine: Launching plugin server for driver hyperkit
I1026 10:50:31.812624    7812 main.go:119] libmachine: Plugin server listening at address 127.0.0.1:51742
I1026 10:50:31.813185    7812 main.go:119] libmachine: () Calling .GetVersion
I1026 10:50:31.813711    7812 main.go:119] libmachine: Using API Version  1
I1026 10:50:31.813728    7812 main.go:119] libmachine: () Calling .SetConfigRaw
I1026 10:50:31.813966    7812 main.go:119] libmachine: () Calling .GetMachineName
I1026 10:50:31.814088    7812 main.go:119] libmachine: (p1) Calling .DriverName
I1026 10:50:31.814194    7812 api_server.go:146] Checking apiserver status ...
I1026 10:50:31.814279    7812 ssh_runner.go:148] Run: sudo pgrep -xnf kube-apiserver.*minikube.*
I1026 10:50:31.814296    7812 main.go:119] libmachine: (p1) Calling .GetSSHHostname
I1026 10:50:31.814403    7812 main.go:119] libmachine: (p1) Calling .GetSSHPort
I1026 10:50:31.814491    7812 main.go:119] libmachine: (p1) Calling .GetSSHKeyPath
I1026 10:50:31.814589    7812 main.go:119] libmachine: (p1) Calling .GetSSHUsername
1026 10:50:31.814685    7812 sshutil.go:45] new ssh client: &{IP:192.168.64.2 Port:22 SSHKeyPath:/Users/medya/.minikube/machines/p1/id_rsa Username:docker}

[medyagh]

@kschaab @jlucktay
the binary in this PR should fix the problem
here is the binary if you like to try it before the next patch release
http://storage.googleapis.com/minikube-builds/9557/minikube-linux-amd64
http://storage.googleapis.com/minikube-builds/9557/minikube-darwin-amd64
http://storage.googleapis.com/minikube-builds/9557/minikube-windows-amd64.exe

[jlucktay]

Thank you! @sharifelgamal @medyagh 🚀