kvm2 + profiles: during machine creation: Machine didn't return an IP after 120 seconds

[GeertJohan]

Creating a minikube instance with non-default profile fails. I've tried this multiple times (start, stop, delete, repeat) and on the default profile (minikube) it always works, but on another profile (nlx) it always fails with the same error: Error creating machine: Error in driver during machine creation: Machine didn't return an IP after 120 seconds.

The exact command to reproduce the issue:

$ minikube profile nlx
$ minikube start --vm-driver=kvm2 --cpus 4 --memory 8192 --disk-size=100G -v 8 --alsologtostderr

The full output of the command that failed:

I0513 13:11:25.963065    6707 notify.go:126] Checking for updates...
😄  minikube v1.0.1 on linux (amd64)
I0513 13:11:26.117706    6707 downloader.go:60] Not caching ISO, using https://storage.googleapis.com/minikube/iso/minikube-v1.0.1.iso
🤹  Downloading Kubernetes v1.14.1 images in the background ...
I0513 13:11:26.118134    6707 start.go:652] Saving config:
{
    "MachineConfig": {
        "MinikubeISO": "https://storage.googleapis.com/minikube/iso/minikube-v1.0.1.iso",
        "Memory": 8192,
        "CPUs": 4,
        "DiskSize": 100000,
        "VMDriver": "kvm2",
        "ContainerRuntime": "docker",
        "HyperkitVpnKitSock": "",
        "HyperkitVSockPorts": [],
        "XhyveDiskDriver": "ahci-hd",
        "DockerEnv": null,
        "InsecureRegistry": null,
        "RegistryMirror": null,
        "HostOnlyCIDR": "192.168.99.1/24",
        "HypervVirtualSwitch": "",
        "KvmNetwork": "default",
        "DockerOpt": null,
        "DisableDriverMounts": false,
        "NFSShare": [],
        "NFSSharesRoot": "/nfsshares",
        "UUID": "",
        "GPU": false,
        "Hidden": false,
        "NoVTXCheck": false
    },
    "KubernetesConfig": {
        "KubernetesVersion": "v1.14.1",
        "NodeIP": "",
        "NodePort": 8443,
        "NodeName": "minikube",
        "APIServerName": "minikubeCA",
        "APIServerNames": null,
        "APIServerIPs": null,
        "DNSDomain": "cluster.local",
        "ContainerRuntime": "docker",
        "CRISocket": "",
        "NetworkPlugin": "",
        "FeatureGates": "",
        "ServiceCIDR": "10.96.0.0/12",
        "ImageRepository": "",
        "ExtraOptions": null,
        "ShouldLoadCachedImages": true,
        "EnableDefaultCNI": false
    }
}
I0513 13:11:26.118320    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/kube-scheduler:v1.14.1 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/kube-scheduler_v1.14.1
I0513 13:11:26.118407    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/kube-proxy:v1.14.1 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/kube-proxy_v1.14.1
I0513 13:11:26.118461    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/k8s-dns-dnsmasq-nanny-amd64:1.14.13 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/k8s-dns-dnsmasq-nanny-amd64_1.14.13
I0513 13:11:26.118419    6707 cache_images.go:309] Attempting to cache image: gcr.io/k8s-minikube/storage-provisioner:v1.8.1 at /home/geertjohan/.minikube/cache/images/gcr.io/k8s-minikube/storage-provisioner_v1.8.1
I0513 13:11:26.118523    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/kube-apiserver:v1.14.1 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/kube-apiserver_v1.14.1
I0513 13:11:26.118552    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/coredns:1.3.1 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/coredns_1.3.1
I0513 13:11:26.118617    6707 cluster.go:78] Machine does not exist... provisioning new machine
I0513 13:11:26.119247    6707 cluster.go:79] Provisioning machine with config: {MinikubeISO:https://storage.googleapis.com/minikube/iso/minikube-v1.0.1.iso Memory:8192 CPUs:4 DiskSize:100000 VMDriver:kvm2 ContainerRuntime:docker HyperkitVpnKitSock: HyperkitVSockPorts:[] XhyveDiskDriver:ahci-hd DockerEnv:[] InsecureRegistry:[] RegistryMirror:[] HostOnlyCIDR:192.168.99.1/24 HypervVirtualSwitch: KvmNetwork:default Downloader:{} DockerOpt:[] DisableDriverMounts:false NFSShare:[] NFSSharesRoot:/nfsshares UUID: GPU:false Hidden:false NoVTXCheck:false}
I0513 13:11:26.118553    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/kube-addon-manager:v9.0 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/kube-addon-manager_v9.0
🔥  Creating kvm2 VM (CPUs=4, Memory=8192MB, Disk=100000MB) ...
I0513 13:11:26.118543    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/pause:3.1 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/pause_3.1
I0513 13:11:26.118668    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/k8s-dns-kube-dns-amd64:1.14.13 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/k8s-dns-kube-dns-amd64_1.14.13
I0513 13:11:26.118673    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/kube-controller-manager:v1.14.1 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/kube-controller-manager_v1.14.1
I0513 13:11:26.118692    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/k8s-dns-sidecar-amd64:1.14.13 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/k8s-dns-sidecar-amd64_1.14.13
I0513 13:11:26.118692    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/kubernetes-dashboard-amd64:v1.10.1 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/kubernetes-dashboard-amd64_v1.10.1
I0513 13:11:26.118722    6707 cache_images.go:309] Attempting to cache image: k8s.gcr.io/etcd:3.3.10 at /home/geertjohan/.minikube/cache/images/k8s.gcr.io/etcd_3.3.10
Found binary path at /usr/local/bin/docker-machine-driver-kvm2
Launching plugin server for driver kvm2
Plugin server listening at address 127.0.0.1:40873
() Calling .GetVersion
Using API Version  1
() Calling .SetConfigRaw
() Calling .GetMachineName
(nlx) Calling .GetMachineName
(nlx) Calling .DriverName
Reading certificate data from /home/geertjohan/.minikube/certs/ca.pem
Decoding PEM data...
Parsing certificate...
Reading certificate data from /home/geertjohan/.minikube/certs/cert.pem
Decoding PEM data...
Parsing certificate...
Running pre-create checks...
(nlx) Calling .PreCreateCheck
(nlx) Calling .GetConfigRaw
Creating machine...
(nlx) Calling .Create
(nlx) Creating machine...
(nlx) Creating network...
(nlx) Setting up network default
(nlx) Setting up network minikube-net
(nlx) Setting up minikube home directory...
(nlx) DBG | Setting executable bit set on /home/geertjohan/.minikube/machines/nlx
(nlx) DBG | Setting executable bit set on /home/geertjohan/.minikube/machines
(nlx) DBG | Setting executable bit set on /home/geertjohan/.minikube
(nlx) DBG | Setting executable bit set on /home/geertjohan
(nlx) DBG | Setting executable bit set on /home
(nlx) Building disk image...
(nlx) Downloading /home/geertjohan/.minikube/cache/boot2docker.iso from file:///home/geertjohan/.minikube/cache/iso/minikube-v1.0.1.iso...
(nlx) DBG | 2019/05/13 13:11:26 [INFO] Creating ssh key...
(nlx) DBG | 2019/05/13 13:11:26 [INFO] Creating raw disk image...
(nlx) DBG | Writing magic tar header
(nlx) DBG | Writing SSH key tar header
(nlx) Creating domain...
(nlx) Getting domain xml...
(nlx) DBG | Finished creating machine, now starting machine...
(nlx) Creating domain...
(nlx) Waiting to get IP...
(nlx) DBG | Waiting for machine to come up 0/40
(nlx) DBG | Waiting for machine to come up 1/40
(nlx) DBG | Waiting for machine to come up 2/40
(nlx) DBG | Waiting for machine to come up 3/40
(nlx) DBG | Waiting for machine to come up 4/40
(nlx) DBG | Waiting for machine to come up 5/40
(nlx) DBG | Waiting for machine to come up 6/40
(nlx) DBG | Waiting for machine to come up 7/40
(nlx) DBG | Waiting for machine to come up 8/40
(nlx) DBG | Waiting for machine to come up 9/40
(nlx) DBG | Waiting for machine to come up 10/40
(nlx) DBG | Waiting for machine to come up 11/40
(nlx) DBG | Waiting for machine to come up 12/40
(nlx) DBG | Waiting for machine to come up 13/40
(nlx) DBG | Waiting for machine to come up 14/40
(nlx) DBG | Waiting for machine to come up 15/40
(nlx) DBG | Waiting for machine to come up 16/40
(nlx) DBG | Waiting for machine to come up 17/40
(nlx) DBG | Waiting for machine to come up 18/40
(nlx) DBG | Waiting for machine to come up 19/40
(nlx) DBG | Waiting for machine to come up 20/40
(nlx) DBG | Waiting for machine to come up 21/40
(nlx) DBG | Waiting for machine to come up 22/40
(nlx) DBG | Waiting for machine to come up 23/40
(nlx) DBG | Waiting for machine to come up 24/40
(nlx) DBG | Waiting for machine to come up 25/40
(nlx) DBG | Waiting for machine to come up 26/40
(nlx) DBG | Waiting for machine to come up 27/40
(nlx) DBG | Waiting for machine to come up 28/40
(nlx) DBG | Waiting for machine to come up 29/40
(nlx) DBG | Waiting for machine to come up 30/40
(nlx) DBG | Waiting for machine to come up 31/40
(nlx) DBG | Waiting for machine to come up 32/40
(nlx) DBG | Waiting for machine to come up 33/40
(nlx) DBG | Waiting for machine to come up 34/40
(nlx) DBG | Waiting for machine to come up 35/40
(nlx) DBG | Waiting for machine to come up 36/40
(nlx) DBG | Waiting for machine to come up 37/40
(nlx) DBG | Waiting for machine to come up 38/40
(nlx) DBG | Waiting for machine to come up 39/40
I0513 13:13:26.175557    6707 cache_images.go:306] 
I0513 13:13:26.175670    6707 cache_images.go:306] 
I0513 13:13:26.175673    6707 cache_images.go:306] 
I0513 13:13:26.175697    6707 cache_images.go:306] 
I0513 13:13:26.175681    6707 cache_images.go:306] 
I0513 13:13:26.175898    6707 cache_images.go:306] 
I0513 13:13:26.175902    6707 cache_images.go:306] 
I0513 13:13:26.176125    6707 cache_images.go:306] 
I0513 13:13:26.176159    6707 cache_images.go:306] 
I0513 13:13:26.176304    6707 cache_images.go:306] 
I0513 13:13:26.176333    6707 cache_images.go:306] 
I0513 13:13:26.176445    6707 cache_images.go:306] 
I0513 13:13:26.176461    6707 cache_images.go:306] 
I0513 13:13:26.176506    6707 cache_images.go:86] Successfully cached all images.
(nlx) DBG | Waiting for machine to come up 40/40
I0513 13:13:32.524151    6707 start.go:428] StartHost: create: Error creating machine: Error in driver during machine creation: Machine didn't return an IP after 120 seconds
I0513 13:13:32.524251    6707 utils.go:122] non-retriable error: create: Error creating machine: Error in driver during machine creation: Machine didn't return an IP after 120 seconds
W0513 13:13:32.524614    6707 exit.go:99] Unable to start VM: create: Error creating machine: Error in driver during machine creation: Machine didn't return an IP after 120 seconds

💣  Unable to start VM: create: Error creating machine: Error in driver during machine creation: Machine didn't return an IP after 120 seconds

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

The output of the minikube logs command:

$ minikube logs

💣  command runner
❌  Error:         [SSH_AUTH_FAILURE] getting ssh client for bootstrapper: Error dialing tcp via ssh client: ssh: handshake failed: ssh: unable to authenticate, attempted methods [none publickey], no supported methods remain
💡  Advice:        Your host is failing to route packets to the minikube VM. If you have VPN software, try turning it off or configuring it so that it does not re-route traffic to the VM IP. If not, check your VM environment routing options.
⁉️   Related issues:
    ▪ https://github.com/kubernetes/minikube/issues/3930

😿  If the above advice does not help, please let us know: 
👉  https://github.com/kubernetes/minikube/issues/new

The operating system version:

$ uname -a
Linux lapromitux3 4.18.0-041800-lowlatency #201808122131 SMP PREEMPT Sun Aug 12 21:36:03 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 18.04.2 LTS
Release:	18.04
Codename:	bionic

[tstromberg]

Probably a dupe of #3566 - though it's curious that the default profile works in this case.

[josedonizetti]

@GeertJohan Have you tried upgrading your docker-machine-driver-kvm2. I was trying to debug this error, as it was also happening for me, and the code I was reading wasn't matching what was happening. After I've built the driver from the source, the new profile creation started to work.

[GeertJohan]

@josedonizetti How do I do that? I'm running ubuntu by the way.

Docker version 18.09.6, build 481bc77
.
$ docker-machine-driver-kvm2 --version
This is a Docker Machine plugin binary.
Plugin binaries are not intended to be invoked directly.
Please use this plugin through the main 'docker-machine' binary.
(API version: 1)

(The --version flag doesn't seem to work for docker-machine-driver-kvm2)
I'm up-to-date according to the official docker apt repo.

[tstromberg]

To upgrade kvm2:

curl -LO https://storage.googleapis.com/minikube/releases/latest/docker-machine-driver-kvm2 \
  && sudo install docker-machine-driver-kvm2 /usr/local/bin/

@GeertJohan - Please let me know if this helps. If so, I'll add this solution to the error text.

[GeertJohan]

@tstromberg It works! 🎉 🚀
I guess I have installed docker-machine-driver-kvm2 a long time ago, and forgot about it. So never updated it. Perhaps minikube or docker-machine-driver-kvm2 should suggest the user to update when a new version is available?