virtualbox: Image pull failing with TLS handshake timeout error

[mauricioklein]

Is this a BUG REPORT or FEATURE REQUEST? BUG REPORT

Environment:

Minikube version: 0.34.0

• OS: MacOS Mojave 10.14.3
• VM Driver: virtualbox
• ISO version: minikube-v0.33.1.iso

What happened:
Minikube is failing to download Docker images frequently. The error is always the same: "TLS handshake timeout" (see image attached). It happens in both minikube start and when rolling out a deployment using kubectl apply -f.

Accessing Minikube terminal (minikube ssh) and trying to reach a random webpage (e.g. curl google.com), it never returns, which indicates that maybe the VM lost connection with the internet, but everything works on the physical machine.

Apparently, the only way to solve the problem and bring Minikube back is:

1. Delete ~/.kube and ~/.minikube
2. Delete the VM instance
3. Restart the physical machine

VM memory was increased from 2GB to 4GB, but problem persists.

What you expected to happen:
Docker images are downloaded normally during both Minikube startup and rollouts

How to reproduce it:
This is an intermittent error, so no deterministic way to reproduce. However, it normally happens on Minikube startup (minikube start) and deployment rollouts (kubectl apply -f .).

Output of minikube logs (if applicable):

==> k8s_coredns_coredns <==
E0216 18:09:07.963492    4313 logs.go:120] failed: Process exited with status 127
==> k8s_kube-apiserver <==
E0216 18:09:07.966602    4313 logs.go:120] failed: Process exited with status 127
==> k8s_kube-scheduler <==
E0216 18:09:07.969083    4313 logs.go:120] failed: Process exited with status 127
==> kubelet <==
-- Logs begin at Sat 2019-02-16 16:55:05 UTC, end at Sat 2019-02-16 17:09:07 UTC. --
Feb 16 17:09:04 minikube kubelet[2738]: E0216 17:09:04.724578    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:04 minikube kubelet[2738]: E0216 17:09:04.771852    2738 remote_image.go:112] PullImage "k8s.gcr.io/etcd:3.2.24" from image service failed: rpc error: code = Unknown desc = Error response from daemon: Get https://k8s.gcr.io/v2/: net/http: TLS handshake timeout
Feb 16 17:09:04 minikube kubelet[2738]: E0216 17:09:04.771878    2738 kuberuntime_image.go:51] Pull image "k8s.gcr.io/etcd:3.2.24" failed: rpc error: code = Unknown desc = Error response from daemon: Get https://k8s.gcr.io/v2/: net/http: TLS handshake timeout
Feb 16 17:09:04 minikube kubelet[2738]: E0216 17:09:04.771979    2738 kuberuntime_manager.go:749] container start failed: ErrImagePull: rpc error: code = Unknown desc = Error response from daemon: Get https://k8s.gcr.io/v2/: net/http: TLS handshake timeout
Feb 16 17:09:04 minikube kubelet[2738]: E0216 17:09:04.772004    2738 pod_workers.go:190] Error syncing pod 6c9e966765fc9ff47fd82a0a2ab3e4a7 ("etcd-minikube_kube-system(6c9e966765fc9ff47fd82a0a2ab3e4a7)"), skipping: failed to "StartContainer" for "etcd" with ErrImagePull: "rpc error: code = Unknown desc = Error response from daemon: Get https://k8s.gcr.io/v2/: net/http: TLS handshake timeout"
Feb 16 17:09:04 minikube kubelet[2738]: E0216 17:09:04.824770    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:04 minikube kubelet[2738]: E0216 17:09:04.925195    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.025887    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.131631    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.174258    2738 event.go:212] Unable to write event: 'Patch https://localhost:8443/api/v1/namespaces/default/events/minikube.1583e680acbb30c0: dial tcp 127.0.0.1:8443: connect: connection refused' (may retry after sleeping)
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.232958    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.333901    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.434085    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.534605    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.567033    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/kubelet.go:453: Failed to list *v1.Node: Get https://localhost:8443/api/v1/nodes?fieldSelector=metadata.name%!D(MISSING)minikube&limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.567832    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/config/apiserver.go:47: Failed to list *v1.Pod: Get https://localhost:8443/api/v1/pods?fieldSelector=spec.nodeName%!D(MISSING)minikube&limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.568330    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/kubelet.go:444: Failed to list *v1.Service: Get https://localhost:8443/api/v1/services?limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.635101    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.735639    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.836276    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:05 minikube kubelet[2738]: E0216 17:09:05.936596    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.037999    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.141480    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.245385    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.346547    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.450466    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.553233    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.570197    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/kubelet.go:444: Failed to list *v1.Service: Get https://localhost:8443/api/v1/services?limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.570585    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/kubelet.go:453: Failed to list *v1.Node: Get https://localhost:8443/api/v1/nodes?fieldSelector=metadata.name%!D(MISSING)minikube&limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.570867    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/config/apiserver.go:47: Failed to list *v1.Pod: Get https://localhost:8443/api/v1/pods?fieldSelector=spec.nodeName%!D(MISSING)minikube&limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.654686    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.759608    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.864314    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:06 minikube kubelet[2738]: E0216 17:09:06.968176    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: I0216 17:09:07.015567    2738 kubelet_node_status.go:278] Setting node annotation to enable volume controller attach/detach
Feb 16 17:09:07 minikube kubelet[2738]: W0216 17:09:07.018515    2738 status_manager.go:485] Failed to get status for pod "kube-addon-manager-minikube_kube-system(5c72fb06dcdda608211b70d63c0ca488)": Get https://localhost:8443/api/v1/namespaces/kube-system/pods/kube-addon-manager-minikube: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.018956    2738 pod_workers.go:190] Error syncing pod 5c72fb06dcdda608211b70d63c0ca488 ("kube-addon-manager-minikube_kube-system(5c72fb06dcdda608211b70d63c0ca488)"), skipping: failed to "StartContainer" for "kube-addon-manager" with ImagePullBackOff: "Back-off pulling image \"k8s.gcr.io/kube-addon-manager:v8.6\""
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.069104    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.176728    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.251130    2738 eviction_manager.go:243] eviction manager: failed to get summary stats: failed to get node info: node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.278521    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.381551    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.481828    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.576574    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/kubelet.go:444: Failed to list *v1.Service: Get https://localhost:8443/api/v1/services?limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.576658    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/config/apiserver.go:47: Failed to list *v1.Pod: Get https://localhost:8443/api/v1/pods?fieldSelector=spec.nodeName%!D(MISSING)minikube&limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.576757    2738 reflector.go:134] k8s.io/kubernetes/pkg/kubelet/kubelet.go:453: Failed to list *v1.Node: Get https://localhost:8443/api/v1/nodes?fieldSelector=metadata.name%!D(MISSING)minikube&limit=500&resourceVersion=0: dial tcp 127.0.0.1:8443: connect: connection refused
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.582505    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.684895    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.785218    2738 kubelet.go:2266] node "minikube" not found
Feb 16 17:09:07 minikube kubelet[2738]: E0216 17:09:07.885627    2738 kubelet.go:2266] node "minikube" not found
💣  Error getting machine logs: unable to fetch logs for: k8s_coredns_coredns, k8s_kube-apiserver, k8s_kube-scheduler

😿  Sorry that minikube crashed. If this was unexpected, we would love to hear from you:
👉  https://github.com/kubernetes/minikube/issues/new

Anything else do we need to know:

Follow a screenshot of the error (TLS handshake timeout) during a Minukube startup:

[tstromberg]

Is it possible that you have a proxy, vpn, or firewall that might be interfering with access?

Since you mention that it's intermittent, it could just be a bad internet connection that kubeadm isn't able to deal with for some reason. Curious.

[mauricioklein]

Thanks for your reply @tstromberg!

No VPN or Proxy in the network, just a regular NAT connection from VirtualBox to access the network of my localhost.

Also, when I say intermitent, it means that happens at random time, but once it happens, just a machine restart solves the problem, while docker pull for the exact same image on my localhost works fine. So, for me, seems like more a problem on Minikube or the VM, because the network on localhost still works fine.

Thanks!

[mauricioklein]

• Tried to downgrade to Minikube v0.33.0: same error
• Tries to increase VM memory from 2GB to 8GB: same error

And now I simply cannot start Minikube at all, since the TLS handshake timeout error happens every single time.

[tstromberg]

I'll have to think about this a bit, but two possible workarounds:

• using --cache-images might help as a workaround, as it tries to fetch images from outside the VM
• using the hyperkit driver might help

Overall this feels like Virtualbox just can't get out to the internet in a stable fashion, so there probably isn't any minikube options that are going to help here. What version of virtualbox are you running?

[mauricioklein]

Thanks, @tstromberg !

For now, I've migrated from Minikube to Kubernates support on DockerDesktop, which uses Hyperkit underneath (which, btw, is working well), but I'll also give a try on --cache-images, because for me as well it's clearly a problem with VirtualBox.

Thanks!

[mrowebot]

Same issue here on OS X:

Environment:
Minikube version: 0.34.0
OS: MacOS High Sierra 10.13.6
VM Driver: virtualbox
ISO version: minikube-v0.34.1.iso

Logs are pretty much the same as @mauricioklein.

Also, docker pull k8s.gcr.io/kube-apiserver-amd64:v1.13.3 runs fine to pull most recent image via docker on local machine.

Issue is when trying to pull images from minikube:

Unable to pull images, which may be OK: running cmd: sudo kubeadm config images pull --config /var/lib/kubeadm.yaml: command failed: sudo kubeadm config images pull --config /var/lib/kubeadm.yaml
stdout:
stderr: failed to pull image "k8s.gcr.io/kube-apiserver:v1.13.3": output: Error response from daemon: Get https://k8s.gcr.io/v2/: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
, error: exit status 1
: Process exited with status 1

I am running this while in work office, behind a proxy so will run again when home to test on different connection.

[tstromberg]

@mrowebot - For what it's worth, your issue does seem different, and likely indicates that the proxy isn't configured inside of the VM: https://github.com/kubernetes/minikube/blob/master/docs/http_proxy.md

[mrowebot]

Fixed by running the following:

minikube start  \                                                                
--docker-env=http_proxy={HTTP_PROXY_URL}:80 \
--docker-env=https_proxy={HTTPS_PROXY_URL}:80 \
--docker-env=no_proxy={minikube_ip}

The issue seems to have been that even though I had env vars set for HTTP_PROXY and HTTPS_PROXY these were not being passed through. HTH people :)