search

kubernetes / minikube

Run Kubernetes locally
https://minikube.sigs.k8s.io/
Apache License 2.0
29.41k stars 4.88k forks source link

podman start minikube returned with exit code 125 #14424

Closed criztovyl closed 2 years ago

criztovyl commented 2 years ago

What Happened?

When podman fails to start minikubes container, minikube seems to ignore that error and runs into an exponential-backoff retring to ssh into the (failed to start) container.

From reading the source I think the bug is in kic Driver.Start()

https://github.com/kubernetes/minikube/blob/b496d669e79fc0d34fe1309d8c0dfde9c8271f6d/pkg/drivers/kic/kic.go#L399-L407

StartContainer() will properly return the error, and Start() goes into err != nil block as visible in the log (Postmortem inspect). Normally Start() would return errors.Wrap(err, "start"), but:

Attach the log file

I0625 14:29:10.929981   19279 out.go:296] Setting OutFile to fd 1 ...
I0625 14:29:10.930078   19279 out.go:348] isatty.IsTerminal(1) = false
I0625 14:29:10.930081   19279 out.go:309] Setting ErrFile to fd 2...
I0625 14:29:10.930085   19279 out.go:348] isatty.IsTerminal(2) = false
I0625 14:29:10.930181   19279 root.go:322] Updating PATH: /home/christoph/.minikube/bin
I0625 14:29:10.930375   19279 out.go:303] Setting JSON to false
I0625 14:29:10.981845   19279 start.go:115] hostinfo: {"hostname":"chschulz09","uptime":6103,"bootTime":1656154048,"procs":367,"os":"linux","platform":"debian","platformFamily":"debian","platformVersion":"11.3","kernelVersion":"5.16.0-0.bpo.4-amd64","kernelArch":"x86_64","virtualizationSystem":"kvm","virtualizationRole":"host","hostId":"a465be46-8ca1-4342-a4a3-702e04d44bb6"}
I0625 14:29:10.981952   19279 start.go:125] virtualization: kvm host
I0625 14:29:10.983771   19279 out.go:177] * minikube v1.26.0-beta.1 on Debian 11.3
* minikube v1.26.0-beta.1 on Debian 11.3
I0625 14:29:10.985018   19279 out.go:177]   - MINIKUBE_ROOTLESS=true
  - MINIKUBE_ROOTLESS=true
I0625 14:29:10.984937   19279 notify.go:193] Checking for updates...
I0625 14:29:10.986779   19279 config.go:178] Loaded profile config "minikube": Driver=podman, ContainerRuntime=cri-o, KubernetesVersion=v1.23.6
I0625 14:29:10.987846   19279 driver.go:358] Setting default libvirt URI to qemu:///system
I0625 14:29:11.110107   19279 podman.go:123] podman version: 3.0.1
I0625 14:29:11.111567   19279 out.go:177] * Using the podman driver based on existing profile
* Using the podman driver based on existing profile
I0625 14:29:11.112628   19279 start.go:284] selected driver: podman
I0625 14:29:11.112635   19279 start.go:806] validating driver "podman" against &{Name:minikube KeepContext:false EmbedCerts:false MinikubeISO: KicBaseImage:gcr.io/k8s-minikube/kicbase:v0.0.31@sha256:c3375f1b260bd936aa532a0c749626e07d94ab129a7f2395e95345aa04ca708c Memory:4000 CPUs:2 DiskSize:20000 VMDriver: Driver:podman HyperkitVpnKitSock: HyperkitVSockPorts:[] DockerEnv:[] ContainerVolumeMounts:[] InsecureRegistry:[] RegistryMirror:[] HostOnlyCIDR:192.168.59.1/24 HypervVirtualSwitch: HypervUseExternalSwitch:false HypervExternalAdapter: KVMNetwork:default KVMQemuURI:qemu:///system KVMGPU:false KVMHidden:false KVMNUMACount:1 APIServerPort:0 DockerOpt:[] DisableDriverMounts:false NFSShare:[] NFSSharesRoot:/nfsshares UUID: NoVTXCheck:false DNSProxy:false HostDNSResolver:true HostOnlyNicType:virtio NatNicType:virtio SSHIPAddress: SSHUser:root SSHKey: SSHPort:22 KubernetesConfig:{KubernetesVersion:v1.23.6 ClusterName:minikube Namespace:default APIServerName:minikubeCA APIServerNames:[] APIServerIPs:[] DNSDomain:cluster.local ContainerRuntime:cri-o CRISocket: NetworkPlugin:cni FeatureGates:KubeletInUserNamespace=true ServiceCIDR:10.96.0.0/12 ImageRepository: LoadBalancerStartIP: LoadBalancerEndIP: CustomIngressCert: RegistryAliases: ExtraOptions:[{Component:kubelet Key:cni-conf-dir Value:/etc/cni/net.mk}] ShouldLoadCachedImages:true EnableDefaultCNI:false CNI: NodeIP: NodePort:8443 NodeName:} Nodes:[{Name: IP: Port:8443 KubernetesVersion:v1.23.6 ContainerRuntime:crio ControlPlane:true Worker:true}] Addons:map[ambassador:false auto-pause:false csi-hostpath-driver:false dashboard:false default-storageclass:true efk:false freshpod:false gcp-auth:false gvisor:false helm-tiller:false ingress:false ingress-dns:false istio:false istio-provisioner:false kong:false kubevirt:false logviewer:false metallb:false metrics-server:false nvidia-driver-installer:false nvidia-gpu-device-plugin:false olm:false pod-security-policy:false portainer:false registry:false registry-aliases:false registry-creds:false storage-provisioner:true storage-provisioner-gluster:false volumesnapshots:false] CustomAddonImages:map[] CustomAddonRegistries:map[] VerifyComponents:map[apiserver:true system_pods:true] StartHostTimeout:6m0s ScheduledStop:<nil> ExposedPorts:[] ListenAddress: Network: Subnet: MultiNodeRequested:false ExtraDisks:0 CertExpiration:26280h0m0s Mount:false MountString:/home/christoph:/minikube-host Mount9PVersion:9p2000.L MountGID:docker MountIP: MountMSize:262144 MountOptions:[] MountPort:0 MountType:9p MountUID:docker BinaryMirror: DisableOptimizations:false DisableMetrics:false}
I0625 14:29:11.112731   19279 start.go:817] status for podman: {Installed:true Healthy:true Running:false NeedsImprovement:false Error:<nil> Reason: Fix: Doc: Version:}
I0625 14:29:11.112780   19279 cli_runner.go:164] Run: podman system info --format json
I0625 14:29:11.667825   19279 info.go:287] podman info: {Host:{BuildahVersion:1.19.6 CgroupVersion:v2 Conmon:{Package:conmon: /usr/bin/conmon Path:/usr/bin/conmon Version:conmon version 2.0.25, commit: unknown} Distribution:{Distribution:debian Version:11} MemFree:11854430208 MemTotal:16790786048 OCIRuntime:{Name:crun Package:crun: /usr/bin/crun Path:/usr/bin/crun Version:crun version 0.17
commit: 0e9229ae34caaebcb86f1fde18de3acaf18c6d9a
spec: 1.0.0
+SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL} SwapFree:1023406080 SwapTotal:1023406080 Arch:amd64 Cpus:16 Eventlogger:journald Hostname:chschulz09 Kernel:5.16.0-0.bpo.4-amd64 Os:linux Security:{Rootless:true} Uptime:1h 41m 42.57s (Approximately 0.04 days)} Registries:{Search:[]} Store:{ConfigFile:/home/christoph/.config/containers/storage.conf ContainerStore:{Number:5} GraphDriverName:overlay GraphOptions:{} GraphRoot:/home/christoph/.local/share/containers/storage GraphStatus:{BackingFilesystem:extfs NativeOverlayDiff:false SupportsDType:true UsingMetacopy:false} ImageStore:{Number:75} RunRoot:/run/user/1000/containers VolumePath:/home/christoph/.local/share/containers/storage/volumes}}
I0625 14:29:11.669248   19279 cni.go:95] Creating CNI manager for ""
I0625 14:29:11.669258   19279 cni.go:162] "podman" driver + cri-o runtime found, recommending kindnet
I0625 14:29:11.669271   19279 start_flags.go:306] config:
{Name:minikube KeepContext:false EmbedCerts:false MinikubeISO: KicBaseImage:gcr.io/k8s-minikube/kicbase:v0.0.31@sha256:c3375f1b260bd936aa532a0c749626e07d94ab129a7f2395e95345aa04ca708c Memory:4000 CPUs:2 DiskSize:20000 VMDriver: Driver:podman HyperkitVpnKitSock: HyperkitVSockPorts:[] DockerEnv:[] ContainerVolumeMounts:[] InsecureRegistry:[] RegistryMirror:[] HostOnlyCIDR:192.168.59.1/24 HypervVirtualSwitch: HypervUseExternalSwitch:false HypervExternalAdapter: KVMNetwork:default KVMQemuURI:qemu:///system KVMGPU:false KVMHidden:false KVMNUMACount:1 APIServerPort:0 DockerOpt:[] DisableDriverMounts:false NFSShare:[] NFSSharesRoot:/nfsshares UUID: NoVTXCheck:false DNSProxy:false HostDNSResolver:true HostOnlyNicType:virtio NatNicType:virtio SSHIPAddress: SSHUser:root SSHKey: SSHPort:22 KubernetesConfig:{KubernetesVersion:v1.23.6 ClusterName:minikube Namespace:default APIServerName:minikubeCA APIServerNames:[] APIServerIPs:[] DNSDomain:cluster.local ContainerRuntime:cri-o CRISocket: NetworkPlugin:cni FeatureGates:KubeletInUserNamespace=true ServiceCIDR:10.96.0.0/12 ImageRepository: LoadBalancerStartIP: LoadBalancerEndIP: CustomIngressCert: RegistryAliases: ExtraOptions:[{Component:kubelet Key:cni-conf-dir Value:/etc/cni/net.mk}] ShouldLoadCachedImages:true EnableDefaultCNI:false CNI: NodeIP: NodePort:8443 NodeName:} Nodes:[{Name: IP: Port:8443 KubernetesVersion:v1.23.6 ContainerRuntime:crio ControlPlane:true Worker:true}] Addons:map[ambassador:false auto-pause:false csi-hostpath-driver:false dashboard:false default-storageclass:true efk:false freshpod:false gcp-auth:false gvisor:false helm-tiller:false ingress:false ingress-dns:false istio:false istio-provisioner:false kong:false kubevirt:false logviewer:false metallb:false metrics-server:false nvidia-driver-installer:false nvidia-gpu-device-plugin:false olm:false pod-security-policy:false portainer:false registry:false registry-aliases:false registry-creds:false storage-provisioner:true storage-provisioner-gluster:false volumesnapshots:false] CustomAddonImages:map[] CustomAddonRegistries:map[] VerifyComponents:map[apiserver:true system_pods:true] StartHostTimeout:6m0s ScheduledStop:<nil> ExposedPorts:[] ListenAddress: Network: Subnet: MultiNodeRequested:false ExtraDisks:0 CertExpiration:26280h0m0s Mount:false MountString:/home/christoph:/minikube-host Mount9PVersion:9p2000.L MountGID:docker MountIP: MountMSize:262144 MountOptions:[] MountPort:0 MountType:9p MountUID:docker BinaryMirror: DisableOptimizations:false DisableMetrics:false}
I0625 14:29:11.671520   19279 out.go:177] * Starting control plane node minikube in cluster minikube
* Starting control plane node minikube in cluster minikube
I0625 14:29:11.672617   19279 cache.go:120] Beginning downloading kic base image for podman with cri-o
I0625 14:29:11.673709   19279 out.go:177] * Pulling base image ...
* Pulling base image ...
I0625 14:29:11.674776   19279 preload.go:132] Checking if preload exists for k8s version v1.23.6 and runtime cri-o
I0625 14:29:11.674799   19279 preload.go:148] Found local preload: /home/christoph/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v18-v1.23.6-cri-o-overlay-amd64.tar.lz4
I0625 14:29:11.674800   19279 cache.go:146] Downloading gcr.io/k8s-minikube/kicbase:v0.0.31@sha256:c3375f1b260bd936aa532a0c749626e07d94ab129a7f2395e95345aa04ca708c to local cache
I0625 14:29:11.674805   19279 cache.go:57] Caching tarball of preloaded images
I0625 14:29:11.674954   19279 image.go:59] Checking for gcr.io/k8s-minikube/kicbase:v0.0.31@sha256:c3375f1b260bd936aa532a0c749626e07d94ab129a7f2395e95345aa04ca708c in local cache directory
I0625 14:29:11.674968   19279 image.go:62] Found gcr.io/k8s-minikube/kicbase:v0.0.31@sha256:c3375f1b260bd936aa532a0c749626e07d94ab129a7f2395e95345aa04ca708c in local cache directory, skipping pull
I0625 14:29:11.674972   19279 image.go:103] gcr.io/k8s-minikube/kicbase:v0.0.31@sha256:c3375f1b260bd936aa532a0c749626e07d94ab129a7f2395e95345aa04ca708c exists in cache, skipping pull
I0625 14:29:11.674984   19279 cache.go:149] successfully saved gcr.io/k8s-minikube/kicbase:v0.0.31@sha256:c3375f1b260bd936aa532a0c749626e07d94ab129a7f2395e95345aa04ca708c as a tarball
I0625 14:29:11.675002   19279 preload.go:174] Found /home/christoph/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v18-v1.23.6-cri-o-overlay-amd64.tar.lz4 in cache, skipping download
I0625 14:29:11.675038   19279 cache.go:60] Finished verifying existence of preloaded tar for  v1.23.6 on cri-o
I0625 14:29:11.675251   19279 profile.go:148] Saving config to /home/christoph/.minikube/profiles/minikube/config.json ...
E0625 14:29:11.675565   19279 cache.go:201] Error downloading kic artifacts:  not yet implemented, see issue #8426
I0625 14:29:11.675584   19279 cache.go:206] Successfully downloaded all kic artifacts
I0625 14:29:11.675619   19279 start.go:352] acquiring machines lock for minikube: {Name:mk3eef0fe0f53c243a6ede0eadea1be70e8391e7 Clock:{} Delay:500ms Timeout:10m0s Cancel:<nil>}
I0625 14:29:11.675722   19279 start.go:356] acquired machines lock for "minikube" in 73.057µs
I0625 14:29:11.675748   19279 start.go:94] Skipping create...Using existing machine configuration
I0625 14:29:11.675759   19279 fix.go:55] fixHost starting: 
I0625 14:29:11.676138   19279 cli_runner.go:164] Run: podman container inspect minikube --format={{.State.Status}}
I0625 14:29:11.791539   19279 fix.go:103] recreateIfNeeded on minikube: state=Stopped err=<nil>
W0625 14:29:11.791577   19279 fix.go:129] unexpected machine state, will restart: <nil>
I0625 14:29:11.794074   19279 out.go:177] * Restarting existing podman container for "minikube" ...
* Restarting existing podman container for "minikube" ...
I0625 14:29:11.795265   19279 cli_runner.go:164] Run: podman start minikube
W0625 14:29:12.917683   19279 cli_runner.go:211] podman start minikube returned with exit code 125
I0625 14:29:12.917708   19279 cli_runner.go:217] Completed: podman start minikube: (1.122382304s)
I0625 14:29:12.917774   19279 cli_runner.go:164] Run: podman inspect minikube
I0625 14:29:13.060958   19279 errors.go:84] Postmortem inspect ("podman inspect minikube"): -- stdout --

--%<--

-- /stdout --
I0625 14:29:13.061094   19279 cli_runner.go:164] Run: podman logs --timestamps minikube
I0625 14:29:13.178909   19279 errors.go:91] Postmortem logs ("podman logs --timestamps minikube"): -- stdout --

--%<--

-- /stdout --
I0625 14:29:13.180886   19279 cli_runner.go:164] Run: podman system info --format json
I0625 14:29:13.651054   19279 info.go:287] podman info: {Host:{BuildahVersion:1.19.6 CgroupVersion:v2 Conmon:{Package:conmon: /usr/bin/conmon Path:/usr/bin/conmon Version:conmon version 2.0.25, commit: unknown} Distribution:{Distribution:debian Version:11} MemFree:11860348928 MemTotal:16790786048 OCIRuntime:{Name:crun Package:crun: /usr/bin/crun Path:/usr/bin/crun Version:crun version 0.17
commit: 0e9229ae34caaebcb86f1fde18de3acaf18c6d9a
spec: 1.0.0
+SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL} SwapFree:1023406080 SwapTotal:1023406080 Arch:amd64 Cpus:16 Eventlogger:journald Hostname:chschulz09 Kernel:5.16.0-0.bpo.4-amd64 Os:linux Security:{Rootless:true} Uptime:1h 41m 44.59s (Approximately 0.04 days)} Registries:{Search:[]} Store:{ConfigFile:/home/christoph/.config/containers/storage.conf ContainerStore:{Number:5} GraphDriverName:overlay GraphOptions:{} GraphRoot:/home/christoph/.local/share/containers/storage GraphStatus:{BackingFilesystem:extfs NativeOverlayDiff:false SupportsDType:true UsingMetacopy:false} ImageStore:{Number:75} RunRoot:/run/user/1000/containers VolumePath:/home/christoph/.local/share/containers/storage/volumes}}
I0625 14:29:13.651135   19279 errors.go:106] postmortem podman info: {Host:{BuildahVersion:1.19.6 CgroupVersion:v2 Conmon:{Package:conmon: /usr/bin/conmon Path:/usr/bin/conmon Version:conmon version 2.0.25, commit: unknown} Distribution:{Distribution:debian Version:11} MemFree:11860348928 MemTotal:16790786048 OCIRuntime:{Name:crun Package:crun: /usr/bin/crun Path:/usr/bin/crun Version:crun version 0.17
commit: 0e9229ae34caaebcb86f1fde18de3acaf18c6d9a
spec: 1.0.0
+SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL} SwapFree:1023406080 SwapTotal:1023406080 Arch:amd64 Cpus:16 Eventlogger:journald Hostname:chschulz09 Kernel:5.16.0-0.bpo.4-amd64 Os:linux Security:{Rootless:true} Uptime:1h 41m 44.59s (Approximately 0.04 days)} Registries:{Search:[]} Store:{ConfigFile:/home/christoph/.config/containers/storage.conf ContainerStore:{Number:5} GraphDriverName:overlay GraphOptions:{} GraphRoot:/home/christoph/.local/share/containers/storage GraphStatus:{BackingFilesystem:extfs NativeOverlayDiff:false SupportsDType:true UsingMetacopy:false} ImageStore:{Number:75} RunRoot:/run/user/1000/containers VolumePath:/home/christoph/.local/share/containers/storage/volumes}}
I0625 14:29:13.651230   19279 network_create.go:272] running [podman network inspect minikube] to gather additional debugging logs...
I0625 14:29:13.651268   19279 cli_runner.go:164] Run: podman network inspect minikube
I0625 14:29:13.747792   19279 network_create.go:277] output of [podman network inspect minikube]: -- stdout --

--%<--

-- /stdout --
I0625 14:29:13.747908   19279 cli_runner.go:164] Run: podman system info --format json
I0625 14:29:14.235527   19279 info.go:287] podman info: {Host:{BuildahVersion:1.19.6 CgroupVersion:v2 Conmon:{Package:conmon: /usr/bin/conmon Path:/usr/bin/conmon Version:conmon version 2.0.25, commit: unknown} Distribution:{Distribution:debian Version:11} MemFree:11852939264 MemTotal:16790786048 OCIRuntime:{Name:crun Package:crun: /usr/bin/crun Path:/usr/bin/crun Version:crun version 0.17
commit: 0e9229ae34caaebcb86f1fde18de3acaf18c6d9a
spec: 1.0.0
+SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +YAJL} SwapFree:1023406080 SwapTotal:1023406080 Arch:amd64 Cpus:16 Eventlogger:journald Hostname:chschulz09 Kernel:5.16.0-0.bpo.4-amd64 Os:linux Security:{Rootless:true} Uptime:1h 41m 45.17s (Approximately 0.04 days)} Registries:{Search:[]} Store:{ConfigFile:/home/christoph/.config/containers/storage.conf ContainerStore:{Number:5} GraphDriverName:overlay GraphOptions:{} GraphRoot:/home/christoph/.local/share/containers/storage GraphStatus:{BackingFilesystem:extfs NativeOverlayDiff:false SupportsDType:true UsingMetacopy:false} ImageStore:{Number:75} RunRoot:/run/user/1000/containers VolumePath:/home/christoph/.local/share/containers/storage/volumes}}
I0625 14:29:14.236140   19279 cli_runner.go:164] Run: podman container inspect -f {{.NetworkSettings.IPAddress}} minikube
I0625 14:29:14.370069   19279 cli_runner.go:164] Run: podman container inspect -f "{{range .NetworkSettings.Networks}}{{.IPAddress}},{{.GlobalIPv6Address}}{{end}}" minikube
I0625 14:29:14.506441   19279 profile.go:148] Saving config to /home/christoph/.minikube/profiles/minikube/config.json ...
I0625 14:29:14.506780   19279 machine.go:88] provisioning docker machine ...
I0625 14:29:14.506824   19279 ubuntu.go:169] provisioning hostname "minikube"
I0625 14:29:14.506897   19279 cli_runner.go:164] Run: podman version --format {{.Version}}
I0625 14:29:14.617884   19279 cli_runner.go:164] Run: podman container inspect -f "'{{(index (index .NetworkSettings.Ports "22/tcp") 0).HostPort}}'" minikube
I0625 14:29:14.767387   19279 main.go:134] libmachine: Using SSH client type: native
I0625 14:29:14.767579   19279 main.go:134] libmachine: &{{{<nil> 0 [] [] []} docker [0x7da240] 0x7dd2a0 <nil>  [] 0s} 127.0.0.1 42477 <nil> <nil>}
I0625 14:29:14.767596   19279 main.go:134] libmachine: About to run SSH command:
sudo hostname minikube && echo "minikube" | sudo tee /etc/hostname
I0625 14:29:14.767795   19279 main.go:134] libmachine: Error dialing TCP: dial tcp 127.0.0.1:42477: connect: connection refused
I0625 14:29:17.769437   19279 main.go:134] libmachine: Error dialing TCP: dial tcp 127.0.0.1:42477: connect: connection refused

Operating System

Other (Debian)

Driver

Podman

criztovyl commented 2 years ago

Isn't this a bug, not support?

criztovyl commented 2 years ago

while trying to reproduce today my podman container started successfully (the podman bug i am sometimes running into did not occur), but I submitted the PR above that should fix what I discovered.

I'll report back when I can verify it with a container that fails to start.

ramchandh-narayanasamy commented 2 months ago

minikube start --nodes=4 😄 minikube v1.33.1 on Darwin 14.3 (arm64) ▪ MINIKUBE_ROOTLESS=true ✨ Using the podman (experimental) driver based on existing profile ❗ You cannot change the number of nodes for an existing minikube cluster. Please use 'minikube node add' to add nodes to an existing cluster. 👍 Starting "minikube" primary control-plane node in "minikube" cluster 🚜 Pulling base image v0.0.44 ... E0830 13:46:25.454194 3401 cache.go:189] Error downloading kic artifacts: not yet implemented, see issue #8426 🔄 Restarting existing podman container for "minikube" ... 🤦 StartHost failed, but will try again: driver start: start: podman start minikube: exit status 125 stdout:

stderr: Error: no container with name or ID "minikube" found: no such container

🔄 Restarting existing podman container for "minikube" ... 😿 Failed to start podman container. Running "minikube delete" may fix it: driver start: start: podman start minikube: exit status 125 stdout:

stderr: Error: no container with name or ID "minikube" found: no such container

❌ Exiting due to GUEST_PROVISION: error provisioning guest: Failed to start host: driver start: start: podman start minikube: exit status 125 stdout:

stderr: Error: no container with name or ID "minikube" found: no such container

╭───────────────────────────────────────────────────────────────────────────────────────────╮ │ │ │ 😿 If the above advice does not help, please let us know: │ │ 👉 https://github.com/kubernetes/minikube/issues/new/choose │ │ │ │ Please run minikube logs --file=logs.txt and attach logs.txt to the GitHub issue. │ │ │ ╰───────────────────────────────────────────────────────────────────────────────────────────╯

I am getting this, can anyone help me to sort this out

MacOS Podman

criztovyl commented 1 month ago

looks unrelated to this issue, if this still occurs, please open a new one.