Kubernetes API server on Minikube sometimes fails to start

[wallrj]

In #105 we added logging so that we could diagnose why kubernetes API is sometimes unavailable in our minikube E2E tests.

This recent build shows the logs:

• https://travis-ci.org/jetstack/navigator/jobs/299108343
• log.txt

/kind bug

[munnerz]

Other things to note: it appears that the apiserver is panicking when the /healthz endpoint is hit.

Using minikube v0.23.0, Kubernetes 1.8 and compiled with Golang 1.8 (in case anyone is stepping through trying to debug locally).

[wallrj]

Another example of this failure in:

• log.txt
• https://s3.amazonaws.com/archive.travis-ci.org/jobs/299662836/log.txt?X-Amz-Expires=30&X-Amz-Date=20171109T144057Z&X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAJRYRXRSVGNKPKO5A/20171109/us-east-1/s3/aws4_request&X-Amz-SignedHeaders=host&X-Amz-Signature=fe28c64ef096ace62a944cb2fb5962712f6edc60ce581ffabefd67dd0d00849f

...
I1109 14:28:20.656317    4130 ready.go:30] Performing healthcheck on https://localhost:8443/healthz
I1109 14:28:20.667771    4130 handler.go:160] kube-aggregator: GET "/healthz" satisfied by nonGoRestful
I1109 14:28:20.667795    4130 pathrecorder.go:240] kube-aggregator: "/healthz" satisfied by exact match
I1109 14:28:20.668177    4130 wrap.go:42] GET /healthz: (609.925µs) 500
goroutine 3162 [running]:
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).recordStatus(0xc42384ca80, 0x1f4)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:207 +0xdd
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc42384ca80, 0x1f4)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:186 +0x35
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).WriteHeader(0xc42bb20440, 0x1f4)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:201 +0xb5
net/http.Error(0x7f1301058da0, 0xc427721eb8, 0xc428b45500, 0x2ed, 0x1f4)
	/usr/local/go/src/net/http/server.go:1954 +0xda
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/healthz.handleRootHealthz.func1(0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/healthz/healthz.go:120 +0x3cb
net/http.HandlerFunc.ServeHTTP(0xc42a79d3c0, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/go/src/net/http/server.go:1942 +0x44
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0xc42b826780, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:241 +0x567
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0xc42113ed90, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:234 +0x72
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server.director.ServeHTTP(0x4710606, 0xf, 0xc429212510, 0xc42113ed90, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/handler.go:161 +0x301
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server.(*director).ServeHTTP(0xc4290e54c0, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	<autogenerated>:69 +0x86
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithAuthorization.func1(0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/filters/authorization.go:51 +0x37a
net/http.HandlerFunc.ServeHTTP(0xc428f73400, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/go/src/net/http/server.go:1942 +0x44
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters.WithMaxInFlightLimit.func1(0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters/maxinflight.go:98 +0x5a0
net/http.HandlerFunc.ServeHTTP(0xc42920a6c0, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/go/src/net/http/server.go:1942 +0x44
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithImpersonation.func1(0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/filters/impersonation.go:49 +0x21b2
net/http.HandlerFunc.ServeHTTP(0xc428f73450, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/go/src/net/http/server.go:1942 +0x44
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithAuthentication.func1(0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/filters/authentication.go:79 +0x2b0
net/http.HandlerFunc.ServeHTTP(0xc428f734a0, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/go/src/net/http/server.go:1942 +0x44
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/request.WithRequestContext.func1(0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/endpoints/request/requestcontext.go:110 +0xef
net/http.HandlerFunc.ServeHTTP(0xc4290e54e0, 0x7f1301058da0, 0xc427721eb8, 0xc42b9e7c00)
	/usr/local/go/src/net/http/server.go:1942 +0x44
k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP.func1(0xc4290e5560, 0x9851340, 0xc427721eb8, 0xc42b9e7c00, 0xc42bb172c0)
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:106 +0x8d
created by k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP
	/usr/local/google/home/mrick/go/src/k8s.io/minikube/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:108 +0x1ca

logging error output: "[+]ping ok\n[+]etcd ok\n[+]poststarthook/generic-apiserver-start-informers ok\n[+]poststarthook/start-apiextensions-informers ok\n[+]poststarthook/start-apiextensions-controllers ok\n[-]poststarthook/bootstrap-controller failed: reason withheld\n[-]poststarthook/rbac/bootstrap-roles failed: reason withheld\n[-]poststarthook/ca-registration failed: reason withheld\n[+]poststarthook/start-kube-apiserver-informers ok\n[+]poststarthook/start-kube-aggregator-informers ok\n[+]poststarthook/apiservice-registration-controller ok\n[+]poststarthook/apiservice-status-available-controller ok\n[+]poststarthook/apiservice-openapi-controller ok\n[+]poststarthook/kube-apiserver-autoregistration ok\n[-]autoregister-completion failed: reason withheld\nhealthz check failed\n"
 [[Go-http-client/1.1] 127.0.0.1:45762]
I1109 14:28:20.668318    4130 ready.go:49] Got healthcheck response: [+]ping ok
[+]etcd ok
[+]poststarthook/generic-apiserver-start-informers ok
[+]poststarthook/start-apiextensions-informers ok
[+]poststarthook/start-apiextensions-controllers ok
[-]poststarthook/bootstrap-controller failed: reason withheld
[-]poststarthook/rbac/bootstrap-roles failed: reason withheld
[-]poststarthook/ca-registration failed: reason withheld
[+]poststarthook/start-kube-apiserver-informers ok
[+]poststarthook/start-kube-aggregator-informers ok
[+]poststarthook/apiservice-registration-controller ok
[+]poststarthook/apiservice-status-available-controller ok
[+]poststarthook/apiservice-openapi-controller ok
[+]poststarthook/kube-apiserver-autoregistration ok
[-]autoregister-completion failed: reason withheld
healthz check failed
I1109 14:28:21.215650    4130 trace.go:76] Trace[1499040573]: "GuaranteedUpdate etcd3: *api.RangeAllocation" (started: 2017-11-09 14:28:14.214206488 +0000 UTC) (total time: 7.001400127s):
Trace[1499040573]: [783.375µs] [783.375µs] initial value restored
Trace[1499040573]: [809.191µs] [25.816µs] Transaction prepared
Trace[1499040573]: [7.001400127s] [7.000590936s] END
F1109 14:28:21.215695    4130 controller.go:132] Unable to perform initial service nodePort check: unable to persist the updated port allocations: etcdserver: request timed out

[munnerz]

This should now be fixed after switching to the kubeadm bootstrapper. I've not seen any issues where the API server doesn't come up (except when the build VM is under super heavy load)