Unable to load cached images

[spowelljr]

Occasionally when starting minikube I see the error:
❌ Unable to load cached images: loading cached images: stat /Users/powellsteven/.minikube/cache/images/arm64/registry.k8s.io/kube-controller-manager_v1.25.3: no such file or directory

I have two ideas of what's happening

1. docker images fails as docker may not have finished restarting
2. The preload untar/download is failing

I've unfortunately not saved the logs and the failure is very flakey and haven't been able to reproduce it. So if anyone runs into this please run minikube logs --file=logs.txt and upload your logs.

Possibility of docker images failing

minikube/pkg/minikube/bootstrapper/kubeadm/kubeadm.go

Lines 922 to 930 in 074e681

	if err := r.Preload(cfg); err != nil {
	klog.Infof("preload failed, will try to load cached images: %v", err)
	}
	if cfg.KubernetesConfig.ShouldLoadCachedImages {
	if err := machine.LoadCachedImages(&cfg, k.c, images, detect.ImageCacheDir(), false); err != nil {
	out.FailureT("Unable to load cached images: {{.error}}", out.V{"error": err})
	}
	}

minikube/pkg/minikube/cruntime/docker.go

Lines 597 to 612 in 074e681

	return r.Restart()
	}
	// dockerImagesPreloaded returns true if all images have been preloaded
	func dockerImagesPreloaded(runner command.Runner, images []string) bool {
	rr, err := runner.RunCmd(exec.Command("docker", "images", "--format", "{{.Repository}}:{{.Tag}}"))
	if err != nil {
	return false
	}
	preloadedImages := map[string]struct{}{}
	for _, i := range strings.Split(rr.Stdout.String(), "\n") {
	i = image.TrimDockerIO(i)
	preloadedImages[i] = struct{}{}
	}
	klog.Infof("Got preloaded images: %s", rr.Output())

When starting the cluster the preload is downloaded and then try to load cached images. At the end of the preload step docker is restarted. During the load cached images step docker images is ran and then we check if all the expected images are present. If the docker images command fails we return false and try loading images from cache but most people don't have images cached as they're using preloads, which is what causes the error being printed. An improvement we can do here is log the failure or docker images instead of just returning false.

If we have a log file we can confirm this by the absence of Got preloaded images in the logs which would indicate the docker images command failed.

Possibility of preload failing

minikube/pkg/minikube/bootstrapper/kubeadm/kubeadm.go

Lines 922 to 924 in 074e681

	if err := r.Preload(cfg); err != nil {
	klog.Infof("preload failed, will try to load cached images: %v", err)
	}

minikube/pkg/minikube/cruntime/docker.go

Lines 614 to 619 in 074e681

	// Make sure images == imgs
	for _, i := range images {
	i = image.TrimDockerIO(i)
	if _, ok := preloadedImages[i]; !ok {
	klog.Infof("%s wasn't preloaded", i)
	return false

It's possible that the preload download and untarring is failing. If the preload step fails we don't stop execution, we just log it as info, then starting the loading from cache step. If the tar failed there will be no images present and the log Got preloaded images should be empty along with multiple %s wasn't preloaded.

[spowelljr]

Just got it to fail!

I1028 15:04:33.891879   45695 docker.go:613] Got preloaded images:
I1028 15:04:33.891885   45695 docker.go:619] registry.k8s.io/kube-apiserver:v1.25.3 wasn't preloaded

So the preload download/untar is failing, investigating further.

[spowelljr]

It seems the download is failing

W1028 15:04:33.907102   45695 vm_assets.go:171] NewFileAsset: /Users/powellsteven/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v18-v1.25.3-docker-overlay2-arm64.tar.lz4 is an empty file!
I1028 15:04:33.907159   45695 ssh_runner.go:362] scp /Users/powellsteven/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v18-v1.25.3-docker-overlay2-arm64.tar.lz4 --> /preloaded.tar.lz4 (0 bytes)
W1028 15:04:33.907163   45695 ssh_runner.go:364] 0 byte asset: &{BaseAsset:{SourcePath:/Users/powellsteven/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v18-v1.25.3-docker-overlay2-arm64.tar.lz4 TargetDir:/ TargetName:preloaded.tar.lz4 Permissions:0644 Source:} reader:0x14000aff620 writer:<nil> file:0x140005a60a8}
W1028 15:04:33.909567   45695 ssh_runner.go:393] asked to copy a 0 byte asset: &{BaseAsset:{SourcePath:/Users/powellsteven/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v18-v1.25.3-docker-overlay2-arm64.tar.lz4 TargetDir:/ TargetName:preloaded.tar.lz4 Permissions:0644 Source:} reader:0x14000aff620 writer:<nil> file:0x140005a60a8}
I1028 15:04:33.927724   45695 docker.go:577] Took 0.020529 seconds to copy over tarball

-rw-r--r--  1 powellsteven  primarygroup    0 Oct 28 14:57 preloaded-images-k8s-v18-v1.25.3-docker-overlay2-arm64.tar.lz4
-rw-r--r--  1 powellsteven  primarygroup   16 Oct 28 14:30 preloaded-images-k8s-v18-v1.25.3-docker-overlay2-arm64.tar.lz4.checksum

[spowelljr]

I1028 15:04:27.446225   45695 preload.go:132] Checking if preload exists for k8s version v1.25.3 and runtime docker
I1028 15:04:27.446253   45695 image.go:76] Checking for gcr.io/k8s-minikube/kicbase-builds:v0.0.35-1666722858-15219@sha256:8debc1b6a335075c5f99bfbf131b4f5566f68c6500dc5991817832e55fcc9456 in local docker daemon
I1028 15:04:27.446280   45695 preload.go:148] Found local preload: /Users/powellsteven/.minikube/cache/preloaded-tarball/preloaded-images-k8s-v18-v1.25.3-docker-overlay2-arm64.tar.lz4

It wasn't downloaded on this start, and the previous start was fine, so between the previous start and delete the contents of the preload was wiped. I may have ctrl+C the previous run, can't remember, but might be part of the puzzle.