Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

kvm2: minikube start fails, due to timeout before disk image is fully created #7561

Closed
raphendyr opened this issue Apr 9, 2020 · 9 comments
Closed

kvm2: minikube start fails, due to timeout before disk image is fully created #7561

raphendyr opened this issue Apr 9, 2020 · 9 comments
Labels
co/kvm2-driver KVM2 driver related issues kind/support Categorizes issue or PR as a support question. triage/needs-information Indicates an issue needs more information in order to work on it.

Comments

@raphendyr
Copy link

raphendyr commented Apr 9, 2020 •
edited
Loading

Steps to reproduce the issue:

  1. Have a Linux host with HDD or other slow storage
  2. Download a version of minikube in range v1.7.3 to v1.9.2
  3. Create a new minikube minikube-1.7.3 start -p minikube173 --auto-update-drivers=false -v=8 --alsologtostderr --vm-driver=kvm2
  4. Minikube start fails after around 2 minutes, due to a hard coded timeout.

Full output of failed command:

Output for v1.9.2 (fails) 
I0410 00:52:01.014304 1546583 start.go:262] hostinfo: {"hostname":"HOSTNAME","uptime":651379,"bootTime":1585817741,"procs":266,"os":"linux","platform":"debian","platformFamily":"debian","platformVersion":"bullseye/sid","kernelVersion":"5.4.0-2-amd64","virtualizationSystem":"kvm","virtualizationRole":"host","hostid":"HOSTID"}
I0410 00:52:01.019119 1546583 start.go:272] virtualization: kvm host
😄  [minikube192] minikube v1.9.2 on Debian bullseye/sid
I0410 00:52:01.102648 1546583 driver.go:245] Setting default libvirt URI to qemu:///system
❗  Both driver=kvm2 and vm-driver=kvm2 have been set.

    Since vm-driver is deprecated, minikube will default to driver=kvm2.

    If vm-driver is set in the global config, please run "minikube config unset vm-driver" to resolve this warning.

✨  Using the kvm2 driver based on user configuration
I0410 00:52:01.270772 1546583 start.go:310] selected driver: kvm2
I0410 00:52:01.283545 1546583 start.go:656] validating driver "kvm2" against <nil>
I0410 00:52:01.283657 1546583 start.go:662] status for kvm2: {Installed:true Healthy:true Error:<nil> Fix: Doc:}
I0410 00:52:01.307835 1546583 install.go:49] acquiring lock: {Name:mk900956b073697a4aa6c80a27c6bb0742a99a53 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:52:01.319666 1546583 install.go:115] Validating docker-machine-driver-kvm2, PATH=/home/USER/.minikube/bin:/home/USER/.local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games
I0410 00:52:01.408336 1546583 start.go:1004] Using suggested 4000MB memory alloc based on sys=16000MB, container=0MB
I0410 00:52:01.416427 1546583 start.go:1210] Wait components to verify : map[apiserver:true system_pods:true]
I0410 00:52:01.417232 1546583 iso.go:119] acquiring lock: {Name:mkc51147e3c3dcff06072bf6bbe3a959e63d43b6 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
💿  Downloading VM boot image ...
I0410 00:52:01.503740 1546583 iso.go:147] full url: https://storage.googleapis.com/minikube/iso/minikube-v1.9.0.iso?checksum=file:https://storage.googleapis.com/minikube/iso/minikube-v1.9.0.iso.sha256
    > minikube-v1.9.0.iso.sha256: 65 B / 65 B [--------------] 100.00% ? p/s 0s
    > minikube-v1.9.0.iso: 174.93 MiB / 174.93 MiB [-] 100.00% 46.69 MiB p/s 4s
👍  Starting control plane node m01 in cluster minikube192
I0410 00:52:07.691223 1546583 preload.go:81] Checking if preload exists for k8s version v1.18.0 and runtime docker
I0410 00:52:07.902275 1546583 preload.go:114] Found remote preload: https://storage.googleapis.com/minikube-preloaded-volume-tarballs/preloaded-images-k8s-v2-v1.18.0-docker-overlay2-amd64.tar.lz4
I0410 00:52:07.918688 1546583 cache.go:46] Caching tarball of preloaded images
I0410 00:52:07.918748 1546583 preload.go:81] Checking if preload exists for k8s version v1.18.0 and runtime docker
I0410 00:52:08.055148 1546583 preload.go:114] Found remote preload: https://storage.googleapis.com/minikube-preloaded-volume-tarballs/preloaded-images-k8s-v2-v1.18.0-docker-overlay2-amd64.tar.lz4
💾  Downloading Kubernetes v1.18.0 preload ...
I0410 00:52:08.097961 1546583 preload.go:144] Downloading: &{Ctx:<nil> Src:https://storage.googleapis.com/minikube-preloaded-volume-tarballs/preloaded-images-k8s-v2-v1.18.0-docker-overlay2-amd64.tar.lz4 Dst:/home/USER/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v2-v1.18.0-docker-overlay2-amd64.tar.lz4.download Pwd: Mode:2 Detectors:[] Decompressors:map[] Getters:map[] Dir:false ProgressListener:<nil> Options:[0xbf9750]}
    > preloaded-images-k8s-v2-v1.18.0-docker-overlay2-amd64.tar.lz4: 542.91 MiB
I0410 00:52:16.518181 1546583 preload.go:160] saving checksum for preloaded-images-k8s-v2-v1.18.0-docker-overlay2-amd64.tar.lz4 ...
I0410 00:52:16.805907 1546583 preload.go:177] verifying checksumm of /home/USER/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v2-v1.18.0-docker-overlay2-amd64.tar.lz4.download ...
I0410 00:52:17.890920 1546583 cache.go:49] Finished downloading the preloaded tar for v1.18.0 on docker
I0410 00:52:17.908480 1546583 profile.go:138] Saving config to /home/USER/.minikube/profiles/minikube192/config.json ...
I0410 00:52:17.920937 1546583 lock.go:35] WriteFile acquiring /home/USER/.minikube/profiles/minikube192/config.json: {Name:mke1656c52393e37263276dbdc350c9a8a193094 Clock:{} Delay:500ms Timeout:1m0s Cancel:<nil>}
I0410 00:52:17.921358 1546583 cache.go:117] Successfully downloaded all kic artifacts
I0410 00:52:17.974539 1546583 start.go:260] acquiring machines lock for minikube192: {Name:mk75de6b7c3cc6b2056966c4f31563e893af7c7a Clock:{} Delay:500ms Timeout:15m0s Cancel:<nil>}
I0410 00:52:17.974707 1546583 start.go:264] acquired machines lock for "minikube192" in 112.304µs
I0410 00:52:17.987383 1546583 start.go:86] Provisioning new machine with config: {Name:minikube192 KeepContext:false EmbedCerts:false MinikubeISO:https://storage.googleapis.com/minikube/iso/minikube-v1.9.0.iso Memory:4000 CPUs:2 DiskSize:20000 Driver:kvm2 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.0 ClusterName:minikube192 APIServerName:minikubeCA APIServerNames:[] APIServerIPs:[] DNSDomain:cluster.local ContainerRuntime:docker CRISocket: NetworkPlugin: FeatureGates: ServiceCIDR:10.96.0.0/12 ImageRepository: ExtraOptions:[] ShouldLoadCachedImages:true EnableDefaultCNI:false NodeIP: NodePort:0 NodeName:} Nodes:[{Name:m01 IP: Port:8443 KubernetesVersion:v1.18.0 ControlPlane:true Worker:true}] Addons:map[] VerifyComponents:map[apiserver:true system_pods:true]} {Name:m01 IP: Port:8443 KubernetesVersion:v1.18.0 ControlPlane:true Worker:true}
I0410 00:52:17.995970 1546583 start.go:107] createHost starting for "m01" (driver="kvm2")
🔥  Creating kvm2 VM (CPUs=2, Memory=4000MB, Disk=20000MB) ...
I0410 00:52:18.057923 1546583 main.go:110] libmachine: Found binary path at /home/USER/.minikube/bin/docker-machine-driver-kvm2
I0410 00:52:18.089559 1546583 main.go:110] libmachine: Launching plugin server for driver kvm2
I0410 00:52:18.124721 1546583 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:35441
I0410 00:52:18.143942 1546583 main.go:110] libmachine: () Calling .GetVersion
I0410 00:52:18.168183 1546583 main.go:110] libmachine: Using API Version  1
I0410 00:52:18.168229 1546583 main.go:110] libmachine: () Calling .SetConfigRaw
I0410 00:52:18.168875 1546583 main.go:110] libmachine: () Calling .GetMachineName
I0410 00:52:18.169346 1546583 main.go:110] libmachine: (minikube192) Calling .GetMachineName
I0410 00:52:18.169685 1546583 main.go:110] libmachine: (minikube192) Calling .DriverName
I0410 00:52:18.170119 1546583 start.go:143] libmachine.API.Create for "minikube192" (driver="kvm2")
I0410 00:52:18.170732 1546583 client.go:169] LocalClient.Create starting
I0410 00:52:18.170804 1546583 main.go:110] libmachine: Reading certificate data from /home/USER/.minikube/certs/ca.pem
I0410 00:52:18.186444 1546583 main.go:110] libmachine: Decoding PEM data...
I0410 00:52:18.186516 1546583 main.go:110] libmachine: Parsing certificate...
I0410 00:52:18.188367 1546583 main.go:110] libmachine: Reading certificate data from /home/USER/.minikube/certs/cert.pem
I0410 00:52:18.196544 1546583 main.go:110] libmachine: Decoding PEM data...
I0410 00:52:18.196595 1546583 main.go:110] libmachine: Parsing certificate...
I0410 00:52:18.196796 1546583 main.go:110] libmachine: Running pre-create checks...
I0410 00:52:18.196832 1546583 main.go:110] libmachine: (minikube192) Calling .PreCreateCheck
I0410 00:52:18.197513 1546583 main.go:110] libmachine: (minikube192) Calling .GetConfigRaw
I0410 00:52:18.199521 1546583 main.go:110] libmachine: Creating machine...
I0410 00:52:18.199559 1546583 main.go:110] libmachine: (minikube192) Calling .Create
I0410 00:52:18.199931 1546583 main.go:110] libmachine: (minikube192) Creating KVM machine...
I0410 00:52:18.204966 1546583 main.go:110] libmachine: (minikube192) Setting up store path in /home/USER/.minikube/machines/minikube192 ...
I0410 00:52:18.205035 1546583 main.go:110] libmachine: (minikube192) Building disk image from file:///home/USER/.minikube/cache/iso/minikube-v1.9.0.iso
I0410 00:52:18.205215 1546583 main.go:110] libmachine: (minikube192) DBG | ERROR: logging before flag.Parse: I0410 00:52:18.204966 1546623 common.go:99] Making disk image using store path: /home/USER/.minikube
I0410 00:52:18.205339 1546583 main.go:110] libmachine: (minikube192) Downloading /home/USER/.minikube/cache/boot2docker.iso from file:///home/USER/.minikube/cache/iso/minikube-v1.9.0.iso...
I0410 00:52:18.731096 1546583 main.go:110] libmachine: (minikube192) DBG | ERROR: logging before flag.Parse: I0410 00:52:18.730971 1546623 common.go:106] Creating ssh key: /home/USER/.minikube/machines/minikube192/id_rsa...
I0410 00:52:18.853865 1546583 main.go:110] libmachine: (minikube192) DBG | ERROR: logging before flag.Parse: I0410 00:52:18.853764 1546623 common.go:112] Creating raw disk image: /home/USER/.minikube/machines/minikube192/minikube192.rawdisk...
I0410 00:52:18.853918 1546583 main.go:110] libmachine: (minikube192) DBG | Writing magic tar header
I0410 00:52:18.853933 1546583 main.go:110] libmachine: (minikube192) DBG | Writing SSH key tar header
I0410 00:54:18.810251 1546583 start.go:110] createHost completed in 2m0.625401783s
I0410 00:54:18.810387 1546583 start.go:77] releasing machines lock for "minikube192", held for 2m0.835648567s
🤦  StartHost failed, but will try again: creating host: create host timed out in 120.000000 seconds
I0410 00:54:26.025321 1546583 main.go:110] libmachine: Found binary path at /home/USER/.minikube/bin/docker-machine-driver-kvm2
I0410 00:54:26.025426 1546583 main.go:110] libmachine: Launching plugin server for driver kvm2
I0410 00:54:27.633828 1546583 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:34483
I0410 00:54:28.666793 1546583 main.go:110] libmachine: () Calling .GetVersion
I0410 00:54:30.087119 1546583 main.go:110] libmachine: Using API Version  1
I0410 00:54:30.087427 1546583 main.go:110] libmachine: () Calling .SetConfigRaw
I0410 00:54:30.088044 1546583 main.go:110] libmachine: () Calling .GetMachineName
I0410 00:54:30.370331 1546583 main.go:110] libmachine: Found binary path at /home/USER/.minikube/bin/docker-machine-driver-kvm2
I0410 00:54:30.622242 1546583 main.go:110] libmachine: Launching plugin server for driver kvm2
I0410 00:54:30.639117 1546583 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:40229
I0410 00:54:30.639639 1546583 main.go:110] libmachine: () Calling .GetVersion
I0410 00:54:30.640051 1546583 main.go:110] libmachine: Using API Version  1
I0410 00:54:30.640085 1546583 main.go:110] libmachine: () Calling .SetConfigRaw
I0410 00:54:30.640353 1546583 main.go:110] libmachine: () Calling .GetMachineName
I0410 00:54:30.640942 1546583 main.go:110] libmachine: (minikube192) Calling .GetState
I0410 00:54:30.878924 1546583 delete.go:72] Unable to get host status for minikube192, assuming it has already been deleted: state: getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube192'')
I0410 00:54:36.553283 1546583 start.go:260] acquiring machines lock for minikube192: {Name:mk75de6b7c3cc6b2056966c4f31563e893af7c7a Clock:{} Delay:500ms Timeout:15m0s Cancel:<nil>}
I0410 00:54:37.334589 1546583 start.go:264] acquired machines lock for "minikube192" in 402.943378ms
I0410 00:54:37.334660 1546583 start.go:90] Skipping create...Using existing machine configuration
I0410 00:54:37.513243 1546583 fix.go:53] fixHost starting: m01
I0410 00:54:37.513886 1546583 main.go:110] libmachine: Found binary path at /home/USER/.minikube/bin/docker-machine-driver-kvm2
I0410 00:54:37.513969 1546583 main.go:110] libmachine: Launching plugin server for driver kvm2
I0410 00:54:37.532144 1546583 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:44977
I0410 00:54:37.532625 1546583 main.go:110] libmachine: () Calling .GetVersion
I0410 00:54:37.533195 1546583 main.go:110] libmachine: Using API Version  1
I0410 00:54:37.533229 1546583 main.go:110] libmachine: () Calling .SetConfigRaw
I0410 00:54:37.533625 1546583 main.go:110] libmachine: () Calling .GetMachineName
I0410 00:54:37.533892 1546583 main.go:110] libmachine: (minikube192) Calling .DriverName
I0410 00:54:37.534221 1546583 main.go:110] libmachine: (minikube192) Calling .GetState
I0410 00:54:37.672647 1546583 fix.go:105] recreateIfNeeded on minikube192: state=Error err=getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube192'')
I0410 00:54:37.711042 1546583 main.go:110] libmachine: (minikube192) Calling .DriverName
I0410 00:54:37.711420 1546583 fix.go:109] exists: true err=getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube192'')
I0410 00:54:39.765717 1546583 fix.go:110] "getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube192'')" vs "machine does not exist"
W0410 00:54:39.783138 1546583 fix.go:130] unexpected machine state, will restart: getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube192'')
🔄  Restarting existing kvm2 VM for "minikube192" ...
I0410 00:54:40.950482 1546583 main.go:110] libmachine: (minikube192) Calling .Start
I0410 00:54:40.950770 1546583 main.go:110] libmachine: (minikube192) Creating network...
I0410 00:54:40.953661 1546583 main.go:110] libmachine: (minikube192) Ensuring networks are active...
I0410 00:54:40.955413 1546583 main.go:110] libmachine: (minikube192) Ensuring network default is active
I0410 00:54:41.517343 1546583 main.go:110] libmachine: (minikube192) Ensuring network minikube-net is active
I0410 00:54:41.517795 1546583 main.go:110] libmachine: (minikube192) Getting domain xml...
I0410 00:54:41.520138 1546583 fix.go:55] fixHost completed within 4.018343297s
I0410 00:54:41.571430 1546583 start.go:77] releasing machines lock for "minikube192", held for 4.236785603s

❌  [KVM2_NO_DOMAIN] Failed to start kvm2 VM. "minikube start -p minikube192" may fix it. driver start: getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube192'')
💡  Suggestion: The VM that minikube is configured for no longer exists. Run 'minikube delete'
⁉️   Related issue: https://github.com/kubernetes/minikube/issues/363
Output for v1.7.3 (fails) 
I0410 00:45:35.396730 1546443 start.go:249] hostinfo: {"hostname":"HOSTNAME","uptime":650994,"bootTime":1585817741,"procs":264,"os":"linux","platform":"debian","platformFamily":"debian","platformVersion":"bullseye/sid","kernelVersion":"5.4.0-2-amd64","virtualizationSystem":"kvm","virtualizationRole":"host","hostid":"HOSTID"}
I0410 00:45:35.397760 1546443 start.go:259] virtualization: kvm host
😄  [minikube173] minikube v1.7.3 on Debian bullseye/sid
I0410 00:45:35.398061 1546443 driver.go:211] Setting default libvirt URI to qemu:///system
✨  Using the kvm2 driver based on user configuration
I0410 00:45:35.483984 1546443 start.go:296] selected driver: kvm2
I0410 00:45:35.484007 1546443 start.go:472] validating driver "kvm2" against <nil>
I0410 00:45:35.484028 1546443 start.go:478] status for kvm2: {Installed:true Healthy:true Error:<nil> Fix: Doc:}
I0410 00:45:35.484142 1546443 install.go:50] acquiring lock: {Name:mk900956b073697a4aa6c80a27c6bb0742a99a53 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.484466 1546443 install.go:116] Validating docker-machine-driver-kvm2, PATH=/home/USER/.minikube/bin:/home/USER/.local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games
I0410 00:45:35.563911 1546443 downloader.go:67] acquiring lock: {Name:mk8410923cfbb61b3c121ecf3c8806edf27f2daa Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.564112 1546443 downloader.go:75] Not caching ISO, using https://storage.googleapis.com/minikube/iso/minikube-v1.7.3.iso
I0410 00:45:35.564443 1546443 cache.go:91] acquiring lock: {Name:mk0fd4cba89e7ca9bc754598a3e0b582ea7d7f50 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.564558 1546443 cache.go:91] acquiring lock: {Name:mk30d2f5a9ac3344f10eeb9d9f0dc7a231219f9d Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.564599 1546443 profile.go:100] Saving config to /home/USER/.minikube/profiles/minikube173/config.json ...
I0410 00:45:35.564654 1546443 cache.go:91] acquiring lock: {Name:mk19e3086623eb9088f143e50c5465e9b57d64cb Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.564692 1546443 cache.go:99] /home/USER/.minikube/cache/images/kubernetesui/metrics-scraper_v1.0.2 exists
I0410 00:45:35.564752 1546443 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/coredns_1.6.5 exists
I0410 00:45:35.564765 1546443 cache.go:80] cache image "kubernetesui/metrics-scraper:v1.0.2" -> "/home/USER/.minikube/cache/images/kubernetesui/metrics-scraper_v1.0.2" took 334.746µs
I0410 00:45:35.564765 1546443 cache.go:91] acquiring lock: {Name:mk6e8a78b5e8ca16df80352b3a593192fce2b881 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.564876 1546443 cache.go:91] acquiring lock: {Name:mk823612dfb6847688c16c5cb0322c56bcca17f5 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.564876 1546443 cache.go:91] acquiring lock: {Name:mk47467bc1ac36a6fa25616fb60b984d9d74f0f7 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.564979 1546443 cache.go:91] acquiring lock: {Name:mke3ea816cb799a005d13a78846b987d325eb47f Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.565073 1546443 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-apiserver_v1.17.3 exists
I0410 00:45:35.565546 1546443 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-controller-manager_v1.17.3 exists
I0410 00:45:35.565569 1546443 cache.go:80] cache image "k8s.gcr.io/kube-apiserver:v1.17.3" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-apiserver_v1.17.3" took 444.745µs
I0410 00:45:35.565621 1546443 cache.go:65] save to tar file k8s.gcr.io/kube-apiserver:v1.17.3 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-apiserver_v1.17.3 succeeded
I0410 00:45:35.565608 1546443 cache.go:80] cache image "k8s.gcr.io/kube-controller-manager:v1.17.3" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-controller-manager_v1.17.3" took 738.425µs
I0410 00:45:35.565644 1546443 cache.go:91] acquiring lock: {Name:mk6081071eb03283b99ba86d3576fe5b9af12d45 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.565710 1546443 cache.go:65] save to tar file k8s.gcr.io/kube-controller-manager:v1.17.3 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-controller-manager_v1.17.3 succeeded
I0410 00:45:35.564814 1546443 cache.go:99] /home/USER/.minikube/cache/images/gcr.io/k8s-minikube/storage-provisioner_v1.8.1 exists
I0410 00:45:35.565868 1546443 cache.go:80] cache image "gcr.io/k8s-minikube/storage-provisioner:v1.8.1" -> "/home/USER/.minikube/cache/images/gcr.io/k8s-minikube/storage-provisioner_v1.8.1" took 1.272147ms
I0410 00:45:35.564810 1546443 cache.go:80] cache image "k8s.gcr.io/coredns:1.6.5" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/coredns_1.6.5" took 324.06µs
I0410 00:45:35.566048 1546443 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-proxy_v1.17.3 exists
I0410 00:45:35.566126 1546443 cache.go:80] cache image "k8s.gcr.io/kube-proxy:v1.17.3" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-proxy_v1.17.3" took 1.068423ms
I0410 00:45:35.564662 1546443 cache.go:91] acquiring lock: {Name:mk499f6775c5d9d431ec39733f002257d420bc42 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.566029 1546443 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-scheduler_v1.17.3 exists
I0410 00:45:35.566282 1546443 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/pause_3.1 exists
I0410 00:45:35.566292 1546443 cache.go:80] cache image "k8s.gcr.io/kube-scheduler:v1.17.3" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-scheduler_v1.17.3" took 1.536146ms
I0410 00:45:35.566359 1546443 cache.go:65] save to tar file k8s.gcr.io/kube-scheduler:v1.17.3 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-scheduler_v1.17.3 succeeded
I0410 00:45:35.565907 1546443 cache.go:99] /home/USER/.minikube/cache/images/kubernetesui/dashboard_v2.0.0-beta8 exists
I0410 00:45:35.566432 1546443 cache.go:80] cache image "kubernetesui/dashboard:v2.0.0-beta8" -> "/home/USER/.minikube/cache/images/kubernetesui/dashboard_v2.0.0-beta8" took 1.536704ms
I0410 00:45:35.566510 1546443 cache.go:65] save to tar file kubernetesui/dashboard:v2.0.0-beta8 -> /home/USER/.minikube/cache/images/kubernetesui/dashboard_v2.0.0-beta8 succeeded
I0410 00:45:35.566323 1546443 cache.go:80] cache image "k8s.gcr.io/pause:3.1" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/pause_3.1" took 1.814041ms
I0410 00:45:35.566544 1546443 cache.go:65] save to tar file k8s.gcr.io/pause:3.1 -> /home/USER/.minikube/cache/images/k8s.gcr.io/pause_3.1 succeeded
I0410 00:45:35.565758 1546443 cache.go:91] acquiring lock: {Name:mke10f635da4049366f93d2e10938d3e68ae6dda Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:45:35.565994 1546443 cache.go:65] save to tar file gcr.io/k8s-minikube/storage-provisioner:v1.8.1 -> /home/USER/.minikube/cache/images/gcr.io/k8s-minikube/storage-provisioner_v1.8.1 succeeded
I0410 00:45:35.564817 1546443 cache.go:65] save to tar file kubernetesui/metrics-scraper:v1.0.2 -> /home/USER/.minikube/cache/images/kubernetesui/metrics-scraper_v1.0.2 succeeded
I0410 00:45:35.566064 1546443 cache.go:65] save to tar file k8s.gcr.io/coredns:1.6.5 -> /home/USER/.minikube/cache/images/k8s.gcr.io/coredns_1.6.5 succeeded
I0410 00:45:35.566180 1546443 cache.go:65] save to tar file k8s.gcr.io/kube-proxy:v1.17.3 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-proxy_v1.17.3 succeeded
I0410 00:45:35.566685 1546443 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/etcd_3.4.3-0 exists
I0410 00:45:35.566726 1546443 cache.go:80] cache image "k8s.gcr.io/etcd:3.4.3-0" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/etcd_3.4.3-0" took 2.19607ms
I0410 00:45:35.566907 1546443 cache.go:65] save to tar file k8s.gcr.io/etcd:3.4.3-0 -> /home/USER/.minikube/cache/images/k8s.gcr.io/etcd_3.4.3-0 succeeded
I0410 00:45:35.566969 1546443 cache.go:72] Successfully saved all images to host disk.
I0410 00:45:35.586274 1546443 lock.go:35] WriteFile acquiring /home/USER/.minikube/profiles/minikube173/config.json: {Name:mk5224d1e4184d609ad69042750bf4743b08f7e0 Clock:{} Delay:500ms Timeout:1m0s Cancel:<nil>}
I0410 00:45:35.586762 1546443 start.go:244] acquiring machines lock for minikube173: {Name:mk75de6b7c3cc6b2056966c4f31563e893af7c7a Clock:{} Delay:500ms Timeout:15m0s Cancel:<nil>}
I0410 00:45:35.586896 1546443 start.go:248] acquired machines lock for "minikube173" in 95.332µs
I0410 00:45:35.586944 1546443 start.go:81] Provisioning new machine with config: {Name:minikube173 KeepContext:false EmbedCerts:false MinikubeISO:https://storage.googleapis.com/minikube/iso/minikube-v1.7.3.iso Memory:2000 CPUs:2 DiskSize:20000 Driver:kvm2 HyperkitVpnKitSock: HyperkitVSockPorts:[] DockerEnv:[] InsecureRegistry:[] RegistryMirror:[] HostOnlyCIDR:192.168.99.1/24 HypervVirtualSwitch: HypervUseExternalSwitch:false HypervExternalAdapter: KVMNetwork:default KVMQemuURI:qemu:///system KVMGPU:false KVMHidden:false Downloader:{} DockerOpt:[] DisableDriverMounts:false NFSShare:[] NFSSharesRoot:/nfsshares UUID: NoVTXCheck:false DNSProxy:false HostDNSResolver:true HostOnlyNicType:virtio NatNicType:virtio KubernetesConfig:{KubernetesVersion:v1.17.3 ClusterName:minikube173 APIServerName:minikubeCA APIServerNames:[] APIServerIPs:[] DNSDomain:cluster.local ContainerRuntime:docker CRISocket: NetworkPlugin: FeatureGates: ServiceCIDR:10.96.0.0/12 ImageRepository: ExtraOptions:[] ShouldLoadCachedImages:true EnableDefaultCNI:false} Nodes:[{Name:minikube173 IP: Port:8443 KubernetesVersion:v1.17.3 ControlPlane:true Worker:true}] Addons:map[]}
I0410 00:45:35.587079 1546443 start.go:100] createHost starting for "minikube173" (driver="kvm2")
🔥  Creating kvm2 VM (CPUs=2, Memory=2000MB, Disk=20000MB) ...
I0410 00:45:35.587449 1546443 main.go:110] libmachine: Found binary path at /home/USER/.minikube/bin/docker-machine-driver-kvm2
I0410 00:45:35.587553 1546443 main.go:110] libmachine: Launching plugin server for driver kvm2
I0410 00:45:35.606949 1546443 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:36325
I0410 00:45:35.607602 1546443 main.go:110] libmachine: () Calling .GetVersion
I0410 00:45:35.608650 1546443 main.go:110] libmachine: Using API Version  1
I0410 00:45:35.608705 1546443 main.go:110] libmachine: () Calling .SetConfigRaw
I0410 00:45:35.609187 1546443 main.go:110] libmachine: () Calling .GetMachineName
I0410 00:45:35.609557 1546443 main.go:110] libmachine: (minikube173) Calling .GetMachineName
I0410 00:45:35.609908 1546443 main.go:110] libmachine: (minikube173) Calling .DriverName
I0410 00:45:35.610253 1546443 start.go:136] libmachine.API.Create for "minikube173" (driver="kvm2")
I0410 00:45:35.610368 1546443 main.go:110] libmachine: Reading certificate data from /home/USER/.minikube/certs/ca.pem
I0410 00:45:35.616418 1546443 main.go:110] libmachine: Decoding PEM data...
I0410 00:45:35.616470 1546443 main.go:110] libmachine: Parsing certificate...
I0410 00:45:35.616700 1546443 main.go:110] libmachine: Reading certificate data from /home/USER/.minikube/certs/cert.pem
I0410 00:45:35.621485 1546443 main.go:110] libmachine: Decoding PEM data...
I0410 00:45:35.621533 1546443 main.go:110] libmachine: Parsing certificate...
I0410 00:45:35.621639 1546443 main.go:110] libmachine: Running pre-create checks...
I0410 00:45:35.621659 1546443 main.go:110] libmachine: (minikube173) Calling .PreCreateCheck
I0410 00:45:35.622191 1546443 main.go:110] libmachine: (minikube173) Calling .GetConfigRaw
I0410 00:45:35.622912 1546443 main.go:110] libmachine: Creating machine...
I0410 00:45:35.622944 1546443 main.go:110] libmachine: (minikube173) Calling .Create
I0410 00:45:35.623218 1546443 main.go:110] libmachine: (minikube173) Creating KVM machine...
I0410 00:45:35.628457 1546443 main.go:110] libmachine: (minikube173) Setting up store path in /home/USER/.minikube/machines/minikube173 ...
I0410 00:45:35.628519 1546443 main.go:110] libmachine: (minikube173) Building disk image from file:///home/USER/.minikube/cache/iso/minikube-v1.7.3.iso
I0410 00:45:35.628666 1546443 main.go:110] libmachine: (minikube173) DBG | ERROR: logging before flag.Parse: I0410 00:45:35.628458 1546481 common.go:99] Making disk image using store path: /home/USER/.minikube
I0410 00:45:35.628799 1546443 main.go:110] libmachine: (minikube173) Downloading /home/USER/.minikube/cache/boot2docker.iso from file:///home/USER/.minikube/cache/iso/minikube-v1.7.3.iso...
I0410 00:45:36.128357 1546443 main.go:110] libmachine: (minikube173) DBG | ERROR: logging before flag.Parse: I0410 00:45:36.128223 1546481 common.go:106] Creating ssh key: /home/USER/.minikube/machines/minikube173/id_rsa...
I0410 00:45:36.383390 1546443 main.go:110] libmachine: (minikube173) DBG | ERROR: logging before flag.Parse: I0410 00:45:36.383278 1546481 common.go:112] Creating raw disk image: /home/USER/.minikube/machines/minikube173/minikube173.rawdisk...
I0410 00:45:36.383442 1546443 main.go:110] libmachine: (minikube173) DBG | Writing magic tar header
I0410 00:45:36.383472 1546443 main.go:110] libmachine: (minikube173) DBG | Writing SSH key tar header
I0410 00:47:35.648056 1546443 start.go:103] createHost completed in 2m0.023568995s
I0410 00:47:35.648109 1546443 start.go:72] releasing machines lock for "minikube173", held for 2m0.06117798s
W0410 00:47:35.648299 1546443 exit.go:101] Unable to start VM. Please investigate and run 'minikube delete' if possible: creating host: create host timed out in 120.000000 seconds

💣  Unable to start VM. Please investigate and run 'minikube delete' if possible: creating host: create host timed out in 120.000000 seconds

😿  minikube is exiting due to an error. If the above message is not useful, open an issue:
👉  https://github.com/kubernetes/minikube/issues/new/choose
Output for v1.7.2 (success after ~5min) 
I0410 00:59:03.649102 1547137 start.go:259] hostinfo: {"hostname":"HOSTNAME","uptime":651802,"bootTime":1585817741,"procs":265,"os":"linux","platform":"debian","platformFamily":"debian","platformVersion":"bullseye/sid","kernelVersion":"5.4.0-2-amd64","virtualizationSystem":"kvm","virtualizationRole":"host","hostid":"HOSTID"}
I0410 00:59:03.650103 1547137 start.go:269] virtualization: kvm host
😄  minikube v1.7.2 on Debian bullseye/sid
I0410 00:59:03.650372 1547137 driver.go:199] Setting default libvirt URI to qemu:///system
✨  Using the kvm2 driver based on user configuration
I0410 00:59:03.727881 1547137 start.go:306] selected driver: kvm2
I0410 00:59:03.727899 1547137 start.go:612] validating driver "kvm2" against <nil>
I0410 00:59:03.727919 1547137 start.go:618] status for kvm2: {Installed:true Healthy:true Error:<nil> Fix: Doc:}
I0410 00:59:03.727999 1547137 install.go:50] acquiring lock: {Name:mk900956b073697a4aa6c80a27c6bb0742a99a53 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.728250 1547137 install.go:116] Validating docker-machine-driver-kvm2, PATH=/home/USER/.minikube/bin:/home/USER/.local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games
I0410 00:59:03.741971 1547137 downloader.go:67] acquiring lock: {Name:mkbad0224f80dc4282079aa36a02e557b2543d7c Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742105 1547137 downloader.go:75] Not caching ISO, using https://storage.googleapis.com/minikube/iso/minikube-v1.7.0.iso
I0410 00:59:03.742310 1547137 profile.go:100] Saving config to /home/USER/.minikube/profiles/minikube/config.json ...
I0410 00:59:03.742538 1547137 cache.go:91] acquiring lock: {Name:mk23e340c8fc8d287e5c8768c6a376ca5018c1a3 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742326 1547137 cache.go:91] acquiring lock: {Name:mk19451412bac045a62bfdb5d2cb30acad7a12bd Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742615 1547137 cache.go:91] acquiring lock: {Name:mkf8af428fd6c23e8842a3036d11f3a25b728f49 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742634 1547137 cache.go:91] acquiring lock: {Name:mk0fd4cba89e7ca9bc754598a3e0b582ea7d7f50 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742688 1547137 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-controller-manager_v1.17.2 exists
I0410 00:59:03.742715 1547137 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-proxy_v1.17.2 exists
I0410 00:59:03.742727 1547137 cache.go:80] cache image "k8s.gcr.io/kube-controller-manager:v1.17.2" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-controller-manager_v1.17.2" took 184.24µs
I0410 00:59:03.742740 1547137 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-apiserver_v1.17.2 exists
I0410 00:59:03.742743 1547137 cache.go:80] cache image "k8s.gcr.io/kube-proxy:v1.17.2" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-proxy_v1.17.2" took 195.275µs
I0410 00:59:03.742848 1547137 cache.go:65] save to tar file k8s.gcr.io/kube-proxy:v1.17.2 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-proxy_v1.17.2 succeeded
I0410 00:59:03.742756 1547137 cache.go:91] acquiring lock: {Name:mkd3715830eb8e738656138ddf59cd2674aa70df Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742876 1547137 cache.go:91] acquiring lock: {Name:mk19e3086623eb9088f143e50c5465e9b57d64cb Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742885 1547137 cache.go:91] acquiring lock: {Name:mke3ea816cb799a005d13a78846b987d325eb47f Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742743 1547137 cache.go:99] /home/USER/.minikube/cache/images/kubernetesui/metrics-scraper_v1.0.2 exists
I0410 00:59:03.742752 1547137 cache.go:65] save to tar file k8s.gcr.io/kube-controller-manager:v1.17.2 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-controller-manager_v1.17.2 succeeded
I0410 00:59:03.742962 1547137 cache.go:99] /home/USER/.minikube/cache/images/gcr.io/k8s-minikube/storage-provisioner_v1.8.1 exists
I0410 00:59:03.742960 1547137 cache.go:80] cache image "kubernetesui/metrics-scraper:v1.0.2" -> "/home/USER/.minikube/cache/images/kubernetesui/metrics-scraper_v1.0.2" took 640.997µs
I0410 00:59:03.742987 1547137 cache.go:80] cache image "gcr.io/k8s-minikube/storage-provisioner:v1.8.1" -> "/home/USER/.minikube/cache/images/gcr.io/k8s-minikube/storage-provisioner_v1.8.1" took 114.609µs
I0410 00:59:03.742846 1547137 lock.go:35] WriteFile acquiring /home/USER/.minikube/profiles/minikube/config.json: {Name:mkcc8cfa21d8e556e316e2fab0384f934d1347a3 Clock:{} Delay:500ms Timeout:1m0s Cancel:<nil>}
I0410 00:59:03.743014 1547137 cache.go:99] /home/USER/.minikube/cache/images/kubernetesui/dashboard_v2.0.0-beta8 exists
I0410 00:59:03.743027 1547137 cache.go:65] save to tar file gcr.io/k8s-minikube/storage-provisioner:v1.8.1 -> /home/USER/.minikube/cache/images/gcr.io/k8s-minikube/storage-provisioner_v1.8.1 succeeded
I0410 00:59:03.742852 1547137 cache.go:80] cache image "k8s.gcr.io/kube-apiserver:v1.17.2" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-apiserver_v1.17.2" took 532.954µs
I0410 00:59:03.743050 1547137 cache.go:65] save to tar file k8s.gcr.io/kube-apiserver:v1.17.2 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-apiserver_v1.17.2 succeeded
I0410 00:59:03.742994 1547137 cache.go:65] save to tar file kubernetesui/metrics-scraper:v1.0.2 -> /home/USER/.minikube/cache/images/kubernetesui/metrics-scraper_v1.0.2 succeeded
I0410 00:59:03.742937 1547137 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/kube-scheduler_v1.17.2 exists
I0410 00:59:03.743090 1547137 cache.go:80] cache image "k8s.gcr.io/kube-scheduler:v1.17.2" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/kube-scheduler_v1.17.2" took 338.168µs
I0410 00:59:03.743110 1547137 cache.go:65] save to tar file k8s.gcr.io/kube-scheduler:v1.17.2 -> /home/USER/.minikube/cache/images/k8s.gcr.io/kube-scheduler_v1.17.2 succeeded
I0410 00:59:03.742815 1547137 cache.go:91] acquiring lock: {Name:mke10f635da4049366f93d2e10938d3e68ae6dda Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742341 1547137 cache.go:91] acquiring lock: {Name:mk499f6775c5d9d431ec39733f002257d420bc42 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.742696 1547137 cache.go:91] acquiring lock: {Name:mk30d2f5a9ac3344f10eeb9d9f0dc7a231219f9d Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0410 00:59:03.743193 1547137 start.go:215] acquiring machines lock for minikube: {Name:mk75de6b7c3cc6b2056966c4f31563e893af7c7a Clock:{} Delay:500ms Timeout:15m0s Cancel:<nil>}
I0410 00:59:03.743040 1547137 cache.go:80] cache image "kubernetesui/dashboard:v2.0.0-beta8" -> "/home/USER/.minikube/cache/images/kubernetesui/dashboard_v2.0.0-beta8" took 165.033µs
I0410 00:59:03.743239 1547137 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/pause_3.1 exists
I0410 00:59:03.743294 1547137 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/etcd_3.4.3-0 exists
I0410 00:59:03.743325 1547137 cache.go:80] cache image "k8s.gcr.io/etcd:3.4.3-0" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/etcd_3.4.3-0" took 513.887µs
I0410 00:59:03.743294 1547137 cache.go:80] cache image "k8s.gcr.io/pause:3.1" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/pause_3.1" took 959.96µs
I0410 00:59:03.743348 1547137 cache.go:65] save to tar file k8s.gcr.io/etcd:3.4.3-0 -> /home/USER/.minikube/cache/images/k8s.gcr.io/etcd_3.4.3-0 succeeded
I0410 00:59:03.743270 1547137 start.go:219] acquired machines lock for "minikube" in 40.437µs
I0410 00:59:03.743361 1547137 cache.go:65] save to tar file k8s.gcr.io/pause:3.1 -> /home/USER/.minikube/cache/images/k8s.gcr.io/pause_3.1 succeeded
I0410 00:59:03.743248 1547137 cache.go:65] save to tar file kubernetesui/dashboard:v2.0.0-beta8 -> /home/USER/.minikube/cache/images/kubernetesui/dashboard_v2.0.0-beta8 succeeded
I0410 00:59:03.743239 1547137 cache.go:99] /home/USER/.minikube/cache/images/k8s.gcr.io/coredns_1.6.5 exists
I0410 00:59:03.743384 1547137 start.go:81] Provisioning new machine with config: {Name:minikube KeepContext:false EmbedCerts:false MinikubeISO:https://storage.googleapis.com/minikube/iso/minikube-v1.7.0.iso Memory:2000 CPUs:2 DiskSize:20000 VMDriver:kvm2 HyperkitVpnKitSock: HyperkitVSockPorts:[] DockerEnv:[] InsecureRegistry:[] RegistryMirror:[] HostOnlyCIDR:192.168.99.1/24 HypervVirtualSwitch: KVMNetwork:default KVMQemuURI:qemu:///system KVMGPU:false KVMHidden:false Downloader:{} DockerOpt:[] DisableDriverMounts:false NFSShare:[] NFSSharesRoot:/nfsshares UUID: NoVTXCheck:false DNSProxy:false HostDNSResolver:true HostOnlyNicType:virtio NatNicType:virtio KubernetesConfig:{KubernetesVersion:v1.17.2 ClusterName:minikube APIServerName:minikubeCA APIServerNames:[] APIServerIPs:[] DNSDomain:cluster.local ContainerRuntime:docker CRISocket: NetworkPlugin: FeatureGates: ServiceCIDR:10.96.0.0/12 ImageRepository: ExtraOptions:[] ShouldLoadCachedImages:true EnableDefaultCNI:false} Nodes:[{Name:minikube IP: Port:8443 KubernetesVersion:v1.17.2 ControlPlane:true Worker:true}] Addons:map[]}
I0410 00:59:03.743460 1547137 cache.go:80] cache image "k8s.gcr.io/coredns:1.6.5" -> "/home/USER/.minikube/cache/images/k8s.gcr.io/coredns_1.6.5" took 1.023095ms
I0410 00:59:03.743471 1547137 start.go:100] createHost starting for "minikube" (driver="kvm2")
I0410 00:59:03.743482 1547137 cache.go:65] save to tar file k8s.gcr.io/coredns:1.6.5 -> /home/USER/.minikube/cache/images/k8s.gcr.io/coredns_1.6.5 succeeded
I0410 00:59:03.743501 1547137 cache.go:72] Successfully saved all images to host disk.
🔥  Creating kvm2 VM (CPUs=2, Memory=2000MB, Disk=20000MB) ...
I0410 00:59:03.744358 1547137 main.go:110] libmachine: Found binary path at /home/USER/.minikube/bin/docker-machine-driver-kvm2
I0410 00:59:03.744394 1547137 main.go:110] libmachine: Launching plugin server for driver kvm2
I0410 00:59:03.758589 1547137 main.go:110] libmachine: Plugin server listening at address 127.0.0.1:42811
I0410 00:59:03.759095 1547137 main.go:110] libmachine: () Calling .GetVersion
I0410 00:59:03.759901 1547137 main.go:110] libmachine: Using API Version  1
I0410 00:59:03.759934 1547137 main.go:110] libmachine: () Calling .SetConfigRaw
I0410 00:59:03.760470 1547137 main.go:110] libmachine: () Calling .GetMachineName
I0410 00:59:03.760693 1547137 main.go:110] libmachine: (minikube) Calling .GetMachineName
I0410 00:59:03.760891 1547137 main.go:110] libmachine: (minikube) Calling .DriverName
I0410 00:59:03.761118 1547137 start.go:133] libmachine.API.Create for "minikube" (driver="kvm2")
I0410 00:59:03.761173 1547137 main.go:110] libmachine: Reading certificate data from /home/USER/.minikube/certs/ca.pem
I0410 00:59:03.770223 1547137 main.go:110] libmachine: Decoding PEM data...
I0410 00:59:03.770268 1547137 main.go:110] libmachine: Parsing certificate...
I0410 00:59:03.770511 1547137 main.go:110] libmachine: Reading certificate data from /home/USER/.minikube/certs/cert.pem
I0410 00:59:03.775314 1547137 main.go:110] libmachine: Decoding PEM data...
I0410 00:59:03.775360 1547137 main.go:110] libmachine: Parsing certificate...
I0410 00:59:03.775476 1547137 main.go:110] libmachine: Running pre-create checks...
I0410 00:59:03.775499 1547137 main.go:110] libmachine: (minikube) Calling .PreCreateCheck
I0410 00:59:03.776004 1547137 main.go:110] libmachine: (minikube) Calling .GetConfigRaw
I0410 00:59:03.776869 1547137 main.go:110] libmachine: Creating machine...
I0410 00:59:03.776910 1547137 main.go:110] libmachine: (minikube) Calling .Create
I0410 00:59:03.777270 1547137 main.go:110] libmachine: (minikube) Creating KVM machine...
I0410 00:59:04.032174 1547137 main.go:110] libmachine: (minikube) Setting up store path in /home/USER/.minikube/machines/minikube ...
I0410 00:59:04.032227 1547137 main.go:110] libmachine: (minikube) Building disk image from file:///home/USER/.minikube/cache/iso/minikube-v1.7.0.iso
I0410 00:59:04.032301 1547137 main.go:110] libmachine: (minikube) DBG | ERROR: logging before flag.Parse: I0410 00:59:04.032126 1547175 common.go:99] Making disk image using store path: /home/USER/.minikube
I0410 00:59:04.032371 1547137 main.go:110] libmachine: (minikube) Downloading /home/USER/.minikube/cache/boot2docker.iso from file:///home/USER/.minikube/cache/iso/minikube-v1.7.0.iso...
I0410 00:59:04.535881 1547137 main.go:110] libmachine: (minikube) DBG | ERROR: logging before flag.Parse: I0410 00:59:04.535735 1547175 common.go:106] Creating ssh key: /home/USER/.minikube/machines/minikube/id_rsa...
I0410 00:59:04.746252 1547137 main.go:110] libmachine: (minikube) DBG | ERROR: logging before flag.Parse: I0410 00:59:04.746160 1547175 common.go:112] Creating raw disk image: /home/USER/.minikube/machines/minikube/minikube.rawdisk...
I0410 00:59:04.746287 1547137 main.go:110] libmachine: (minikube) DBG | Writing magic tar header
I0410 00:59:04.746302 1547137 main.go:110] libmachine: (minikube) DBG | Writing SSH key tar header
I0410 01:03:53.927097 1547137 main.go:110] libmachine: (minikube) DBG | ERROR: logging before flag.Parse: I0410 01:03:53.926898 1547175 common.go:126] Fixing permissions on /home/USER/.minikube/machines/minikube ...
I0410 01:03:53.927247 1547137 main.go:110] libmachine: (minikube) DBG | Checking permissions on dir: /home/USER/.minikube/machines/minikube
I0410 01:03:53.927311 1547137 main.go:110] libmachine: (minikube) Setting executable bit set on /home/USER/.minikube/machines/minikube (perms=drwx------)
I0410 01:03:53.927350 1547137 main.go:110] libmachine: (minikube) DBG | Checking permissions on dir: /home/USER/.minikube/machines
I0410 01:03:53.927409 1547137 main.go:110] libmachine: (minikube) DBG | Checking permissions on dir: /home/USER/.minikube
I0410 01:03:53.927450 1547137 main.go:110] libmachine: (minikube) DBG | Checking permissions on dir: /home/USER
I0410 01:03:53.927488 1547137 main.go:110] libmachine: (minikube) Setting executable bit set on /home/USER/.minikube/machines (perms=drwxr-xr-x)
I0410 01:03:53.927543 1547137 main.go:110] libmachine: (minikube) Setting executable bit set on /home/USER/.minikube (perms=drwxr-xr-x)
I0410 01:03:53.927590 1547137 main.go:110] libmachine: (minikube) DBG | Checking permissions on dir: /home
I0410 01:03:53.927626 1547137 main.go:110] libmachine: (minikube) Creating domain...
I0410 01:03:53.927673 1547137 main.go:110] libmachine: (minikube) DBG | Skipping /home - not owner
I0410 01:03:55.025875 1547137 main.go:110] libmachine: (minikube) Creating network...
I0410 01:03:55.030470 1547137 main.go:110] libmachine: (minikube) Ensuring networks are active...
I0410 01:03:55.035331 1547137 main.go:110] libmachine: (minikube) Ensuring network default is active
I0410 01:03:55.035938 1547137 main.go:110] libmachine: (minikube) Ensuring network minikube-net is active
I0410 01:03:55.036669 1547137 main.go:110] libmachine: (minikube) Getting domain xml...
I0410 01:03:55.038572 1547137 main.go:110] libmachine: (minikube) Creating domain...
I0410 01:04:14.623205 1547137 main.go:110] libmachine: (minikube) Waiting to get IP...
I0410 01:04:14.630867 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 0/40
I0410 01:04:17.958224 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 1/40
I0410 01:04:20.963434 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 2/40
I0410 01:04:23.968433 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 3/40
I0410 01:04:26.973359 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 4/40
I0410 01:04:29.978362 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 5/40
I0410 01:04:32.983363 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 6/40
I0410 01:04:35.988664 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 7/40
I0410 01:04:38.993792 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 8/40
I0410 01:04:41.999031 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 9/40
I0410 01:04:45.004345 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 10/40
I0410 01:04:48.009705 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 11/40
I0410 01:04:51.014480 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 12/40
I0410 01:04:54.025527 1547137 main.go:110] libmachine: (minikube) DBG | Waiting for machine to come up 13/40
I0410 01:04:57.057448 1547137 main.go:110] libmachine: (minikube) Found IP for machine: 192.168.39.136
I0410 01:04:57.057523 1547137 main.go:110] libmachine: (minikube) DBG | Getting to WaitForSSH function...
I0410 01:04:57.057570 1547137 main.go:110] libmachine: (minikube) Waiting for SSH to be available...
I0410 01:04:57.081112 1547137 main.go:110] libmachine: (minikube) DBG | Using SSH client type: external
I0410 01:04:57.081171 1547137 main.go:110] libmachine: (minikube) DBG | Using SSH private key: /home/USER/.minikube/machines/minikube/id_rsa (-rw-------)
I0410 01:04:57.081263 1547137 main.go:110] libmachine: (minikube) DBG | &{[-F /dev/null -o ConnectionAttempts=3 -o ConnectTimeout=10 -o ControlMaster=no -o ControlPath=none -o LogLevel=quiet -o PasswordAuthentication=no -o ServerAliveInterval=60 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null docker@192.168.39.136 -o IdentitiesOnly=yes -i /home/USER/.minikube/machines/minikube/id_rsa -p 22] /usr/bin/ssh <nil>}
I0410 01:04:57.081321 1547137 main.go:110] libmachine: (minikube) DBG | About to run SSH command:
I0410 01:04:57.081395 1547137 main.go:110] libmachine: (minikube) DBG | exit 0
I0410 01:04:57.267455 1547137 main.go:110] libmachine: (minikube) DBG | SSH cmd err, output: <nil>: 
I0410 01:04:57.268290 1547137 main.go:110] libmachine: (minikube) KVM machine creation complete!
I0410 01:04:57.268401 1547137 main.go:110] libmachine: (minikube) Calling .GetConfigRaw
I0410 01:04:57.269345 1547137 main.go:110] libmachine: (minikube) Calling .DriverName
I0410 01:04:57.269678 1547137 main.go:110] libmachine: (minikube) Calling .DriverName
I0410 01:04:57.269956 1547137 main.go:110] libmachine: Waiting for machine to be running, this may take a few minutes...
I0410 01:04:57.270002 1547137 main.go:110] libmachine: (minikube) Calling .GetState
I0410 01:04:57.275325 1547137 main.go:110] libmachine: Detecting operating system of created instance...
I0410 01:04:57.275368 1547137 main.go:110] libmachine: Waiting for SSH to be available...
I0410 01:04:57.275402 1547137 main.go:110] libmachine: Getting to WaitForSSH function...
I0410 01:04:57.275436 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHHostname
I0410 01:04:57.283835 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHPort
I0410 01:04:57.284096 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHKeyPath
I0410 01:04:57.284400 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHKeyPath
I0410 01:04:57.284613 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHUsername
I0410 01:04:57.284931 1547137 main.go:110] libmachine: Using SSH client type: native
I0410 01:04:57.316917 1547137 main.go:110] libmachine: &{{{<nil> 0 [] [] []} docker [0x7b6460] 0x7b6430 <nil>  [] 0s} 192.168.39.136 22 <nil> <nil>}
I0410 01:04:57.316968 1547137 main.go:110] libmachine: About to run SSH command:
exit 0
I0410 01:04:57.510397 1547137 main.go:110] libmachine: SSH cmd err, output: <nil>: 
I0410 01:04:57.510456 1547137 main.go:110] libmachine: Detecting the provisioner...
I0410 01:04:57.510551 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHHostname
I0410 01:04:57.521364 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHPort
I0410 01:04:57.521731 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHKeyPath
I0410 01:04:57.522030 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHKeyPath
I0410 01:04:57.522335 1547137 main.go:110] libmachine: (minikube) Calling .GetSSHUsername
I0410 01:04:57.522675 1547137 main.go:110] libmachine: Using SSH client type: native
I0410 01:04:57.523026 1547137 main.go:110] libmachine: &{{{<nil> 0 [] [] []} docker [0x7b6460] 0x7b6430 <nil>  [] 0s} 192.168.39.136 22 <nil> <nil>}
I0410 01:04:57.523059 1547137 main.go:110] libmachine: About to run SSH command:
cat /etc/os-release
I0410 01:04:57.657033 1547137 main.go:110] libmachine: SSH cmd err, output: <nil>: NAME=Buildroot
VERSION=2019.02.8
ID=buildroot
VERSION_ID=2019.02.8
PRETTY_NAME="Buildroot 2019.02.8"

# continues to setup Kubernetes...

Image sizes

% du -sch ~/.minikube/machines/*
19G  /home/USER/.minikube/machines/minikube
11G  /home/USER/.minikube/machines/minikube173
11G  /home/USER/.minikube/machines/minikube192
40G  total

It seems that 1.7.3 and 1.9.2 images are not as big as they are supposed to be.

Other details

Timeout was introduced in PR #6625 and released in tag v1.7.3.

Ideas for solution

  • add command line option to set or skip the timeout
  • ignore the timeout for interactive sessions
  • Introduce a variable timeout length based on the driver (i.e. expected duration)
@tstromberg tstromberg added kind/support Categorizes issue or PR as a support question. co/kvm2-driver KVM2 driver related issues labels Apr 10, 2020
@tstromberg tstromberg mentioned this issue Apr 10, 2020
Merged
@tstromberg
Copy link
Contributor

I'll send a PR out for a lower-tech solution, just to see if it works. This step typically takes 10 seconds, so normally 2 minutes is enough, and well, 4 minutes should be plenty of time.

@tstromberg
Copy link
Contributor

Do you mind checking if this binary fixes your issue:

https://storage.googleapis.com/minikube-builds/7565/minikube-linux-amd64

@tstromberg tstromberg added the triage/needs-information Indicates an issue needs more information in order to work on it. label Apr 10, 2020
@afbjorklund
Copy link
Collaborator

Hmm, this is supposed to create a sparse image...

It will grow over time (too much*), but not to 20G ?

* see #3155

Which version of libvirt (QEMU and KVM) is this ?

Disk bloat is my main reason for preferring VirtualBox

@afbjorklund
Copy link
Collaborator

You could try inspecting the image (compacting it could also help)

qemu-img info ~/.minikube/machines/minikube/minikube.rawdisk

@raphendyr
Copy link
Author

This setup is at my work computer and I lost access to it, so I get more details next week, when that is fixed.

In my terminal history, the size of minikube.rawdisk is 4,5K from ls -lh and 7,0G from du -sch. so I would presume it to be sparse. On my home computer, qemu-img create -f raw test.rawimg 20G takes no time and creates file of size 20G from ls -lh and 4K from du -sch. This makes me question the setup of my work computer. I'll need to check mount options and if ecryptfs, used for my home at work, has anything to do with this.

Libvirt, qemu and kvm should be versions from Debian testing/unstable, as I just had updated packages, thus libvirt should be v6.Any case, I'll get back to you on these. It could be that qemu-utils package would be old for some reason.

As a side note, I think we should find a way to limit the timeout only for the driver.Start() call. Though, this seems hard, as it is executed as part of Create (ref: kvm.go#L349). I would have presumed, these to be called seperately by machine/start.go.

@tstromberg
Copy link
Contributor

@raphendyr - Thank you for the update. Please let me know if the PR I sent out helps at all.

@medyagh
Copy link
Member

medyagh commented May 13, 2020

@raphendyr have you a chance to try our latest version of minikube to verify this solved your problem?

@medyagh
Copy link
Member

medyagh commented May 28, 2020

@raphendyr haven't heard from you. I will close this please feel free to re-open

@medyagh medyagh closed this as completed May 28, 2020
@raphendyr
Copy link
Author

Sorry, I have not tragged github notifications for a while again...

Any case, I forgot to comment that the creation delay is because ecryptfs must create the full file for parse images due to security reasons. I "fixed" it by creating a symlink from ~/.minikube/machines to non-crypted storage. I would expect this setup to be rare, as full disk encryption is way better option compared to ecryptfs.

The newest minikube (v.1.10.1), still fails due to long image creation time. However, I think the symlink is a viable workaround, unless you want to support encrypting the raw image via ecryptfs mount.

Timestamped log from the last test using minikube v1.10.1 
# minikube start --driver=kvm2 2>&1 | ts '[%Y-%m-%d %H:%M:%S]'
[2020-05-29 13:30:13] * minikube v1.10.1 on Debian bullseye/sid
[2020-05-29 13:30:14] * Using the kvm2 driver based on user configuration
[2020-05-29 13:30:14] * Starting control plane node minikube in cluster minikube
[2020-05-29 13:30:14] * Creating kvm2 VM (CPUs=2, Memory=4000MB, Disk=20000MB) ...
[2020-05-29 13:34:19] ! StartHost failed, but will try again: creating host: create host timed out in 240.000000 seconds
[2020-05-29 13:34:26] * Restarting existing kvm2 VM for "minikube" ...
[2020-05-29 13:34:27] * Failed to start kvm2 VM. "minikube start" may fix it: driver start: getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube'')
[2020-05-29 13:34:27] * 
[2020-05-29 13:34:27] * [KVM2_NO_DOMAIN] error provisioning host Failed to start host: driver start: getting connection: looking up domain: virError(Code=42, Domain=10, Message='Domain not found: no domain with matching name 'minikube'')
[2020-05-29 13:34:27] * Suggestion: The VM that minikube is configured for no longer exists. Run 'minikube delete'
[2020-05-29 13:34:27] * Related issue: https://github.com/kubernetes/minikube/issues/3636

I can personally accept this behaviour, so the issue can stay closed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
co/kvm2-driver KVM2 driver related issues kind/support Categorizes issue or PR as a support question. triage/needs-information Indicates an issue needs more information in order to work on it.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@tstromberg @raphendyr @medyagh @afbjorklund