Multiple primaries in Kubernetes during node failure and network partition
Author: wb14123Created Oct 26, 2024Updated Sep 30, 2025
Labelsquestionci
What happened?
When run a Jepsen test with Patroni (https://github.com/wb14123/jepsen-postgres-ha), it observes multiple primaries through the tests, when some node failure and network partition events happened.
The test setup a 3 nodes Kubernetes cluster with k3s, and deploy it with this yaml file. Then it randomly takes down the primary node and create network partition. At the same time it tries to get primary nodes using kubectl get pods -L role -o wide.
The test itself will report failure at the end. However, just giving an example here, here is how the cluster ended in one of my test:
kubectl get pods -L role -o wide
NAME READY STATUS RESTARTS AGE IP NODE NOMINATED NODE READINESS GATES ROLE
patronidemo-0 1/1 Running 1 (4m27s ago) 9m47s 10.42.2.3 postgres-server-3 <none> <none> primary
patronidemo-1 1/1 Running 0 9m12s 10.42.1.2 postgres-server-2 <none> <none> primary
patronidemo-2 1/1 Running 1 (4m28s ago) 8m52s 10.42.0.8 postgres-server-1 <none> <none> replicaHow can we reproduce it (as minimally and precisely as possible)?
Download the project here. Install requirements. Follow here to setup Vagrant VMs. And run the command:
lein run test --nodes-file ./nodes --username vagrant -w check-primary --concurrency 1 --isolation serializable --nemesis partition,kill --time-limit 600 -r 1 --max-writes-per-key 16 --nemesis-interval 120 --cluster patroniThis will run the tests for 10 minutes. The test will import node failures and network partition for primary nodes.
What did you expect to happen?
There should be at most 1 primary nodes at any given time.
Patroni/PostgreSQL/DCS version
Using the docker image built from commit 969d7ec4, using the Dockerfile.
- Patroni version: v4.0.3
- PostgreSQL version: 16.
- DCS (and its version):
Patroni configuration file
It is deployed through Kubernetes using this yaml file: https://github.com/wb14123/jepsen-postgres-ha/blob/master/cluster/patroni/k8s.yamlpatronictl show-config
postgres@patronidemo-0:~$ patronictl show-config
postgresql:
pg_hba:
- host all all 0.0.0.0/0 md5
- host replication standby 10.42.0.10/16 md5
- host replication standby 127.0.0.1/32 md5
use_pg_rewind: truePatroni log files
# logs are from `kubectl logs ...` so the logs before the node crash may lost.
# node 0:
2024-10-26 03:35:01,883 INFO: Selected new K8s API server endpoint https://192.168.56.3:6443
2024-10-26 03:35:08,157 INFO: No PostgreSQL configuration items changed, nothing to reload.
2024-10-26 03:35:08,165 INFO: Reaped pid=12, exit status=0
2024-10-26 03:35:08,171 INFO: Reaped pid=15, exit status=0
2024-10-26 03:35:08,171 WARNING: Postgresql is not running.
2024-10-26 03:35:08,172 INFO: Lock owner: patronidemo-1; I am patronidemo-0
2024-10-26 03:35:08,183 INFO: Reaped pid=16, exit status=0
2024-10-26 03:35:08,184 INFO: pg_controldata:
pg_control version number: 1300
Catalog version number: 202307071
Database system identifier: 7429921490361479191
Database cluster state: in production
pg_control last modified: Sat Oct 26 03:30:16 2024
Latest checkpoint location: 0/3000060
Latest checkpoint's REDO location: 0/3000028
Latest checkpoint's REDO WAL file: 000000010000000000000003
Latest checkpoint's TimeLineID: 1
Latest checkpoint's PrevTimeLineID: 1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID: 0:733
Latest checkpoint's NextOID: 24576
Latest checkpoint's NextMultiXactId: 1
Latest checkpoint's NextMultiOffset: 0
Latest checkpoint's oldestXID: 723
Latest checkpoint's oldestXID's DB: 1
Latest checkpoint's oldestActiveXID: 733
Latest checkpoint's oldestMultiXid: 1
Latest checkpoint's oldestMulti's DB: 1
Latest checkpoint's oldestCommitTsXid: 0
Latest checkpoint's newestCommitTsXid: 0
Time of latest checkpoint: Sat Oct 26 03:30:16 2024
Fake LSN counter for unlogged rels: 0/3E8
Minimum recovery ending location: 0/0
Min recovery ending loc's timeline: 0
Backup start location: 0/0
Backup end location: 0/0
End-of-backup record required: no
wal_level setting: replica
wal_log_hints setting: on
max_connections setting: 100
max_worker_processes setting: 8
max_wal_senders setting: 10
max_prepared_xacts setting: 0
max_locks_per_xact setting: 64
track_commit_timestamp setting: off
Maximum data alignment: 8
Database block size: 8192
Blocks per segment of large relation: 131072
WAL block size: 8192
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chunk: 1996
Size of a large-object chunk: 2048
Date/time type storage: 64-bit integers
Float8 argument passing: by value
Data page checksum version: 1
Mock authentication nonce: e71f8193c5240fa7ec520c71dd6b0948d7af291a6e839c91faea92c067b7ef1d
2024-10-26 03:35:08,209 INFO: Reaped pid=18, exit status=0
2024-10-26 03:35:08,289 INFO: doing crash recovery in a single user mode
2024-10-26 03:35:08,289 INFO: Lock owner: patronidemo-1; I am patronidemo-0
2024-10-26 03:35:08,290 INFO: doing crash recovery in a single user mode in progress
2024-10-26 03:35:08,682 WARNING: Postgresql is not running.
2024-10-26 03:35:08,682 INFO: Lock owner: patronidemo-1; I am patronidemo-0
2024-10-26 03:35:08,685 INFO: Reaped pid=24, exit status=0
2024-10-26 03:35:08,685 INFO: pg_controldata:
pg_control version number: 1300
Catalog version number: 202307071
Database system identifier: 7429921490361479191
Database cluster state: shut down
pg_control last modified: Sat Oct 26 03:35:08 2024
Latest checkpoint location: 0/5000028
Latest checkpoint's REDO location: 0/5000028
Latest checkpoint's REDO WAL file: 000000010000000000000005
Latest checkpoint's TimeLineID: 1
Latest checkpoint's PrevTimeLineID: 1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID: 0:744
Latest checkpoint's NextOID: 24576
Latest checkpoint's NextMultiXactId: 1
Latest checkpoint's NextMultiOffset: 0
Latest checkpoint's oldestXID: 723
Latest checkpoint's oldestXID's DB: 1
Latest checkpoint's oldestActiveXID: 0
Latest checkpoint's oldestMultiXid: 1
Latest checkpoint's oldestMulti's DB: 1
Latest checkpoint's oldestCommitTsXid: 0
Latest checkpoint's newestCommitTsXid: 0
Time of latest checkpoint: Sat Oct 26 03:35:08 2024
Fake LSN counter for unlogged rels: 0/3E8
Minimum recovery ending location: 0/0
Min recovery ending loc's timeline: 0
Backup start location: 0/0
Backup end location: 0/0
End-of-backup record required: no
wal_level setting: replica
wal_log_hints setting: on
max_connections setting: 100
max_worker_processes setting: 8
max_wal_senders setting: 10
max_prepared_xacts setting: 0
max_locks_per_xact setting: 64
track_commit_timestamp setting: off
Maximum data alignment: 8
Database block size: 8192
Blocks per segment of large relation: 131072
WAL block size: 8192
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chunk: 1996
Size of a large-object chunk: 2048
Date/time type storage: 64-bit integers
Float8 argument passing: by value
Data page checksum version: 1
Mock authentication nonce: e71f8193c5240fa7ec520c71dd6b0948d7af291a6e839c91faea92c067b7ef1d
2024-10-26 03:35:08,685 INFO: Lock owner: patronidemo-1; I am patronidemo-0
2024-10-26 03:35:08,694 INFO: Reaped pid=26, exit status=0
2024-10-26 03:35:08,696 INFO: Reaped pid=27, exit status=0
2024-10-26 03:35:08,696 INFO: Local timeline=1 lsn=0/5000028
2024-10-26 03:35:08,708 INFO: primary_timeline=2
2024-10-26 03:35:08,709 INFO: primary: history=1 0/404D580 no recovery target specified
2024-10-26 03:35:08,717 INFO: Reaped pid=29, exit status=0
2024-10-26 03:35:08,718 INFO: Reaped pid=30, exit status=0
2024-10-26 03:35:08,719 INFO: running pg_rewind from patronidemo-1
2024-10-26 03:35:08,761 INFO: running pg_rewind from dbname=postgres user=postgres host=10.42.1.3 port=5432 target_session_attrs=read-write
2024-10-26 03:35:10,356 INFO: pg_rewind exit code=0
2024-10-26 03:35:10,356 INFO: stdout=
2024-10-26 03:35:10,356 INFO: stderr=pg_rewind: servers diverged at WAL location 0/404D580 on timeline 1
pg_rewind: rewinding from last common checkpoint at 0/3000060 on timeline 1
pg_rewind: Done!
2024-10-26 03:35:10,357 WARNING: Postgresql is not running.
2024-10-26 03:35:10,357 INFO: Lock owner: patronidemo-1; I am patronidemo-0
2024-10-26 03:35:10,358 INFO: Reaped pid=36, exit status=0
2024-10-26 03:35:10,359 INFO: pg_controldata:
pg_control version number: 1300
Catalog version number: 202307071
Database system identifier: 7429921490361479191
Database cluster state: in archive recovery
pg_control last modified: Sat Oct 26 03:35:10 2024
Latest checkpoint location: 0/404D6D0
Latest checkpoint's REDO location: 0/404D698
Latest checkpoint's REDO WAL file: 000000020000000000000004
Latest checkpoint's TimeLineID: 2
Latest checkpoint's PrevTimeLineID: 2
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID: 0:744
Latest checkpoint's NextOID: 24576
Latest checkpoint's NextMultiXactId: 1
Latest checkpoint's NextMultiOffset: 0
Latest checkpoint's oldestXID: 723
Latest checkpoint's oldestXID's DB: 1
Latest checkpoint's oldestActiveXID: 744
Latest checkpoint's oldestMultiXid: 1
Latest checkpoint's oldestMulti's DB: 1
Latest checkpoint's oldestCommitTsXid: 0
Latest checkpoint's newestCommitTsXid: 0
Time of latest checkpoint: Sat Oct 26 03:33:16 2024
Fake LSN counter for unlogged rels: 0/3E8
Minimum recovery ending location: 0/404D780
Min recovery ending loc's timeline: 2
Backup start location: 0/0
Backup end location: 0/0
End-of-backup record required: no
wal_level setting: replica
wal_log_hints setting: on
max_connections setting: 100
max_worker_processes setting: 8
max_wal_senders setting: 10
max_prepared_xacts setting: 0
max_locks_per_xact setting: 64
track_commit_timestamp setting: off
Maximum data alignment: 8
Database block size: 8192
Blocks per segment of large relation: 131072
WAL block size: 8192
Bytes per WAL segment: 16777216
Maximum length of identifiers: 64
Maximum columns in an index: 32
Maximum size of a TOAST chunk: 1996
Size of a large-object chunk: 2048
Date/time type storage: 64-bit integers
Float8 argument passing: by value
Data page checksum version: 1
Mock authentication nonce: e71f8193c5240fa7ec520c71dd6b0948d7af291a6e839c91faea92c067b7ef1d
2024-10-26 03:35:10,359 INFO: Lock owner: patronidemo-1; I am patronidemo-0
2024-10-26 03:35:10,359 INFO: starting as a secondary
2024-10-26 03:35:10.921 UTC [42] LOG: starting PostgreSQL 16.4 (Debian 16.4-1.pgdg120+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2024-10-26 03:35:10.921 UTC [42] LOG: listening on IPv4 address "0.0.0.0", port 5432
2024-10-26 03:35:10.925 UTC [42] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2024-10-26 03:35:10,938 INFO: postmaster pid=42
2024-10-26 03:35:10.939 UTC [45] LOG: database system was interrupted while in recovery at log time 2024-10-26 03:33:16 UTC
2024-10-26 03:35:10.939 UTC [45] HINT: If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2024-10-26 03:35:11.007 UTC [47] FATAL: the database system is starting up
localhost:5432 - rejecting connections
2024-10-26 03:35:11.059 UTC [45] LOG: entering standby mode
2024-10-26 03:35:11.059 UTC [45] LOG: starting backup recovery with redo LSN 0/3000028, checkpoint LSN 0/3000060, on timeline ID 1
2024-10-26 03:35:11.062 UTC [45] LOG: redo starts at 0/3000028
2024-10-26 03:35:11.063 UTC [45] LOG: completed backup recovery with redo LSN 0/3000028 and end LSN 0/3000100
2024-10-26 03:35:11.064 UTC [45] LOG: consistent recovery state reached at 0/404D780
2024-10-26 03:35:11.064 UTC [45] LOG: invalid record length at 0/404D780: expected at least 24, got 0
2024-10-26 03:35:11.064 UTC [42] LOG: database system is ready to accept read-only connections
2024-10-26 03:35:11.076 UTC [49] LOG: started streaming WAL from primary at 0/4000000 on timeline 2
localhost:5432 - accepting connections
2024-10-26 03:35:11,092 INFO: Lock owner: patronidemo-1; I am patronidemo-0
2024-10-26 03:35:11,092 INFO: establishing a new patroni heartbeat connection to postgres
2024-10-26 03:35:11,197 INFO: no action. I am (patronidemo-0), a secondary, and following a leader (patronidemo-1)
2024-10-26 03:35:16,416 INFO: no action. I am (patronidemo-0), a secondary, and following a leader (patronidemo-1)
2024-10-26 03:35:17,929 ERROR: ObjectCache.run ProtocolError("Connection broken: InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got length b'', 0 bytes read))
2024-10-26 03:35:17,931 ERROR: ObjectCache.run ProtocolError("Connection broken: InvalidChunkLength(got length b'', 0 bytes read)", InvalidChunkLength(got length b'', 0 bytes read))
2024-10-26 03:35:18,110 ERROR: Request to server https://192.168.56.3:6443 failed: MaxRetryError("HTTPSConnectionPool(host='192.168.56.3', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/endpoints?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by ProtocolError('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer')))")
2024-10-26 03:35:18,110 INFO: Retrying on https://192.168.56.2:6443
2024-10-26 03:35:18,120 ERROR: Request to server https://192.168.56.3:6443 failed: MaxRetryError("HTTPSConnectionPool(host='192.168.56.3', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/pods?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by ProtocolError('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer')))")
2024-10-26 03:35:18,120 INFO: Retrying on https://192.168.56.2:6443
2024-10-26 03:35:18.216 UTC [49] FATAL: could not receive data from WAL stream: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
2024-10-26 03:35:18.249 UTC [55] FATAL: could not connect to the primary server: connection to server at "10.42.1.3", port 5432 failed: Connection refused
Is the server running on that host and accepting TCP/IP connections?
2024-10-26 03:35:18.250 UTC [45] LOG: waiting for WAL to become available at 0/4002000
2024-10-26 03:35:21,452 ERROR: Request to server https://192.168.56.2:6443 failed: MaxRetryError('HTTPSConnectionPool(host=\'192.168.56.2\', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/endpoints?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by ReadTimeoutError("HTTPSConnectionPool(host=\'192.168.56.2\', port=6443): Read timed out. (read timeout=3.2898557833332993)"))')
2024-10-26 03:35:21,452 INFO: Retrying on https://192.168.56.4:6443
2024-10-26 03:35:21,471 ERROR: Request to server https://192.168.56.2:6443 failed: MaxRetryError('HTTPSConnectionPool(host=\'192.168.56.2\', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/pods?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by ReadTimeoutError("HTTPSConnectionPool(host=\'192.168.56.2\', port=6443): Read timed out. (read timeout=3.3005952073334206)"))')
2024-10-26 03:35:21,471 INFO: Retrying on https://192.168.56.4:6443
2024-10-26 03:35:23.233 UTC [56] FATAL: could not connect to the primary server: connection to server at "10.42.1.3", port 5432 failed: Connection refused
Is the server running on that host and accepting TCP/IP connections?
2024-10-26 03:35:23.234 UTC [45] LOG: waiting for WAL to become available at 0/4002000
2024-10-26 03:35:24,789 ERROR: Request to server https://192.168.56.4:6443 failed: MaxRetryError('HTTPSConnectionPool(host=\'192.168.56.4\', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/endpoints?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by ReadTimeoutError("HTTPSConnectionPool(host=\'192.168.56.4\', port=6443): Read timed out. (read timeout=3.3016312423333907)"))')
2024-10-26 03:35:24,811 ERROR: Request to server https://192.168.56.4:6443 failed: MaxRetryError('HTTPSConnectionPool(host=\'192.168.56.4\', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/pods?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by ReadTimeoutError("HTTPSConnectionPool(host=\'192.168.56.4\', port=6443): Read timed out. (read timeout=3.3174746023333532)"))')
2024-10-26 03:35:26,193 ERROR: ObjectCache.run K8sConnectionFailed('No more API server nodes in the cluster')
2024-10-26 03:35:26,196 WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=0, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f0a51885850>: Failed to establish a new connection: [Errno 111] Connection refused')': /api/v1/namespaces/default/endpoints/kubernetes
2024-10-26 03:35:26,199 ERROR: ObjectCache.run K8sConnectionFailed('No more API server nodes in the cluster')
2024-10-26 03:35:26,234 ERROR: Request to server https://192.168.56.3:6443 failed: MaxRetryError("HTTPSConnectionPool(host='192.168.56.3', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/pods?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f0a51885e10>: Failed to establish a new connection: [Errno 111] Connection refused'))")
2024-10-26 03:35:26,234 INFO: Retrying on https://192.168.56.4:6443
2024-10-26 03:35:26,246 ERROR: Request to server https://192.168.56.3:6443 failed: MaxRetryError("HTTPSConnectionPool(host='192.168.56.3', port=6443): Max retries exceeded with url: /api/v1/namespaces/default/endpoints?labelSelector=application%3Dpatroni%2Ccluster-name%3Dpatronidemo (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f0a5187c810>: Failed to establish a new connection: [Errno 111] Connection refused'))")
2024-10-26 03:35:26,246 INFO: Retrying on https://192.168.56.4:6443
2024-10-26 03:35:26,299 INFO: Selected new K8s API server endpoint https://192.168.56.4:6443
2024-10-26 03:35:26,308 INFO: Selected new K8s API server endpoint https://192.168.56.4:6443
2024-10-26 03:35:26,943 INFO: no action. I am (patronidemo-0), a secondary, and following a leader (patronidemo-1)
2024-10-26 03:35:28.230 UTC [59] FATAL: could not connect to the primary server: connection to server at "10.42.1.3", port 5432 failed: Connection refused
Is the server running on that host and accepting TCP/IP connections?
2024-10-26 03:35:28.230 UTC [45] LOG: waiting for WAL to become available at 0/4002000
2024-10-26 03:35:33.243 UTC [60] FATAL: could not connect to the primary server: connection to server at "10.42.1.3", port 5432 failed: Connection refused
Is the server running on that host and accepting TCP/IP connections?
2024-10-26 03:35:33.243 UTC [45] LOG: waiting for WAL to become available at 0/4002000
2024-10-26 03:35:36,Source: patroni/patroni