etcd hangs indefinitely when its stdout/stderr log sink stops being drained

[vladonutu]

Bug report criteria

• This bug report is not security related, security issues should be disclosed privately via security@etcd.io.
• This is not a support request or question, support requests or questions should be raised in the etcd discussion forums.
• You have read the etcd bug reporting guidelines.
• Existing open issues along with etcd frequently asked questions have been checked and this is not a duplicate.

What happened?

Linked to RKE2 issue: rancher/rke2#11056

cc @brandond @piugoyal

When etcd's zap logger writes to stdout/stderr in a container and the reader on the other end of that pipe stops (the container runtime is killed), etcd doesn't crash or time out - it deadlocks indefinitely. It stays alive but never elects/rejoins a raft leader and all client RPCs eventually time out. It never recovers on its own, even once the network/runtime condition that triggered this is fully restored.

What did you expect to happen?

Either etcd keeps working (a file-based log-outputs sink is still writable and functioning fine the whole time) or it fails visibly (crash/exit), not silently deadlock forever with no crash.

How can we reproduce it (as minimally and precisely as possible)?

1. Run a 3-node etcd cluster with default log-outputs (stdout/stderr, captured by a container runtime as usual).
2. On the node currently holding etcd leadership, cut network connectivity to its peers for 1-2 minutes, then restore it.
3. Independently of etcd, have whatever supervises it exit and its container runtime get killed as a side effect (in our case: a Kubernetes Lease-holder self-fataling on lease loss, which kills containerd as part of its own restart). This stops anything draining the pipe backing etcd's stdout/stderr. etcd itself is never killed and keeps running as an orphaned process.
4. If the outage is long enough, etcd's goroutines block inside a logging call and the process becomes fully unresponsive, even once the network is fully healthy again and raw TCP to peers on 2380 works.

Anything else we need to know?

Full writeup with many reproductions across RKE2 versions/clusters: rancher/rke2#11056

In that thread, @brandond independently reproduced this with RKE2 in Docker containers and diagnosed the same mechanism: "This suggests that there is a bug in etcd, in that the etcd logging library (zap) writers are blocking. This will cause the process to deadlock when log writes hang due to the container's stdout/stderr pipes filling. It doesn't crash, the goroutines all just block in calls that would write to the log."

Logs can be available on request.

Etcd version (please run commands below)

vlado-mgmt-cp-3525a81a39-ndqxl:~ # curl -s http://127.0.0.1:2381/metrics | grep etcd_server_version
# HELP etcd_server_version Which version is running. 1 for 'server_version' label with current version.
# TYPE etcd_server_version gauge
etcd_server_version{server_version="3.5.26"} 1

Etcd configuration (command line flags or environment variables)

Bug reproduces with:

vlado-mgmt-cp-3525a81a39-ndqxl:~ # cat /var/lib/rancher/rke2/server/db/etcd/config
advertise-client-urls: https://10.16.21.112:2379
auto-compaction-mode: periodic
auto-compaction-retention: 12h0m0s
client-transport-security:
  cert-file: /var/lib/rancher/rke2/server/tls/etcd/server-client.crt
  client-cert-auth: true
  key-file: /var/lib/rancher/rke2/server/tls/etcd/server-client.key
  trusted-ca-file: /var/lib/rancher/rke2/server/tls/etcd/server-ca.crt
data-dir: /var/lib/rancher/rke2/server/db/etcd
election-timeout: 5000
experimental-initial-corrupt-check: true
experimental-watch-progress-notify-interval: 5000000000
heartbeat-interval: 500
initial-advertise-peer-urls: https://10.16.21.112:2380
initial-cluster: vlado-mgmt-cp-3525a81a39-jz2kt-9c7bf5df=https://10.16.21.123:2380,vlado-mgmt-cp-3525a81a39-ndqxl-84cd0312=https://10.16.21.112:2380
initial-cluster-state: existing
listen-client-http-urls: https://127.0.0.1:2382
listen-client-urls: https://127.0.0.1:2379,https://10.16.21.112:2379
listen-metrics-urls: http://127.0.0.1:2381,http://10.16.21.112:2381
listen-peer-urls: https://127.0.0.1:2380,https://10.16.21.112:2380
log-outputs:
- stderr
logger: zap
name: vlado-mgmt-cp-3525a81a39-ndqxl-84cd0312
peer-transport-security:
  cert-file: /var/lib/rancher/rke2/server/tls/etcd/peer-server-client.crt
  client-cert-auth: true
  key-file: /var/lib/rancher/rke2/server/tls/etcd/peer-server-client.key
  trusted-ca-file: /var/lib/rancher/rke2/server/tls/etcd/peer-ca.crt
quota-backend-bytes: 4294967296
snapshot-count: 10000
socket-options:
  reuse-address: true
  reuse-port: true

OR

vlado-mgmt-cp-3525a81a39-ndqxl:~ # cat /var/lib/rancher/rke2/server/db/etcd/config
advertise-client-urls: https://10.16.21.112:2379
auto-compaction-mode: periodic
auto-compaction-retention: 12h0m0s
client-transport-security:
  cert-file: /var/lib/rancher/rke2/server/tls/etcd/server-client.crt
  client-cert-auth: true
  key-file: /var/lib/rancher/rke2/server/tls/etcd/server-client.key
  trusted-ca-file: /var/lib/rancher/rke2/server/tls/etcd/server-ca.crt
data-dir: /var/lib/rancher/rke2/server/db/etcd
election-timeout: 5000
experimental-initial-corrupt-check: true
experimental-watch-progress-notify-interval: 5000000000
heartbeat-interval: 500
initial-advertise-peer-urls: https://10.16.21.112:2380
initial-cluster: vlado-mgmt-cp-3525a81a39-jz2kt-9c7bf5df=https://10.16.21.123:2380,vlado-mgmt-cp-3525a81a39-ndqxl-84cd0312=https://10.16.21.112:2380
initial-cluster-state: existing
listen-client-http-urls: https://127.0.0.1:2382
listen-client-urls: https://127.0.0.1:2379,https://10.16.21.112:2379
listen-metrics-urls: http://127.0.0.1:2381,http://10.16.21.112:2381
listen-peer-urls: https://127.0.0.1:2380,https://10.16.21.112:2380
log-outputs:
- stderr
- /var/lib/rancher/rke2/server/db/etcd/etcd-internal.log
logger: zap
name: vlado-mgmt-cp-3525a81a39-ndqxl-84cd0312
peer-transport-security:
  cert-file: /var/lib/rancher/rke2/server/tls/etcd/peer-server-client.crt
  client-cert-auth: true
  key-file: /var/lib/rancher/rke2/server/tls/etcd/peer-server-client.key
  trusted-ca-file: /var/lib/rancher/rke2/server/tls/etcd/peer-ca.crt
quota-backend-bytes: 4294967296
snapshot-count: 10000
socket-options:
  reuse-address: true
  reuse-port: true

Bug is no longer reproducing with config:

$ cat /var/lib/rancher/rke2/server/db/etcd/config
advertise-client-urls: https://10.16.21.112:2379
auto-compaction-mode: periodic
auto-compaction-retention: 12h0m0s
client-transport-security:
  cert-file: /var/lib/rancher/rke2/server/tls/etcd/server-client.crt
  client-cert-auth: true
  key-file: /var/lib/rancher/rke2/server/tls/etcd/server-client.key
  trusted-ca-file: /var/lib/rancher/rke2/server/tls/etcd/server-ca.crt
data-dir: /var/lib/rancher/rke2/server/db/etcd
election-timeout: 5000
experimental-initial-corrupt-check: true
experimental-watch-progress-notify-interval: 5000000000
heartbeat-interval: 500
initial-advertise-peer-urls: https://10.16.21.112:2380
initial-cluster: vlado-mgmt-cp-3525a81a39-jz2kt-9c7bf5df=https://10.16.21.123:2380,vlado-mgmt-cp-3525a81a39-ndqxl-84cd0312=https://10.16.21.112:2380
initial-cluster-state: existing
listen-client-http-urls: https://127.0.0.1:2382
listen-client-urls: https://127.0.0.1:2379,https://10.16.21.112:2379
listen-metrics-urls: http://127.0.0.1:2381,http://10.16.21.112:2381
listen-peer-urls: https://127.0.0.1:2380,https://10.16.21.112:2380
log-outputs:
- /var/lib/rancher/rke2/server/db/etcd/etcd-internal.log
logger: zap
name: vlado-mgmt-cp-3525a81a39-ndqxl-84cd0312
peer-transport-security:
  cert-file: /var/lib/rancher/rke2/server/tls/etcd/peer-server-client.crt
  client-cert-auth: true
  key-file: /var/lib/rancher/rke2/server/tls/etcd/peer-server-client.key
  trusted-ca-file: /var/lib/rancher/rke2/server/tls/etcd/peer-ca.crt
quota-backend-bytes: 4294967296
snapshot-count: 10000
socket-options:
  reuse-address: true
  reuse-port: true

Etcd debug information (please run commands below, feel free to obfuscate the IP address or FQDN in the output)

No response

Relevant log output

[brandond]

etcd itself is never killed and keeps running as an orphaned process

I do want to correct this statement. etcd is not an orphan process. It is a child of the shim, and containerd will resume managing the shim and its child processes when it is started again. This is an intentional part of containerd's design, and allows containers to remain running without disruption even when containerd itself is upgraded. See the upstream docs: https://containerd.io/docs/2.3/ops/#systemd

We want to be able to upgrade containerd and allow existing containers to keep running without interruption. Setting KillMode to process ensures that systemd only kills the containerd daemon and not any child processes such as the shims and containers.

When running etcd in containerd, this can be reproduced by stopping the containerd service. The etcd container continues running and can be interacted with normally for a while, but eventually etcd will hang when zap's writes to stdout/stderr block. This can be accelerated by taking down the network on the local node, or stopping/disconnecting other cluster members... anything that causes etcd so start writing a higher volume of logs.

I will also note that this may take an enhancement to uber-go/zap to resolve. etcd just passes in the provided log paths. For stderr and stdout zap just wraps go's os.Stdout/os.Stderr with a no-op closer, and in the case of multiple outputs combines them using zapcore.multiWriteSyncer which just writes to each sink in turn. If os.Stderr.Write() hangs, then zap will hang as well.

[brandond]

See proof of concept nonblocking zap log sink here: https://github.com/brandond/playground-zap

This should probably be taken upstream to zap.