Wenn das Storage stottert

Key-Value (KV) Stores sind in Cloudumgebungen eine nicht wegzudenkende Komponente. Viele KV Stores verfügen über einen Replikations- und Clustermechanismus, um unzuverlässigen Netzwerkverbindungen zum Trotz "ausfallsicher" zu sein. Oft kommt dazu der Raft-Algorithmus zum Einsatz, der bei einer ungeraden Anzahl von Instanzen dafür sorgen soll, dass der Inhalt des KV Stores für andere (Dienste) les- und schreibbar bleibt - auch wenn Instanzen des Clusters plötzlich ausfallen.

Dabei werden Schreibvorgänge nur beim "Leader" durchgeführt. Diese landen in einem Log (wie in Logbuch), dieses Log wird dann im Zuge von Transaktionen zu den "Followern" repliziert. Auf diese Weise soll sichergestellt werden, dass "Leader" und "Follower" immer auf demselben Stand sind.

Um keine Änderungen im Log zu verlieren, werden diese zyklisch (meist nach einem bestimmten Zeitraum oder nach einer bestimmten Menge Änderungen) auf die Festplatte der jeweiligen Instanz geschrieben.

Die genauen Mechanismen sind von KV Store zu KV Store verschieden. Deswegen ist es vernünftig, sich die Voraussetzungen zu vergegenwärtigen, die der jeweilig verwendete KV Store hat, wenn man das zur Verfügung stehende Storage betrachtet.

Etcd, Redis und Consul führen verschiedene Voraussetzungen an. Je höher die Voraussetzungen, desdo stärker reagiert der KV Store auf Storagelatenzen, was wiederum Folgen für die Ausfallsicherheit haben kann.

Dies ist der "Leader" in einem kleinen Consul Cluster:

root@consul-2:~# consul operator raft list-peers
Node      ID                                    Address             State     Voter  RaftProtocol  Commit Index  Trails Leader By
consul-1  35bdc5f6-c3bc-42d0-6cbc-6cb3fa9fdc23  192.168.0.157:8300  follower  true   3             2915568       0 commits
consul-0  dc7c6daa-35f0-b811-fb93-2c2f2675d6e5  192.168.0.215:8300  follower  true   3             2915568       0 commits
consul-2  1508b554-d281-8bf5-a1ea-02dd4b26e96f  192.168.0.185:8300  leader    true   3             2915568       -

am 24.01. gab es offenbar ein Storageproblem:

Jan 24 00:41:03 consul-2 consul[13136]: 2025-01-24T00:41:03.510Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:44:12 consul-2 kernel: [13538438.015202] INFO: task jbd2/sda1-8:144 blocked for more than 120 seconds.
Jan 24 00:44:12 consul-2 kernel: [13538438.016529]       Not tainted 5.10.0-28-cloud-amd64 #1 Debian 5.10.209-2
Jan 24 00:44:12 consul-2 kernel: [13538438.017811] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 24 00:44:12 consul-2 kernel: [13538438.019256] task:jbd2/sda1-8     state:D stack:    0 pid:  144 ppid:     2 flags:0x00004000
Jan 24 00:44:12 consul-2 kernel: [13538438.020937] Call Trace:
Jan 24 00:44:12 consul-2 kernel: [13538438.021689]  __schedule+0x282/0x870
Jan 24 00:44:12 consul-2 kernel: [13538438.022597]  ? bit_wait+0x60/0x60
Jan 24 00:44:12 consul-2 kernel: [13538438.023595]  schedule+0x46/0xb0
Jan 24 00:44:12 consul-2 kernel: [13538438.024527]  io_schedule+0x42/0x70
Jan 24 00:44:12 consul-2 kernel: [13538438.025490]  bit_wait_io+0xd/0x60
Jan 24 00:44:12 consul-2 kernel: [13538438.026439]  __wait_on_bit+0x2a/0x90
Jan 24 00:44:12 consul-2 kernel: [13538438.027461]  out_of_line_wait_on_bit+0x92/0xb0
[...]

Consul liefert "nur" ein Warning (und auch erst vier Minuten später):

Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:41:38.511Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:42:13.512Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:42:48.513Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:43:23.514Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:43:58.515Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:44:33.516Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:45:08.518Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:45:43.519Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:46:18.520Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:46:53.521Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:47:28.523Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"
Jan 24 00:48:26 consul-2 consul[13136]: 2025-01-24T00:48:03.525Z [WARN]  agent.server.coordinate: Batch update failed: error="timed out enqueuing operation"

Der einzige Raft-Fehler, der gemeldet wird erscheint viel später (und hat möglicherweise nichts mit dem Ereignis zu tun:

Jan 24 10:05:16 consul-2 consul[13136]: 2025-01-24T10:05:16.410Z [ERROR] agent.server.raft: failed to pipeline appendEntries: peer="{Voter dc7c6daa-35f0-b811-fb93-2c2f2675d6e5 192.168.0.215:8300}" error="write tcp 192.168.0.185:44138->192.168.0.215:8300: use of closed network connection"
Jan 24 10:05:16 consul-2 consul[13136]: 2025-01-24T10:05:16.410Z [INFO]  agent.server.raft: aborting pipeline replication: peer="{Voter dc7c6daa-35f0-b811-fb93-2c2f2675d6e5 192.168.0.215:8300}"
Jan 24 10:05:16 consul-2 consul[13136]: 2025-01-24T10:05:16.589Z [INFO]  agent.server.raft: pipelining replication: peer="{Voter dc7c6daa-35f0-b811-fb93-2c2f2675d6e5 192.168.0.215:8300}"

Es gibt keinen Failover oder eine Re-Election eines neuen "Leaders".

In diesem Fall erfolgt die Clusterkommunikation unter anderem über Mesh-Gateways. Die hohe Storagelatenz war auch dort zu sehen:

Jan 24 00:44:06 consul-gateway-0 consul[8856]: [2025-01-24 00:44:06.810][8856][debug][main] [source/server/server.cc:263] flushing stats
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.722738] INFO: task jbd2/sda1-8:144 blocked for more than 120 seconds.
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.724333]       Not tainted 5.10.0-28-cloud-amd64 #1 Debian 5.10.209-2
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.725630] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.727122] task:jbd2/sda1-8     state:D stack:    0 pid:  144 ppid:     2 flags:0x00004000
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.728832] Call Trace:
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.729442]  __schedule+0x282/0x870
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.730359]  ? bit_wait+0x60/0x60
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.731159]  schedule+0x46/0xb0
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.731857]  io_schedule+0x42/0x70
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.732596]  bit_wait_io+0xd/0x60
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.733346]  __wait_on_bit+0x2a/0x90
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.734121]  out_of_line_wait_on_bit+0x92/0xb0
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.735045]  ? var_wake_function+0x30/0x30
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.735871]  jbd2_journal_commit_transaction+0x16ac/0x1ad0
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.736876]  ? sched_clock+0x5/0x10
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.737655]  kjournald2+0xab/0x270
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.738402]  ? add_wait_queue_exclusive+0x70/0x70
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.739385]  ? load_superblock.part.0+0xb0/0xb0
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.740267]  kthread+0x11b/0x140
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.740977]  ? __kthread_bind_mask+0x60/0x60
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.741818]  ret_from_fork+0x22/0x30
Jan 24 00:44:07 consul-gateway-0 kernel: [13536835.742591] INFO: task kworker/u4:2:2267245 blocked for more than 120 seconds.
[...]

Ist aber ohne weitere Auswirkungen auf das Gateway - sobald die Maschine wieder reagiert, geht es weiter:

Jan 24 00:46:08 consul-gateway-0 kernel: [13536956.676056]  ? __kthread_bind_mask+0x60/0x60
Jan 24 00:46:08 consul-gateway-0 kernel: [13536956.676940]  ret_from_fork+0x22/0x30
Jan 24 00:48:35 consul-gateway-0 consul[8856]: [2025-01-24 00:44:11.815][8856][debug][main] [source/server/server.cc:263] flushing stats
Jan 24 00:48:35 consul-gateway-0 consul[8856]: [2025-01-24 00:44:16.818][8856][debug][main] [source/server/server.cc:263] flushing stats
Jan 24 00:48:35 consul-gateway-0 consul[8856]: [2025-01-24 00:44:21.823][8856][debug][main] [source/server/server.cc:263] flushing stats

Dasselbe war auch in einem Consul-Cluster, welches als "distributed configuration service" (DCS) in einer Patroni-Umgebung verwendet wird: Keine Leader-Election, Ähnliche Warnungen wie in diesem Cluster. Der Patroni-Cluster blieb dehalb ebenfalls unverändert. Die Datenbanken hatten zwar ebenfalls mit der erhöhten Latenz des Storage zu kämpfen aber es kam nicht zu einem Failover (der sowieso nichts genützt hätte, da natürlich auch die Follower-Datenbank von der Storagelatenz betroffen war).

Von etcd wissen wir, dass er wesentlich empfindlicher auf Storagelatenzen reagiert und z. B. mit Re-Elections beginnt.

Dazu kommt noch, dass es in einer etcd-Umgebung nur die etcd-Server gibt, die von den Client-Applikationen direkt angesprochen werden. In einem Consul-Cluster, kommunizieren die Client-Applikationen nur mit dem lokal installierten Consul-Client, der seinerseits dann wieder die Kommunikation mit dem Consul-Server übernimmt. Parallel dazu kommuniziert er aber auch über das Gossip-Protokoll mit den anderen Consul-Clients und -Servern im Cluster. Auf diese Weise lassen sich Fehlerzustände leichter erkennen und den Cluster besser (oder gar nicht) darauf reagieren.

Bisher haben sich sie entsprechenden Cluster als durchaus robust im Angesicht von Storagelatenzen erwiesen.