Okd: etcd bootstrap failures

[jdhirst]

Noticed in latest build (4.4.0-0.okd-2020-01-29-103659)

etcd fails to bootstrap correctly. This occurs very often on bootstrap or master nodes, but not always.

Jan 29 17:45:56 bootstrap.okd.example.net bootkube.sh[830]: {"level":"warn","ts":"2020-01-29T17:45:56.812Z","caller":"clientv3/retry_interceptor.go:61","msg":"retrying of unary invoker failed","target":"endpoint://client-2eb8c07f-110f-4509-86bc-1204fc6ef953/172.16.20.29:2379","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = latest connection error: connection error: desc = \"transport: Error while dialing dial tcp 172.16.20.29:2379: connect: connection refused\""}
Jan 29 17:45:56 bootstrap.okd.example.net bootkube.sh[830]: https://172.16.20.29:2379 is unhealthy: failed to commit proposal: context deadline exceeded
Jan 29 17:45:56 bootstrap.okd.example.net bootkube.sh[830]: Error: unhealthy cluster

We can see that etcd isn't getting certificates:

2020-01-29T17:43:10.301492157+00:00 stderr F + kube-client-agent request --kubeconfig=/etc/kubernetes/kubeconfig --orgname=system:etcd-servers --assetsdir=/etc/ssl/etcd --dnsnames=localhost,etcd.kube-system.svc,etcd.kube-system.svc.cluster.local,etcd.openshift-etcd.svc,etcd.openshift-etcd.svc.cluster.local --commonname=system:etcd-server:172.16.20.29 --ipaddrs=172.16.20.29,127.0.0.1
2020-01-29T17:43:20.456237172+00:00 stderr F ERROR: logging before flag.Parse: E0129 17:43:20.456082       7 agent.go:145] unable to retrieve approved CSR: the server could not find the requested resource (get certificatesigningrequests.certificates.k8s.io system:etcd-server:172.16.20.29). Retrying.
2020-01-29T17:43:23.459441822+00:00 stderr P ERROR: logging before flag.Parse: 
2020-01-29T17:43:23.459516973+00:00 stderr F E0129 17:43:23.459187       7 agent.go:145] unable to retrieve approved CSR: the server could not find the requested resource (get certificatesigningrequests.certificates.k8s.io system:etcd-server:172.16.20.29). Retrying.
2020-01-29T17:43:26.457881285+00:00 stderr F ERROR: logging before flag.Parse: E0129 17:43:26.457771       7 agent.go:145] unable to retrieve approved CSR: the server could not find the requested resource (get certificatesigningrequests.certificates.k8s.io system:etcd-server:172.16.20.29). Retrying.
2020-01-29T17:43:29.457852868+00:00 stderr F ERROR: logging before flag.Parse: E0129 17:43:29.457774       7 agent.go:145] unable to retrieve approved CSR: the server could not find the requested resource (get certificatesigningrequests.certificates.k8s.io system:etcd-server:172.16.20.29). Retrying.
2020-01-29T17:43:30.457434550+00:00 stderr F ERROR: logging before flag.Parse: E0129 17:43:30.457358       7 agent.go:145] unable to retrieve approved CSR: the server could not find the requested resource (get certificatesigningrequests.certificates.k8s.io system:etcd-server:172.16.20.29). Retrying.
2020-01-29T17:43:30.457434550+00:00 stderr F Error: error requesting certificate: error obtaining signed certificate from signer: timed out waiting for the condition
2020-01-29T17:43:30.457716467+00:00 stderr F Usage:
2020-01-29T17:43:30.457716467+00:00 stderr F   kube-client-agent request --FLAGS [flags]
2020-01-29T17:43:30.457716467+00:00 stderr F 
2020-01-29T17:43:30.457716467+00:00 stderr F Flags:
2020-01-29T17:43:30.457716467+00:00 stderr F       --assetsdir string    Directory location for the agent where it stores signed certs
2020-01-29T17:43:30.457716467+00:00 stderr F       --commonname string   Common name for the certificate being requested
2020-01-29T17:43:30.457716467+00:00 stderr F       --dnsnames string     Comma separated DNS names of the node to be provided for the X509 certificate
2020-01-29T17:43:30.457716467+00:00 stderr F   -h, --help                help for request
2020-01-29T17:43:30.457716467+00:00 stderr F       --ipaddrs string      Comma separated IP addresses of the node to be provided for the X509 certificate
2020-01-29T17:43:30.457716467+00:00 stderr F       --kubeconfig string   Path to the kubeconfig file to connect to apiserver. If "", InClusterConfig is used which uses the service account kubernetes gives to pods.
2020-01-29T17:43:30.457716467+00:00 stderr F       --orgname string      CA private key file for signer
2020-01-29T17:43:30.457716467+00:00 stderr F 
2020-01-29T17:43:30.457716467+00:00 stderr F ERROR: logging before flag.Parse: F0129 17:43:30.457651       7 main.go:18] Error executing kube-client-agent: error requesting certificate: error obtaining signed certificate from signer: timed out waiting for the condition

No logs in etcd-signer container on bootstrap node.

[vrutkovs]

Seems to be intermittent, seen this in ~50% of all runs on CI (independent of the platform)

It appears that etcd-signer container is shown as running but is stuck and not approving csrs

[jdhirst]

I'm not sure if its intermittent as far as the individual release goes because I have rebuild my bootstrap node around 10 times so far on 4.4.0-0.okd-2020-01-29-103659, and the issue occurs every time.

However, when I use build 4.4.0-0.okd-2020-01-28-022517, bootstrap node works fine, but the masters have this happen around 50% of the time. (the master issue seems to be intermittent).

UPDATE: Confirmed that this is the case with 4.4.0-0.okd-2020-01-29-161855 as well, so it seems to be something added starting at 4.4.0-0.okd-2020-01-29-103659.

[vrutkovs]

Does it fail every time on mirrored images? I've noticed CI's registry has become very unreliable recently, so it may have been caused by hidden pull errors. Could you give it a try?

https://github.com/openshift/installer/pull/3013 would help eliminating those

[jdhirst]

Yes, I have been using mirrored images and appending the imageContentSources key to the end of my install-config.yaml file. This occurs with both direct to CI installs and mirrored installs.

[jdhirst]

Just tested 4.4.0-0.okd-2020-02-03-164031, same issue occurs, bootstrap etcd signer fails:

2020-02-03T18:21:32.510878803+00:00 stderr F Error: error requesting certificate: error obtaining signed certificate from signer: timed out waiting for the condition
2020-02-03T18:21:32.512207454+00:00 stderr F Usage:
2020-02-03T18:21:32.512207454+00:00 stderr F   kube-client-agent request --FLAGS [flags]
2020-02-03T18:21:32.512207454+00:00 stderr F 
2020-02-03T18:21:32.512207454+00:00 stderr F Flags:
2020-02-03T18:21:32.512207454+00:00 stderr F       --assetsdir string    Directory location for the agent where it stores signed certs
2020-02-03T18:21:32.512207454+00:00 stderr F       --commonname string   Common name for the certificate being requested
2020-02-03T18:21:32.512207454+00:00 stderr F       --dnsnames string     Comma separated DNS names of the node to be provided for the X509 certificate
2020-02-03T18:21:32.512207454+00:00 stderr F   -h, --help                help for request
2020-02-03T18:21:32.512207454+00:00 stderr F       --ipaddrs string      Comma separated IP addresses of the node to be provided for the X509 certificate
2020-02-03T18:21:32.512207454+00:00 stderr F       --kubeconfig string   Path to the kubeconfig file to connect to apiserver. If "", InClusterConfig is used which uses the service account kubernetes gives to pods.
2020-02-03T18:21:32.512207454+00:00 stderr F       --orgname string      CA private key file for signer
2020-02-03T18:21:32.512207454+00:00 stderr F 
2020-02-03T18:21:32.512207454+00:00 stderr F ERROR: logging before flag.Parse: F0203 18:21:32.512137       7 main.go:18] Error executing kube-client-agent: error requesting certificate: error obtaining signed certificate from signer: timed out waiting for the condition

[jdhirst]

For those testing OKD and want to bypass this bug to get UPI to deploy, it is sufficient to destroy the old etcd-signer container using podman rm -f etcd-signer and redeploy manually using the method from bootkube.sh.

Here is my example: (replace KUBE_ETCD_SIGNER_SERVER_IMAGE with the same image used in your build; obtain from podman ps)

KUBE_ETCD_SIGNER_SERVER_IMAGE=registry.svc.ci.openshift.org/origin/4.4-2020-02-04-174205@sha256:8755e700accb5b6d92fd7d2c7b7a6252ed62f843f06fc31812b415a0ac47e0e1
podman pull ${KUBE_ETCD_SIGNER_SERVER_IMAGE}
podman run --quiet --net=host \
    --name etcd-signer \
    --detach \
    --volume /opt/openshift/tls:/opt/openshift/tls:ro,z \
    "${KUBE_ETCD_SIGNER_SERVER_IMAGE}" \
    serve \
    --cacrt=/opt/openshift/tls/etcd-signer.crt \
    --cakey=/opt/openshift/tls/etcd-signer.key \
    --metric-cacrt=/opt/openshift/tls/etcd-metric-signer.crt \
    --metric-cakey=/opt/openshift/tls/etcd-metric-signer.key \
    --servcrt=/opt/openshift/tls/kube-apiserver-lb-server.crt \
    --servkey=/opt/openshift/tls/kube-apiserver-lb-server.key \
    --servcrt=/opt/openshift/tls/kube-apiserver-internal-lb-server.crt \
    --servkey=/opt/openshift/tls/kube-apiserver-internal-lb-server.key \
    --servcrt=/opt/openshift/tls/kube-apiserver-localhost-server.crt \
    --servkey=/opt/openshift/tls/kube-apiserver-localhost-server.key \
    --address=0.0.0.0:6443 \
    --insecure-health-check-address=0.0.0.0:6080 \
    --csrdir=/tmp \
    --peercertdur=26280h \
    --servercertdur=26280h \
    --metriccertdur=26280h

This allowed me to bootstrap without issue and was able to get OKD deployed to test other components.

[vrutkovs]

I'm pretty sure crun/ conmon/ podman from Fedora are unstable (CI gets stuck on this fairly often too). The symptoms are:

• podman inspect etcd-signer says no such container
• podman logs etcd-signer exits immediately. Usually container comes up correctly on next reboot

@openshift/sig-containers ^ any ideas how to debug this?

[vrutkovs]

Pretty sure its a podman bug - https://github.com/containers/libpod/issues/5109

[vrutkovs]

CRIO and podman are not playing well together - crio finds podman containers, checks it DB - and since these are not there it removes them. Sometimes it happens when etcd-signer is still running, so signer's storage is removed and it hangs.

This is a crio bug, I'll attempt to work it around until the fix lands in the machine-os-content

[vrutkovs]

https://github.com/cri-o/cri-o/pull/3227 is the fix for crio 1.17

[vrutkovs]

Current workaround: restart the pod or simply reboot the bootstrap node

[sgreene570]

thought I was hitting this but then i remembered that the initial etcd cert expires 24hrs after creating ignition configs. :man_facepalming:
https://bugzilla.redhat.com/show_bug.cgi?id=1726995

[vrutkovs]

crio 1.17.0 landed a few days ago, etcd-signer no longers gets stuck in my tests