minikube addons enable registry doesn't work - timeout

[nicolasduminil]

Steps to reproduce the issue:

1. $ minikube start
   😄 minikube v1.14.0 on Ubuntu 20.04
   ✨ Automatically selected the docker driver
   👍 Starting control plane node minikube in cluster minikube
   🔥 Creating docker container (CPUs=2, Memory=7900MB) ...
   🐳 Preparing Kubernetes v1.19.2 on Docker 19.03.8 ...
   🔎 Verifying Kubernetes components...
   🌟 Enabled addons: storage-provisioner, default-storageclass

❗ /home/nicolas/google-cloud-sdk/bin/kubectl is version 1.16.13-dispatcher, which may have incompatibilites with Kubernetes 1.19.2.
💡 Want kubectl v1.19.2? Try 'minikube kubectl -- get pods -A'
🏄 Done! kubectl is now configured to use "minikube" by default

2. $ minikube addons enable registry
   🔎 Verifying registry addon...

❌ Exiting due to MK_ENABLE: run callbacks: running callbacks: [verifying registry addon pods : timed out waiting for the condition: timed out waiting for the condition]

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

[nicolasduminil]

The full output with --alsologtostderr

I1021 17:41:58.292413 41687 addons.go:55] Setting registry=true in profile "minikube"
I1021 17:41:58.292430 41687 addons.go:131] Setting addon registry=true in "minikube"
I1021 17:41:58.292445 41687 host.go:65] Checking if "minikube" exists ...
I1021 17:41:58.292835 41687 cli_runner.go:110] Run: docker container inspect minikube --format={{.State.Status}}
I1021 17:41:58.322015 41687 addons.go:243] installing /etc/kubernetes/addons/registry-rc.yaml
I1021 17:41:58.322070 41687 ssh_runner.go:215] scp deploy/addons/registry/registry-rc.yaml.tmpl --> /etc/kubernetes/addons/registry-rc.yaml (748 bytes)
I1021 17:41:58.322158 41687 cli_runner.go:110] Run: docker container inspect -f "'{{(index (index .NetworkSettings.Ports "22/tcp") 0).HostPort}}'" minikube
I1021 17:41:58.350103 41687 sshutil.go:44] new ssh client: &{IP:127.0.0.1 Port:9015 SSHKeyPath:/home/nicolas/.minikube/machines/minikube/id_rsa Username:docker}
I1021 17:41:58.477232 41687 addons.go:243] installing /etc/kubernetes/addons/registry-svc.yaml
I1021 17:41:58.477280 41687 ssh_runner.go:215] scp deploy/addons/registry/registry-svc.yaml.tmpl --> /etc/kubernetes/addons/registry-svc.yaml (398 bytes)
I1021 17:41:58.515257 41687 addons.go:243] installing /etc/kubernetes/addons/registry-proxy.yaml
I1021 17:41:58.515304 41687 ssh_runner.go:215] scp deploy/addons/registry/registry-proxy.yaml.tmpl --> /etc/kubernetes/addons/registry-proxy.yaml (878 bytes)
I1021 17:41:58.552293 41687 ssh_runner.go:148] Run: sudo KUBECONFIG=/var/lib/minikube/kubeconfig /var/lib/minikube/binaries/v1.19.2/kubectl apply -f /etc/kubernetes/addons/registry-rc.yaml -f /etc/kubernetes/addons/registry-svc.yaml -f /etc/kubernetes/addons/registry-proxy.yaml
I1021 17:41:58.720085 41687 addons.go:342] Verifying addon registry=true in "minikube"
I1021 17:41:58.722553 41687 out.go:109] 🔎 Verifying registry addon...
🔎 Verifying registry addon...
I1021 17:41:58.723596 41687 kapi.go:59] client config for minikube: &rest.Config{Host:"https://192.168.49.2:8443", APIPath:"", ContentConfig:rest.ContentConfig{AcceptContentTypes:"", ContentType:"", GroupVersion:(*schema.GroupVersion)(nil), NegotiatedSerializer:runtime.NegotiatedSerializer(nil)}, Username:"", Password:"", BearerToken:"", BearerTokenFile:"", Impersonate:rest.ImpersonationConfig{UserName:"", Groups:[]string(nil), Extra:map[string][]string(nil)}, AuthProvider:, AuthConfigPersister:rest.AuthProviderConfigPersister(nil), ExecProvider:, TLSClientConfig:rest.sanitizedTLSClientConfig{Insecure:false, ServerName:"", CertFile:"/home/nicolas/.minikube/profiles/minikube/client.crt", KeyFile:"/home/nicolas/.minikube/profiles/minikube/client.key", CAFile:"/home/nicolas/.minikube/ca.crt", CertData:[]uint8(nil), KeyData:[]uint8(nil), CAData:[]uint8(nil), NextProtos:[]string(nil)}, UserAgent:"", DisableCompression:false, Transport:http.RoundTripper(nil), WrapTransport:(transport.WrapperFunc)(0x16cdfd0), QPS:0, Burst:0, RateLimiter:flowcontrol.RateLimiter(nil), Timeout:0, Dial:(func(context.Context, string, string) (net.Conn, error))(nil)}
I1021 17:41:58.725261 41687 kapi.go:75] Waiting for pod with label "kubernetes.io/minikube-addons=registry" in ns "kube-system" ...
I1021 17:41:58.738360 41687 kapi.go:86] Found 2 Pods for label selector kubernetes.io/minikube-addons=registry
I1021 17:41:58.738377 41687 kapi.go:96] waiting for pod "kubernetes.io/minikube-addons=registry", current state: Pending: []
I1021 17:41:59.246932 41687 kapi.go:96] waiting for pod "kubernetes.io/minikube-addons=registry", current state: Pending: []
...
I1021 17:44:58.753808 41687 kapi.go:108] duration metric: took 3m0.028536465s to wait for kubernetes.io/minikube-addons=registry ...
I1021 17:44:58.760719 41687 out.go:109]

W1021 17:44:58.760957 41687 out.go:145] ❌ Exiting due to MK_ENABLE: run callbacks: running callbacks: [verifying registry addon pods : timed out waiting for the condition: timed out waiting for the condition]
❌ Exiting due to MK_ENABLE: run callbacks: running callbacks: [verifying registry addon pods : timed out waiting for the condition: timed out waiting for the condition]
W1021 17:44:58.761548 41687 out.go:145]

W1021 17:44:58.761640 41687 out.go:145] 😿 If the above advice does not help, please let us know:
😿 If the above advice does not help, please let us know:
W1021 17:44:58.761731 41687 out.go:145] 👉 https://github.com/kubernetes/minikube/issues/new/choose
👉 https://github.com/kubernetes/minikube/issues/new/choose
I1021 17:44:58.768913 41687 out.go:109]

[tstromberg]

Hey @nicolasduminil - do you mind sharing the output of:

• kubectl describe po -l kubernetes.io/minikube-addons=registry -n kube-system
• kubectl logs -l kubernetes.io/minikube-addons=registry -n kube-system

Thanks!

[nicolasduminil]

@tstromberg : Hi, yes, sure

kubectl describe po -l kubernetes.io/minikube-addons=registry -n kube-system
Name: registry-8t8jg
Namespace: kube-system
Priority: 0
Node: minikube/192.168.49.2
Start Time: Wed, 21 Oct 2020 17:41:58 +0200
Labels: actual-registry=true
addonmanager.kubernetes.io/mode=Reconcile
kubernetes.io/minikube-addons=registry
Annotations:
Status: Running
IP: 172.17.0.4
IPs:
IP: 172.17.0.4
Controlled By: ReplicationController/registry
Containers:
registry:
Container ID: docker://44543d604017eef2b3a28ccf2ff1eda17641bd0dc14fc6d1b7a3912dbf1c7d75
Image: registry.hub.docker.com/library/registry:2.7.1
Image ID: docker-pullable://registry.hub.docker.com/library/registry@sha256:8be26f81ffea54106bae012c6f349df70f4d5e7e2ec01b143c46e2c03b9e551d
Port: 5000/TCP
Host Port: 0/TCP
State: Running
Started: Wed, 21 Oct 2020 17:44:59 +0200
Ready: True
Restart Count: 0
Environment:
REGISTRY_STORAGE_DELETE_ENABLED: true
Mounts:
/var/run/secrets/kubernetes.io/serviceaccount from default-token-pqncf (ro)
Conditions:
Type Status
Initialized True
Ready True
ContainersReady True
PodScheduled True
Volumes:
default-token-pqncf:
Type: Secret (a volume populated by a Secret)
SecretName: default-token-pqncf
Optional: false
QoS Class: BestEffort
Node-Selectors:
Tolerations: node.kubernetes.io/not-ready:NoExecute for 300s
node.kubernetes.io/unreachable:NoExecute for 300s
Events:
Type Reason Age From Message

---

Normal Scheduled 50m default-scheduler Successfully assigned kube-system/registry-8t8jg to minikube
Normal Pulling 50m kubelet, minikube Pulling image "registry.hub.docker.com/library/registry:2.7.1"
Normal Pulled 47m kubelet, minikube Successfully pulled image "registry.hub.docker.com/library/registry:2.7.1" in 2m59.649166216s
Normal Created 47m kubelet, minikube Created container registry
Normal Started 47m kubelet, minikube Started container registry

Name: registry-proxy-b4cpb
Namespace: kube-system
Priority: 0
Node: minikube/192.168.49.2
Start Time: Wed, 21 Oct 2020 17:41:58 +0200
Labels: addonmanager.kubernetes.io/mode=Reconcile
controller-revision-hash=5dbc645dbb
kubernetes.io/minikube-addons=registry
pod-template-generation=1
registry-proxy=true
Annotations:
Status: Running
IP: 172.17.0.3
IPs:
IP: 172.17.0.3
Controlled By: DaemonSet/registry-proxy
Containers:
registry-proxy:
Container ID: docker://4bbb99faa3a13d7c05779c8f2d5a7ec8bdff6326e32543c3298518ab6517094c
Image: gcr.io/google_containers/kube-registry-proxy:0.4
Image ID: docker-pullable://gcr.io/google_containers/kube-registry-proxy@sha256:1040f25a5273de0d72c54865a8efd47e3292de9fb8e5353e3fa76736b854f2da
Port: 80/TCP
Host Port: 5000/TCP
State: Running
Started: Wed, 21 Oct 2020 17:44:36 +0200
Ready: True
Restart Count: 0
Environment:
REGISTRY_HOST: registry.kube-system.svc.cluster.local
REGISTRY_PORT: 80
Mounts:
/var/run/secrets/kubernetes.io/serviceaccount from default-token-pqncf (ro)
Conditions:
Type Status
Initialized True
Ready True
ContainersReady True
PodScheduled True
Volumes:
default-token-pqncf:
Type: Secret (a volume populated by a Secret)
SecretName: default-token-pqncf
Optional: false
QoS Class: BestEffort
Node-Selectors:
Tolerations: node.kubernetes.io/disk-pressure:NoSchedule
node.kubernetes.io/memory-pressure:NoSchedule
node.kubernetes.io/not-ready:NoExecute
node.kubernetes.io/pid-pressure:NoSchedule
node.kubernetes.io/unreachable:NoExecute
node.kubernetes.io/unschedulable:NoSchedule
Events:
Type Reason Age From Message

---

Normal Scheduled 50m default-scheduler Successfully assigned kube-system/registry-proxy-b4cpb to minikube
Normal Pulling 50m kubelet, minikube Pulling image "gcr.io/google_containers/kube-registry-proxy:0.4"
Normal Pulled 47m kubelet, minikube Successfully pulled image "gcr.io/google_containers/kube-registry-proxy:0.4" in 2m36.638674617s
Normal Created 47m kubelet, minikube Created container registry-proxy
Normal Started 47m kubelet, minikube Started container registry-proxy

$ kubectl logs -l kubernetes.io/minikube-addons=registry -n kube-system
192.168.49.2 - - [21/Oct/2020:16:06:24 +0000] "GET /v2/default/camel-k-kit-bu85lbu45tcuee0lpbi0/blobs/sha256:1f912d57785bd71fe4927566a215154129688ea025b793a29f1ec8891f9a62c2 HTTP/1.1" 200 13876205 "" "docker/19.03.8 go/go1.13.8 git-commit/afacb8b7f0 kernel/5.4.0-48-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)"
time="2020-10-21T16:06:24.934228942Z" level=info msg="response completed" go.version=go1.11.2 http.request.host=10.109.85.243 http.request.id=a972f94f-700c-4b92-a04a-1b6d252fc412 http.request.method=GET http.request.remoteaddr="192.168.49.2:49122" http.request.uri="/v2/default/camel-k-kit-bu85lbu45tcuee0lpbi0/blobs/sha256:671db6c87e86f6ba5286925ed64555fd353c9a51bdbb4f899470ee47234d9682" http.request.useragent="docker/19.03.8 go/go1.13.8 git-commit/afacb8b7f0 kernel/5.4.0-48-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)" http.response.contenttype="application/octet-stream" http.response.duration=7.975339ms http.response.status=200 http.response.written=8499728
192.168.49.2 - - [21/Oct/2020:16:06:24 +0000] "GET /v2/default/camel-k-kit-bu85lbu45tcuee0lpbi0/blobs/sha256:671db6c87e86f6ba5286925ed64555fd353c9a51bdbb4f899470ee47234d9682 HTTP/1.1" 200 8499728 "" "docker/19.03.8 go/go1.13.8 git-commit/afacb8b7f0 kernel/5.4.0-48-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)"
time="2020-10-21T16:06:24.944606852Z" level=info msg="response completed" go.version=go1.11.2 http.request.host=10.109.85.243 http.request.id=7b6c2c50-1b89-401a-bbea-0bcabd403870 http.request.method=GET http.request.remoteaddr="192.168.49.2:49110" http.request.uri="/v2/default/camel-k-kit-bu85lbu45tcuee0lpbi0/blobs/sha256:171857c49d0f5e2ebf623e6cb36a8bcad585ed0c2aa99c87a055df034c1e5848" http.request.useragent="docker/19.03.8 go/go1.13.8 git-commit/afacb8b7f0 kernel/5.4.0-48-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)" http.response.contenttype="application/octet-stream" http.response.duration=83.682559ms http.response.status=200 http.response.written=26701612
192.168.49.2 - - [21/Oct/2020:16:06:24 +0000] "GET /v2/default/camel-k-kit-bu85lbu45tcuee0lpbi0/blobs/sha256:171857c49d0f5e2ebf623e6cb36a8bcad585ed0c2aa99c87a055df034c1e5848 HTTP/1.1" 200 26701612 "" "docker/19.03.8 go/go1.13.8 git-commit/afacb8b7f0 kernel/5.4.0-48-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)"
192.168.49.2 - - [21/Oct/2020:16:06:24 +0000] "GET /v2/default/camel-k-kit-bu85lbu45tcuee0lpbi0/blobs/sha256:277e7f8f77af4e30a68e13f58eb5a3a8522af6ceafbf852bfb85038357125746 HTTP/1.1" 200 126420917 "" "docker/19.03.8 go/go1.13.8 git-commit/afacb8b7f0 kernel/5.4.0-48-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)"
time="2020-10-21T16:06:25.355923285Z" level=info msg="response completed" go.version=go1.11.2 http.request.host=10.109.85.243 http.request.id=1a94d853-31e1-4c7b-8529-209d792cbb31 http.request.method=GET http.request.remoteaddr="192.168.49.2:49120" http.request.uri="/v2/default/camel-k-kit-bu85lbu45tcuee0lpbi0/blobs/sha256:277e7f8f77af4e30a68e13f58eb5a3a8522af6ceafbf852bfb85038357125746" http.request.useragent="docker/19.03.8 go/go1.13.8 git-commit/afacb8b7f0 kernel/5.4.0-48-generic os/linux arch/amd64 UpstreamClient(Go-http-client/1.1)" http.response.contenttype="application/octet-stream" http.response.duration=484.012503ms http.response.status=200 http.response.written=126420917
time="2020-10-21T16:23:59.716382549Z" level=info msg="PurgeUploads starting: olderThan=2020-10-14 16:23:59.716322613 +0000 UTC m=-602459.973192736, actuallyDelete=true"
time="2020-10-21T16:23:59.716997401Z" level=info msg="Purge uploads finished. Num deleted=0, num errors=0"
time="2020-10-21T16:23:59.717039425Z" level=info msg="Starting upload purge in 24h0m0s" go.version=go1.11.2 instance.id=a8457d84-85bb-4782-8ba4-a2cb3e8be480 service=registry version=v2.7.1
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
waiting for the registry (registry.kube-system.svc.cluster.local:80) to come online...
starting proxy...

[tstromberg]

minikube has a 3 minute timeout on addon startup, and it seems like it took 2m59s to pull the registry image:

Normal Pulled 47m kubelet, minikube Successfully pulled image "registry.hub.docker.com/library/registry:2.7.1" in 2m59.649166216s

I'll see about extending the timeout

[nicolasduminil]

Okay, I'll try to do that, thanks.

[tstromberg]

Let's keep this issue open until the PR is merged.

If you get a chance, please check if this updated minikube binary fixes the issue for you:

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