docker driver failing on glinux due to static IP bug

[priyawadhwa]

minikube is failing on the docker driver due to a static IP bug, which I haven't isolated yet. But, if I remove the static IP code, minikube works again, so I know it is related.

It fails with these logs:

I0825 11:22:16.065409 2478980 main.go:115] libmachine: About to run SSH command:
sudo hostname minikube && echo "minikube" | sudo tee /etc/hostname
I0825 11:22:19.129951 2478980 main.go:115] libmachine: Error dialing TCP: ssh: handshake failed: read tcp 127.0.0.1:57616->127.0.0.1:32915: read: connection reset by peer
I0825 11:22:22.201675 2478980 main.go:115] libmachine: Error dialing TCP: ssh: handshake failed: read tcp 127.0.0.1:57622->127.0.0.1:32915: read: connection reset by peer

To reproduce:
On gLinux, run:

minikube start --driver docker --alsologtostderr

The logs look like this:

$ minikube start --driver docker --alsologtostderr
I0825 11:22:06.401326 2478980 out.go:197] Setting JSON to false
I0825 11:22:06.428307 2478980 start.go:100] hostinfo: {"hostname":"priyawadhwa1.sfo.corp.google.com","uptime":584299,"bootTime":1597795427,"procs":436,"os":"linux","platform":"debian","platformFamily":"debian","platformVersion":"rodete","kernelVersion":"5.2.17-1rodete3-amd64","virtualizationSystem":"kvm","virtualizationRole":"host","hostid":"30fa276e-289b-11e8-9c43-bc0000760000"}
I0825 11:22:06.429198 2478980 start.go:110] virtualization: kvm host
I0825 11:22:06.434174 2478980 out.go:105] 😄  minikube v1.12.3 on Debian rodete
😄  minikube v1.12.3 on Debian rodete
I0825 11:22:06.434523 2478980 driver.go:287] Setting default libvirt URI to qemu:///system
I0825 11:22:06.516635 2478980 docker.go:87] docker version: linux-19.03.12
I0825 11:22:06.522996 2478980 out.go:105] ✨  Using the docker driver based on user configuration
✨  Using the docker driver based on user configuration
I0825 11:22:06.523035 2478980 start.go:232] selected driver: docker
I0825 11:22:06.523050 2478980 start.go:638] validating driver "docker" against <nil>
I0825 11:22:06.523083 2478980 start.go:649] status for docker: {Installed:true Healthy:true NeedsImprovement:false Error:<nil> Fix: Doc:}
I0825 11:22:06.523273 2478980 cli_runner.go:109] Run: docker system info --format "{{json .}}"
I0825 11:22:06.639299 2478980 start_flags.go:222] no existing cluster config was found, will generate one from the flags 
I0825 11:22:06.639362 2478980 start_flags.go:240] Using suggested 16100MB memory alloc based on sys=64405MB, container=64405MB
I0825 11:22:06.639607 2478980 start_flags.go:613] Wait components to verify : map[apiserver:true system_pods:true]
I0825 11:22:06.639652 2478980 cni.go:74] Creating CNI manager for ""
I0825 11:22:06.639670 2478980 cni.go:117] CNI unnecessary in this configuration, recommending no CNI
I0825 11:22:06.639686 2478980 start_flags.go:344] config:
{Name:minikube KeepContext:false EmbedCerts:false MinikubeISO: KicBaseImage:gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 Memory:16100 CPUs:2 DiskSize:20000 VMDriver: Driver:docker HyperkitVpnKitSock: HyperkitVSockPorts:[] DockerEnv:[] InsecureRegistry:[] RegistryMirror:[] HostOnlyCIDR:192.168.99.1/24 HypervVirtualSwitch: HypervUseExternalSwitch:false HypervExternalAdapter: KVMNetwork:default KVMQemuURI:qemu:///system KVMGPU:false KVMHidden:false DockerOpt:[] DisableDriverMounts:false NFSShare:[] NFSSharesRoot:/nfsshares UUID: NoVTXCheck:false DNSProxy:false HostDNSResolver:true HostOnlyNicType:virtio NatNicType:virtio KubernetesConfig:{KubernetesVersion:v1.18.3 ClusterName:minikube APIServerName:minikubeCA APIServerNames:[] APIServerIPs:[] DNSDomain:cluster.local ContainerRuntime:docker CRISocket: NetworkPlugin: FeatureGates: ServiceCIDR:10.96.0.0/12 ImageRepository: LoadBalancerStartIP: LoadBalancerEndIP: ExtraOptions:[] ShouldLoadCachedImages:true EnableDefaultCNI:false CNI: NodeIP: NodePort:8443 NodeName:} Nodes:[] Addons:map[] VerifyComponents:map[apiserver:true system_pods:true] StartHostTimeout:6m0s}
I0825 11:22:06.645743 2478980 out.go:105] 👍  Starting control plane node minikube in cluster minikube
👍  Starting control plane node minikube in cluster minikube
I0825 11:22:06.706591 2478980 image.go:92] Found gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 in local docker daemon, skipping pull
I0825 11:22:06.706647 2478980 cache.go:113] gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 exists in daemon, skipping pull
I0825 11:22:06.706677 2478980 preload.go:97] Checking if preload exists for k8s version v1.18.3 and runtime docker
I0825 11:22:06.706752 2478980 preload.go:105] Found local preload: /usr/local/google/home/priyawadhwa/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v5-v1.18.3-docker-overlay2-amd64.tar.lz4
I0825 11:22:06.706771 2478980 cache.go:51] Caching tarball of preloaded images
I0825 11:22:06.706803 2478980 preload.go:131] Found /usr/local/google/home/priyawadhwa/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v5-v1.18.3-docker-overlay2-amd64.tar.lz4 in cache, skipping download
I0825 11:22:06.706820 2478980 cache.go:54] Finished verifying existence of preloaded tar for  v1.18.3 on docker
I0825 11:22:06.707308 2478980 profile.go:150] Saving config to /usr/local/google/home/priyawadhwa/.minikube/profiles/minikube/config.json ...
I0825 11:22:06.707364 2478980 lock.go:35] WriteFile acquiring /usr/local/google/home/priyawadhwa/.minikube/profiles/minikube/config.json: {Name:mk00b8435a0b9eb5cd75291f05f9d1d6bf04c661 Clock:{} Delay:500ms Timeout:1m0s Cancel:<nil>}
I0825 11:22:06.707735 2478980 cache.go:181] Successfully downloaded all kic artifacts
I0825 11:22:06.707834 2478980 start.go:298] acquiring machines lock for minikube: {Name:mk30deb601a5a55c917408bc4d4dd3ff884142bc Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0825 11:22:06.707937 2478980 start.go:302] acquired machines lock for "minikube" in 74.939µs
I0825 11:22:06.707970 2478980 start.go:89] Provisioning new machine with config: &{Name:minikube KeepContext:false EmbedCerts:false MinikubeISO: KicBaseImage:gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 Memory:16100 CPUs:2 DiskSize:20000 VMDriver: Driver:docker HyperkitVpnKitSock: HyperkitVSockPorts:[] DockerEnv:[] InsecureRegistry:[] RegistryMirror:[] HostOnlyCIDR:192.168.99.1/24 HypervVirtualSwitch: HypervUseExternalSwitch:false HypervExternalAdapter: KVMNetwork:default KVMQemuURI:qemu:///system KVMGPU:false KVMHidden:false DockerOpt:[] DisableDriverMounts:false NFSShare:[] NFSSharesRoot:/nfsshares UUID: NoVTXCheck:false DNSProxy:false HostDNSResolver:true HostOnlyNicType:virtio NatNicType:virtio KubernetesConfig:{KubernetesVersion:v1.18.3 ClusterName:minikube APIServerName:minikubeCA APIServerNames:[] APIServerIPs:[] DNSDomain:cluster.local ContainerRuntime:docker CRISocket: NetworkPlugin: FeatureGates: ServiceCIDR:10.96.0.0/12 ImageRepository: LoadBalancerStartIP: LoadBalancerEndIP: ExtraOptions:[] ShouldLoadCachedImages:true EnableDefaultCNI:false CNI: NodeIP: NodePort:8443 NodeName:} Nodes:[{Name: IP: Port:8443 KubernetesVersion:v1.18.3 ControlPlane:true Worker:true}] Addons:map[] VerifyComponents:map[apiserver:true system_pods:true] StartHostTimeout:6m0s} &{Name: IP: Port:8443 KubernetesVersion:v1.18.3 ControlPlane:true Worker:true}
I0825 11:22:06.708055 2478980 start.go:126] createHost starting for "" (driver="docker")
I0825 11:22:06.712305 2478980 out.go:105] 🔥  Creating docker container (CPUs=2, Memory=16100MB) ...
🔥  Creating docker container (CPUs=2, Memory=16100MB) ...
I0825 11:22:06.712623 2478980 start.go:163] libmachine.API.Create for "minikube" (driver="docker")
I0825 11:22:06.712676 2478980 client.go:164] LocalClient.Create starting
I0825 11:22:06.712736 2478980 main.go:115] libmachine: Reading certificate data from /usr/local/google/home/priyawadhwa/.minikube/certs/ca.pem
I0825 11:22:06.712806 2478980 main.go:115] libmachine: Decoding PEM data...
I0825 11:22:06.712852 2478980 main.go:115] libmachine: Parsing certificate...
I0825 11:22:06.713093 2478980 main.go:115] libmachine: Reading certificate data from /usr/local/google/home/priyawadhwa/.minikube/certs/cert.pem
I0825 11:22:06.713147 2478980 main.go:115] libmachine: Decoding PEM data...
I0825 11:22:06.713179 2478980 main.go:115] libmachine: Parsing certificate...
I0825 11:22:06.713896 2478980 cli_runner.go:109] Run: docker network ls --format {{.Name}}
I0825 11:22:06.775507 2478980 cli_runner.go:109] Run: docker network create --driver=bridge --subnet=192.168.39.0/24 --gateway 192.168.39.1 minikube
I0825 11:22:06.904247 2478980 cli_runner.go:109] Run: docker ps -a --format {{.Names}}
I0825 11:22:06.956363 2478980 cli_runner.go:109] Run: docker volume create minikube --label name.minikube.sigs.k8s.io=minikube --label created_by.minikube.sigs.k8s.io=true
I0825 11:22:07.018855 2478980 oci.go:103] Successfully created a docker volume minikube
I0825 11:22:07.019011 2478980 cli_runner.go:109] Run: docker run --rm --entrypoint /usr/bin/test -v minikube:/var gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 -d /var/lib
I0825 11:22:08.037869 2478980 cli_runner.go:151] Completed: docker run --rm --entrypoint /usr/bin/test -v minikube:/var gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 -d /var/lib: (1.018808515s)
I0825 11:22:08.037893 2478980 oci.go:107] Successfully prepared a docker volume minikube
W0825 11:22:08.037929 2478980 oci.go:173] Your kernel does not support swap limit capabilities or the cgroup is not mounted.
I0825 11:22:08.038113 2478980 preload.go:97] Checking if preload exists for k8s version v1.18.3 and runtime docker
I0825 11:22:08.038149 2478980 preload.go:105] Found local preload: /usr/local/google/home/priyawadhwa/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v5-v1.18.3-docker-overlay2-amd64.tar.lz4
I0825 11:22:08.038154 2478980 kic.go:141] Starting extracting preloaded images to volume ...
I0825 11:22:08.038166 2478980 cli_runner.go:109] Run: docker info --format "'{{json .SecurityOptions}}'"
I0825 11:22:08.038208 2478980 cli_runner.go:109] Run: docker run --rm --entrypoint /usr/bin/tar -v /usr/local/google/home/priyawadhwa/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v5-v1.18.3-docker-overlay2-amd64.tar.lz4:/preloaded.tar:ro -v minikube:/extractDir gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 -I lz4 -xvf /preloaded.tar -C /extractDir
I0825 11:22:08.159190 2478980 cli_runner.go:109] Run: docker run -d -t --privileged --security-opt seccomp=unconfined --tmpfs /tmp --tmpfs /run -v /lib/modules:/lib/modules:ro --hostname minikube --name minikube --label created_by.minikube.sigs.k8s.io=true --label name.minikube.sigs.k8s.io=minikube --label role.minikube.sigs.k8s.io= --label mode.minikube.sigs.k8s.io=minikube --network minikube --ip 192.168.39.2 --volume minikube:/var --security-opt apparmor=unconfined --cpus=2 --memory=16100mb -e container=docker --expose 8443 --publish=127.0.0.1::8443 --publish=127.0.0.1::22 --publish=127.0.0.1::2376 --publish=127.0.0.1::5000 gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568
I0825 11:22:08.880291 2478980 cli_runner.go:109] Run: docker container inspect minikube --format={{.State.Running}}
I0825 11:22:08.925025 2478980 cli_runner.go:109] Run: docker container inspect minikube --format={{.State.Status}}
I0825 11:22:08.970996 2478980 cli_runner.go:109] Run: docker exec minikube stat /var/lib/dpkg/alternatives/iptables
I0825 11:22:09.100488 2478980 oci.go:230] the created container "minikube" has a running status.
I0825 11:22:09.100522 2478980 kic.go:165] Creating ssh key for kic: /usr/local/google/home/priyawadhwa/.minikube/machines/minikube/id_rsa...
I0825 11:22:09.201611 2478980 kic_runner.go:179] docker (temp): /usr/local/google/home/priyawadhwa/.minikube/machines/minikube/id_rsa.pub --> /home/docker/.ssh/authorized_keys (381 bytes)
I0825 11:22:09.336619 2478980 cli_runner.go:109] Run: docker container inspect minikube --format={{.State.Status}}
I0825 11:22:09.385136 2478980 kic_runner.go:93] Run: chown docker:docker /home/docker/.ssh/authorized_keys
I0825 11:22:09.385160 2478980 kic_runner.go:114] Args: [docker exec --privileged minikube chown docker:docker /home/docker/.ssh/authorized_keys]
I0825 11:22:15.935109 2478980 cli_runner.go:151] Completed: docker run --rm --entrypoint /usr/bin/tar -v /usr/local/google/home/priyawadhwa/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v5-v1.18.3-docker-overlay2-amd64.tar.lz4:/preloaded.tar:ro -v minikube:/extractDir gcr.io/k8s-minikube/kicbase:v0.0.12-snapshot@sha256:7be40a42fdfec56fbf7bc9de07ea2ed4a931cbb70dccb8612b2ba13763bf4568 -I lz4 -xvf /preloaded.tar -C /extractDir: (7.896845737s)
I0825 11:22:15.935151 2478980 kic.go:146] duration metric: took 7.896993 seconds to extract preloaded images to volume
I0825 11:22:15.935324 2478980 cli_runner.go:109] Run: docker container inspect minikube --format={{.State.Status}}
I0825 11:22:16.002738 2478980 machine.go:88] provisioning docker machine ...
I0825 11:22:16.002818 2478980 ubuntu.go:166] provisioning hostname "minikube"
I0825 11:22:16.002977 2478980 cli_runner.go:109] Run: docker container inspect -f "'{{(index (index .NetworkSettings.Ports "22/tcp") 0).HostPort}}'" minikube
I0825 11:22:16.065048 2478980 main.go:115] libmachine: Using SSH client type: native
I0825 11:22:16.065376 2478980 main.go:115] libmachine: &{{{<nil> 0 [] [] []} docker [0x92d3a0] 0x92d360 <nil>  [] 0s} 127.0.0.1 32915 <nil> <nil>}
I0825 11:22:16.065409 2478980 main.go:115] libmachine: About to run SSH command:
sudo hostname minikube && echo "minikube" | sudo tee /etc/hostname
I0825 11:22:19.129951 2478980 main.go:115] libmachine: Error dialing TCP: ssh: handshake failed: read tcp 127.0.0.1:57616->127.0.0.1:32915: read: connection reset by peer
I0825 11:22:22.201675 2478980 main.go:115] libmachine: Error dialing TCP: ssh: handshake failed: read tcp 127.0.0.1:57622->127.0.0.1:32915: read: connection reset by peer
I0825 11:22:28.281763 2478980 main.go:115] libmachine: Error dialing TCP: ssh: handshake failed: read tcp 127.0.0.1:57626->127.0.0.1:32915: read: connection reset by peer

We could potentially revert static IP until we know what the fix for this is. We definitely shouldn't release with this bug still in the code.

[ramrengaswamy]

Could this also be impacting the current latest release:

minikube version
minikube version: v1.12.3
commit: 2243b4b97c131e3244c5f014faedca0d846599f5-dirty

See a similar failure with: minikube start --driver=docker