Project: Operator not coming into ready state [installed using terraform]

Created on 19 Apr 2019 · 18Comments · Source: kubedb/project

I am using kubedb operator 0.11.0 on AKS where we install kubedb operator via terraform.

Kubernetes versions tested 1.12.6 and 1.12.7.

Log analytics for kube-controler is showing:

2019-04-18T20:49:55.000    kube-controller-manager    E0418 20:49:55.630101 1 resource_quota_controller.go:430] unable to retrieve the complete list of server APIs: mutators.kubedb.com/v1alpha1: the server is currently unable to handle the request, validators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:49:44.000    kube-controller-manager    E0418 20:49:44.038596 1 memcache.go:134] couldn't get resource list for mutators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:49:44.000    kube-controller-manager    E0418 20:49:44.082915 1 memcache.go:134] couldn't get resource list for validators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:49:30.000    kube-controller-manager    W0418 20:49:30.703688 1 garbagecollector.go:647] failed to discover some groups: map[validators.kubedb.com/v1alpha1:the server is currently unable to handle the request mutators.kubedb.com/v1alpha1:the server is currently unable to handle the request]     
    2019-04-18T20:49:24.000    kube-controller-manager    E0418 20:49:24.815215 1 resource_quota_controller.go:430] unable to retrieve the complete list of server APIs: mutators.kubedb.com/v1alpha1: the server is currently unable to handle the request, validators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:49:13.000    kube-controller-manager    E0418 20:49:13.278725 1 memcache.go:134] couldn't get resource list for validators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:49:13.000    kube-controller-manager    E0418 20:49:13.228473 1 memcache.go:134] couldn't get resource list for mutators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:48:57.000    kube-controller-manager    W0418 20:48:57.700706 1 garbagecollector.go:647] failed to discover some groups: map[mutators.kubedb.com/v1alpha1:the server is currently unable to handle the request validators.kubedb.com/v1alpha1:the server is currently unable to handle the request]     
    2019-04-18T20:48:54.000    kube-controller-manager    E0418 20:48:54.003569 1 resource_quota_controller.go:430] unable to retrieve the complete list of server APIs: mutators.kubedb.com/v1alpha1: the server is currently unable to handle the request, validators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:48:42.000    kube-controller-manager    E0418 20:48:42.471433 1 memcache.go:134] couldn't get resource list for validators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:48:42.000    kube-controller-manager    E0418 20:48:42.421184 1 memcache.go:134] couldn't get resource list for mutators.kubedb.com/v1alpha1: the server is currently unable to handle the request     
    2019-04-18T20:48:24.000    kube-controller-manager    W0418 20:48:24.698134 1 garbagecollector.go:647] failed to discover some groups: map[mutators.kubedb.com/v1alpha1:the server is currently unable to handle the request validators.kubedb.com/v1alpha1:the server is currently unable to handle the request]
2019-04-18T20:48:23.000    kube-controller-manager    E0418 20:48:23.249980 1 resource_quota_controller.go:430] unable to retrieve the complete list of server APIs: mutators.kubedb.com/v1alpha1: the server is currently unable to handle the request, validators.kubedb.co

I0418 10:58:24.058951       1 log.go:172] FLAG: --alsologtostderr="false"
I0418 10:58:24.059945       1 log.go:172] FLAG: --audit-dynamic-configuration="false"
I0418 10:58:24.059965       1 log.go:172] FLAG: --audit-log-batch-buffer-size="10000"
I0418 10:58:24.059974       1 log.go:172] FLAG: --audit-log-batch-max-size="1"
I0418 10:58:24.059982       1 log.go:172] FLAG: --audit-log-batch-max-wait="0s"
I0418 10:58:24.060016       1 log.go:172] FLAG: --audit-log-batch-throttle-burst="0"
I0418 10:58:24.060027       1 log.go:172] FLAG: --audit-log-batch-throttle-enable="false"
I0418 10:58:24.060036       1 log.go:172] FLAG: --audit-log-batch-throttle-qps="0"
I0418 10:58:24.060045       1 log.go:172] FLAG: --audit-log-format="json"
I0418 10:58:24.060053       1 log.go:172] FLAG: --audit-log-maxage="0"
I0418 10:58:24.060061       1 log.go:172] FLAG: --audit-log-maxbackup="0"
I0418 10:58:24.060069       1 log.go:172] FLAG: --audit-log-maxsize="0"
I0418 10:58:24.060100       1 log.go:172] FLAG: --audit-log-mode="blocking"
I0418 10:58:24.060111       1 log.go:172] FLAG: --audit-log-path="-"
I0418 10:58:24.060119       1 log.go:172] FLAG: --audit-log-truncate-enabled="false"
I0418 10:58:24.060128       1 log.go:172] FLAG: --audit-log-truncate-max-batch-size="10485760"
I0418 10:58:24.060136       1 log.go:172] FLAG: --audit-log-truncate-max-event-size="102400"
I0418 10:58:24.060145       1 log.go:172] FLAG: --audit-log-version="audit.k8s.io/v1"
I0418 10:58:24.060152       1 log.go:172] FLAG: --audit-policy-file=""
I0418 10:58:24.060181       1 log.go:172] FLAG: --audit-webhook-batch-buffer-size="10000"
I0418 10:58:24.060192       1 log.go:172] FLAG: --audit-webhook-batch-initial-backoff="10s"
I0418 10:58:24.060201       1 log.go:172] FLAG: --audit-webhook-batch-max-size="400"
I0418 10:58:24.060209       1 log.go:172] FLAG: --audit-webhook-batch-max-wait="30s"
I0418 10:58:24.060218       1 log.go:172] FLAG: --audit-webhook-batch-throttle-burst="15"
I0418 10:58:24.060226       1 log.go:172] FLAG: --audit-webhook-batch-throttle-enable="true"
I0418 10:58:24.060236       1 log.go:172] FLAG: --audit-webhook-batch-throttle-qps="10"
I0418 10:58:24.060264       1 log.go:172] FLAG: --audit-webhook-config-file=""
I0418 10:58:24.060280       1 log.go:172] FLAG: --audit-webhook-initial-backoff="10s"
I0418 10:58:24.060297       1 log.go:172] FLAG: --audit-webhook-mode="batch"
I0418 10:58:24.060305       1 log.go:172] FLAG: --audit-webhook-truncate-enabled="false"
I0418 10:58:24.060314       1 log.go:172] FLAG: --audit-webhook-truncate-max-batch-size="10485760"
I0418 10:58:24.060323       1 log.go:172] FLAG: --audit-webhook-truncate-max-event-size="102400"
I0418 10:58:24.060355       1 log.go:172] FLAG: --audit-webhook-version="audit.k8s.io/v1"
I0418 10:58:24.060364       1 log.go:172] FLAG: --authentication-kubeconfig=""
I0418 10:58:24.060373       1 log.go:172] FLAG: --authentication-skip-lookup="false"
I0418 10:58:24.060382       1 log.go:172] FLAG: --authentication-token-webhook-cache-ttl="***REDACTED***"
I0418 10:58:24.060398       1 log.go:172] FLAG: --authorization-always-allow-paths="[]"
I0418 10:58:24.060406       1 log.go:172] FLAG: --authorization-kubeconfig=""
I0418 10:58:24.060435       1 log.go:172] FLAG: --authorization-webhook-cache-authorized-ttl="10s"
I0418 10:58:24.060445       1 log.go:172] FLAG: --authorization-webhook-cache-unauthorized-ttl="10s"
I0418 10:58:24.060455       1 log.go:172] FLAG: --bind-address="0.0.0.0"
I0418 10:58:24.060464       1 log.go:172] FLAG: --burst="1000000"
I0418 10:58:24.060473       1 log.go:172] FLAG: --bypass-validating-webhook-xray="false"
I0418 10:58:24.060482       1 log.go:172] FLAG: --cert-dir="apiserver.local.config/certificates"
I0418 10:58:24.060491       1 log.go:172] FLAG: --client-ca-file=""
I0418 10:58:24.060519       1 log.go:172] FLAG: --contention-profiling="false"
I0418 10:58:24.060529       1 log.go:172] FLAG: --enable-analytics="true"
I0418 10:58:24.060537       1 log.go:172] FLAG: --enable-mutating-webhook="true"
I0418 10:58:24.060545       1 log.go:172] FLAG: --enable-status-subresource="true"
I0418 10:58:24.060555       1 log.go:172] FLAG: --enable-swagger-ui="false"
I0418 10:58:24.060566       1 log.go:172] FLAG: --enable-validating-webhook="true"
I0418 10:58:24.060573       1 log.go:172] FLAG: --governing-service="kubedb"
I0418 10:58:24.060596       1 log.go:172] FLAG: --help="false"
I0418 10:58:24.060608       1 log.go:172] FLAG: --http2-max-streams-per-connection="1000"
I0418 10:58:24.060616       1 log.go:172] FLAG: --kubeconfig=""
I0418 10:58:24.060635       1 log.go:172] FLAG: --label-key-blacklist="[app.kubernetes.io/name,app.kubernetes.io/version,app.kubernetes.io/instance,app.kubernetes.io/managed-by]"
I0418 10:58:24.060649       1 log.go:172] FLAG: --log-flush-frequency="5s"
I0418 10:58:24.060659       1 log.go:172] FLAG: --log_backtrace_at=":0"
I0418 10:58:24.060668       1 log.go:172] FLAG: --log_dir=""
I0418 10:58:24.060677       1 log.go:172] FLAG: --logtostderr="false"
I0418 10:58:24.060686       1 log.go:172] FLAG: --profiling="true"
I0418 10:58:24.060696       1 log.go:172] FLAG: --qps="1e+06"
I0418 10:58:24.060705       1 log.go:172] FLAG: --rbac="true"
I0418 10:58:24.060717       1 log.go:172] FLAG: --requestheader-allowed-names="[]"
I0418 10:58:24.060726       1 log.go:172] FLAG: --requestheader-client-ca-file=""
I0418 10:58:24.060737       1 log.go:172] FLAG: --requestheader-extra-headers-prefix="[x-remote-extra-]"
I0418 10:58:24.060749       1 log.go:172] FLAG: --requestheader-group-headers="[x-remote-group]"
I0418 10:58:24.060758       1 log.go:172] FLAG: --requestheader-username-headers="[x-remote-user]"
I0418 10:58:24.060767       1 log.go:172] FLAG: --restrict-to-operator-namespace="false"
I0418 10:58:24.060776       1 log.go:172] FLAG: --resync-period="10m0s"
I0418 10:58:24.060785       1 log.go:172] FLAG: --secure-port="8443"
I0418 10:58:24.060800       1 log.go:172] FLAG: --stderrthreshold="0"
I0418 10:58:24.060810       1 log.go:172] FLAG: --tls-cert-file="/var/serving-cert/tls.crt"
I0418 10:58:24.060821       1 log.go:172] FLAG: --tls-cipher-suites="[]"
I0418 10:58:24.060830       1 log.go:172] FLAG: --tls-min-version=""
I0418 10:58:24.060839       1 log.go:172] FLAG: --tls-private-key-file="/var/serving-cert/tls.key"
I0418 10:58:24.060847       1 log.go:172] FLAG: --tls-sni-cert-key="[]"
I0418 10:58:24.060856       1 log.go:172] FLAG: --use-kubeapiserver-fqdn-for-aks="true"
I0418 10:58:24.060864       1 log.go:172] FLAG: --v="3"
I0418 10:58:24.060873       1 log.go:172] FLAG: --vmodule=""
I0418 10:58:24.168849       1 run.go:24] Starting kubedb-server...
I0418 10:58:24.624316       1 client_config.go:104] resetting Kubeconfig host to https://X from https://X:443 for AKS to workaround https://github.com/Azure/AKS/issues/522
I0418 10:58:24.634421       1 lib.go:112] Kubernetes version: &version.Info{Major:"1", Minor:"12", GitVersion:"v1.12.6", GitCommit:"ab91afd7062d4240e95e51ac00a18bd58fddd365", GitTreeState:"clean", BuildDate:"2019-02-26T12:49:28Z", GoVersion:"go1.10.8", Compiler:"gc", Platform:"linux/amd64"}
I0418 10:58:24.643977       1 controller.go:72] Ensuring CustomResourceDefinition...

```

Name: kubedb-operator-865cd795f8-ngsjb
Namespace: kube-system
Priority: 0
PriorityClassName:
Node: aks-default-39479143-0/10.201.32.4
Start Time: Thu, 18 Apr 2019 12:53:04 +0200
Labels: app=kubedb
chart=kubedb-0.11.0
heritage=Tiller
pod-template-hash=865cd795f8
release=kubedb-operator
Annotations:
Status: Running
IP: 10.200.0.7
Controlled By: ReplicaSet/kubedb-operator-865cd795f8
Containers:
operator:
Container ID: docker://adab7ac5f85d3a79562c0dcc62e9e44fcf10ba0a52718baa423bbbedbafb2df7
Image: kubedb/operator:0.11.0
Image ID: docker-pullable://kubedb/operator@sha256:9f7ff77a4770f485741275a43c269980ff3e6c7d6f466d9c93a0123ecd7f4c4b
Port: 8443/TCP
Host Port: 0/TCP
Args:
run
--v=3
--governing-service=kubedb
--rbac=true
--secure-port=8443
--audit-log-path=-
--tls-cert-file=/var/serving-cert/tls.crt
--tls-private-key-file=/var/serving-cert/tls.key
--enable-mutating-webhook=true
--enable-validating-webhook=true
--enable-status-subresource=true
--bypass-validating-webhook-xray=false
--use-kubeapiserver-fqdn-for-aks=true
--enable-analytics=true
State: Waiting
Reason: CrashLoopBackOff
Last State: Terminated
Reason: Error
Exit Code: 137
Started: Thu, 18 Apr 2019 13:01:03 +0200
Finished: Thu, 18 Apr 2019 13:02:23 +0200
Ready: False
Restart Count: 6
Requests:
cpu: 100m
Liveness: http-get https://:8443/healthz delay=15s timeout=15s period=10s #success=1 #failure=3
Readiness: http-get https://:8443/healthz delay=5s timeout=1s period=10s #success=1 #failure=3
Environment:
MY_POD_NAME: kubedb-operator-865cd795f8-ngsjb (v1:metadata.name)
MY_POD_NAMESPACE: kube-system (v1:metadata.namespace)
KUBERNETES_PORT_443_TCP_ADDR: ace-test-e2005a20.hcp.westeurope.azmk8s.io
KUBERNETES_PORT: tcp://ace-test-e2005a20.hcp.westeurope.azmk8s.io:443
KUBERNETES_PORT_443_TCP: tcp://ace-test-e2005a20.hcp.westeurope.azmk8s.io:443
KUBERNETES_SERVICE_HOST: ace-test-e2005a20.hcp.westeurope.azmk8s.io
Mounts:
/var/run/secrets/kubernetes.io/serviceaccount from kubedb-operator-token-t2vl9 (ro)
/var/serving-cert from serving-cert (rw)
Conditions:
Type Status
Initialized True
Ready False
ContainersReady False
PodScheduled True
Volumes:
serving-cert:
Type: Secret (a volume populated by a Secret)
SecretName: kubedb-operator-apiserver-cert
Optional: false
kubedb-operator-token-t2vl9:
Type: Secret (a volume populated by a Secret)
SecretName: kubedb-operator-token-t2vl9
Optional: false
QoS Class: Burstable
Node-Selectors: beta.kubernetes.io/arch=amd64
beta.kubernetes.io/os=linux
Tolerations: node.kubernetes.io/not-ready:NoExecute for 300s
node.kubernetes.io/unreachable:NoExecute for 300s
Events:
Type Reason Age From Message
---- ------ ---- ---- -------
Normal Scheduled 11m default-scheduler Successfully assigned kube-system/kubedb-operator-865cd795f8-ngsjb to aks-default-39479143-0
Normal Pulled 9m (x2 over 11m) kubelet, aks-default-39479143-0 Container image "kubedb/operator:0.11.0" already present on machine
Normal Created 9m (x2 over 11m) kubelet, aks-default-39479143-0 Created container
Normal Started 9m (x2 over 11m) kubelet, aks-default-39479143-0 Started container
Normal Killing 9m kubelet, aks-default-39479143-0 Killing container with id docker://operator:Container failed liveness probe.. Container will be killed and recreated.
Warning Unhealthy 9m (x6 over 10m) kubelet, aks-default-39479143-0 Liveness probe failed: Get https://10.200.0.7:8443/healthz: net/http: TLS handshake timeout
Warning Unhealthy 6m (x28 over 11m) kubelet, aks-default-39479143-0 Readiness probe failed: Get https://10.200.0.7:8443/healthz: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
Warning BackOff 1m (x6 over 1m) kubelet, aks-default-39479143-0 Back-off restarting failed container```

bug

Source

ekarlso

Most helpful comment

Issue-Label Bot is automatically applying the label bug to this issue, with a confidence of 0.86. Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!

Links: app homepage, dashboard and code for this bot.

issue-label-bot[bot] on 19 Apr 2019

👍2

All 18 comments

Issue-Label Bot is automatically applying the label bug to this issue, with a confidence of 0.86. Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!

Links: app homepage, dashboard and code for this bot.

issue-label-bot[bot] on 19 Apr 2019

👍2

So I tried again to test this using AKS k8s v1.12.7, it seems to get the same "error" with kubedb-operator never coming online. I then tried to delete the operator pod but then it all just crashes, the AKS k8s api seems totally unresponsive to actions and I rebooted the nodes but they never come back online.

ekarlso on 21 Apr 2019

Tried AKS 1.12.6 too, same errors there when checking logs for the cluster.

ekarlso on 21 Apr 2019

https://github.com/ekarlso/kubedb-aks-tf-helm/ See this for code.

ekarlso on 21 Apr 2019

So I thought it was something due to our terraform cluster module but I tried setting up a vanilla cluster using the CLI

az group create -n testing -l westeurope
az aks create --enable-rbac -g testing -n testing-cluster --kubernetes-version 1.12.7

ekarlso on 21 Apr 2019

can you try kubedb helm installation? I tried few days ago and there was no issue. can you verify if kubedb chart works in your cluster? https://kubedb.com/docs/0.11.0/setup/install/#using-helm

the-redback on 23 Apr 2019

I tested this and it seems to work when you install it directly from the chart / helm. I can't see why it deosnt work with terraform though ?

ekarlso on 23 Apr 2019

Steps to reprocude:

az group create -n testing -l westeurope
az aks create --enable-rbac -g testing -n testing-cluster --kubernetes-version 1.12.7
az aks get-credentials -g testing -n testing-cluster -a -f ~/.kube/testing-creds
export KUBECONFIG=~/.kube/testing-creds

Go into the example repo I have linked
cd tf-helm
terraform init
terraform apply # this will then start the deployment of the given helm charts to the cluster context in KUBECONFIG above.

ekarlso on 23 Apr 2019

```
~ $ netstat -tunlp | grep 8443
tcp 5 0 :::8443 :::* LISTEN 1/kubedb-operator


Events for the kubedb pod

Normal Started 36s (x2 over 1m) kubelet, aks-default-15932083-0 Started container
Warning Unhealthy 36s kubelet, aks-default-15932083-0 Readiness probe failed: Get https://10.99.0.15:8443/healthz: dial tcp 10.99.0.15:8443: connect: connection refused
Normal Killing 36s kubelet, aks-default-15932083-0 Killing container with id docker://operator:Container failed liveness probe.. Container will be killed and recreated.
Warning Unhealthy 7s (x4 over 1m) kubelet, aks-default-15932083-0 Liveness probe failed: Get https://10.99.0.15:8443/healthz: net/http: TLS handshake timeout
Warning Unhealthy 5s (x10 over 1m) kubelet, aks-default-15932083-0 Readiness probe failed: Get https://10.99.0.15:8443/healthz: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)


Connecting from "tunnelfront" via curl to the :8443 on the kubedb operator pod

curl https://10.99.0.15:8443/healthz
curl: (35) OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to 10.99.0.15:8443
```

ekarlso on 23 Apr 2019

It seems for me that the kubedb operator is listening but not accepting connections or something ?

ekarlso on 23 Apr 2019

Hello,
I am also having the same issue and it may come from a wrong order in the Helm file.
This issue happens when the wait is required because helm wait first the deployment to be ready before pushing the CRD to the cluster but this is not possible because the pod it self want the CRD to be ready.
As a patch use wait = false on your resource.

PhilippeVienne on 11 May 2019

👍1

Seems like something wrong went wrong in our APIService .

you can run Kubectl get APIService
check wether our 'mutators.kubedb.com' status

weenxin on 23 May 2019

Might help someone who finds this issue, to fix this I manually changed the liveness probe timeout to 3 mins.
Watching the logs I can see that after about 2 mins the kubeDB controller starts up:

I0708 07:51:30.932501       1 controller.go:72] Ensuring CustomResourceDefinition...
I0708 07:53:57.169032       1 run.go:36] Starting KubeDB controller
I0708 07:53:57.171377       1 secure_serving.go:116] Serving securely on [::]:8443

I got this after upgrading from 0.9 to the latest (0.12.0).

mt3593 on 8 Jul 2019

Any ideas on this?

ekarlso on 21 Jul 2019

Same problem on GKE, with command line helm works but with terraform it doesn't work

rtrive on 21 Jan 2020

I was experiencing the same problem. It seems like the healthchecks happen too early before CRDs are created. I followed @PhilippeVienne suggestion as well as not using --atomic helm deployment and did the trick. After initial liveness probe fails, it recovers

cortopy on 10 Apr 2020

Same problem on GKE, with command line helm works but with terraform it doesn't work

I'm also experiencing this on bare metal, as well as AKS (Azure). Performing the helm install manually works just fine, using terraform not.

Increasing initial delay and timeout values for liveness and readiness probe did not help.

I'm using 0.12.0

My current workaround: perform the manual helm install, and then import into terraform. From then one it works fine (haven't tried changes, but I can add databases).

carlowouters on 8 Jun 2020

I found the problem in GKE on a private cluster. By default masters only are able to communicate via 443 and 10250. I added port 8443 and it started working.