Stolon does not recover after temporary full disk on master keeper #912

nh2 · 2023-08-15T11:28:10Z

What happened

Today we had a production outage of a 11 minutes, suspectedly because:

Stolon does not correctly recover from the master's disk being full. It stops serving pg_basebackup requests from follower nodes.

The downtime lasted only 11 minutes because I manually restarted the master stolon-keeper that stopped serving pg_basebackup requests.

I observed the following in our 3-node Stolon cluster composed of nodes node-4, node-5, node-6:

node-5 temporarily ran out of disk space while being stolon master.
The other 2 nodes tried to sync up with the node-5 master, by running pg_basebackup.
Disk space was freed on node-5.
Stolon did not recover from the master having a full-disk event:
- The follower DB nodes were blocked in pg_basebackup, and restarting them did not help.
  - Last logs of followers: pg_basebackup: initiating base backup, waiting for checkpoint to complete
- Apparently the Stolon master stopped serving pg_basebackup responses after the full-disk event, even though disk space was freed up.
- This looks like a Stolon bug to me.
  - Maybe similar to a Stolon bug we hit earlier, with the common Go bug of not checking the return value of Write...() functions:
    - One stolon-keeper fails to start #359 (comment)
    - https://github.com/sorintlab/stolon/pull/495/files#diff-e888c3a094beb4b948ad27b6e53e11278bc828126f187e0e2ed21c60855d8e90L781

What you expected to happen

Stolon should serve pg_basebackup responses when the disk is no longer full.

How to reproduce it (as minimally and precisely as possible)

I have not yet tried to reproduce it exactly, as I am not sure how to trigger the other 2 nodes trying to do pg_basebackup at the correct time.

Logs

Follower logs

Follower logs hanging in pg_basebackup: initiating base backup, waiting for checkpoint to complete:

Click to expand logs

Aug 15 10:25:08 node-4 keeper[3426683]: 2023-08-15T10:25:08.700Z        INFO        cmd/keeper.go:1576        already standby
Aug 15 10:25:08 node-4 keeper[3426683]: 2023-08-15T10:25:08.717Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:25:08 node-4 keeper[3426683]: 2023-08-15T10:25:08.717Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:25:10 node-4 keeper[3426683]: 2023-08-15T10:25:10.734Z        INFO        cmd/keeper.go:1141        current db UID different than cluster data db UID        {"db": "c6cb2f35", "cdDB": "6f2488cf"}
Aug 15 10:25:10 node-4 keeper[3426683]: 2023-08-15T10:25:10.734Z        INFO        cmd/keeper.go:1296        resyncing the database cluster
Aug 15 10:25:10 node-4 keeper[3426683]: 2023-08-15T10:25:10.736Z        INFO        postgresql/postgresql.go:384        stopping database
Aug 15 10:25:10 node-4 keeper[1624016]: waiting for server to shut down.... done
Aug 15 10:25:10 node-4 keeper[1624016]: server stopped
Aug 15 10:25:10 node-4 keeper[3426683]: 2023-08-15T10:25:10.848Z        INFO        cmd/keeper.go:899        syncing using pg_rewind        {"masterDB": "140f41c1", "keeper": "node_5"}
Aug 15 10:25:10 node-4 keeper[3426683]: 2023-08-15T10:25:10.848Z        INFO        postgresql/postgresql.go:921        running pg_rewind
Aug 15 10:25:10 node-4 keeper[1624020]: pg_rewind: fetched file "global/pg_control", length 8192
Aug 15 10:25:10 node-4 keeper[1624020]: pg_rewind: source and target cluster are on the same timeline
Aug 15 10:25:10 node-4 keeper[1624020]: pg_rewind: no rewind required
Aug 15 10:25:10 node-4 keeper[3426683]: 2023-08-15T10:25:10.865Z        INFO        postgresql/postgresql.go:844        writing standby signal file
Aug 15 10:25:10 node-4 keeper[3426683]: 2023-08-15T10:25:10.865Z        INFO        postgresql/postgresql.go:319        starting database
Aug 15 10:25:10 node-4 keeper[1624022]: 2023-08-15 10:25:10.874 UTC [1624022] LOG:  redirecting log output to logging collector process
Aug 15 10:25:10 node-4 keeper[1624022]: 2023-08-15 10:25:10.874 UTC [1624022] HINT:  Future log output will appear in directory "/var/log/postgres".
Aug 15 10:25:11 node-4 keeper[3426683]: 2023-08-15T10:25:11.103Z        INFO        cmd/keeper.go:968        followed instance timeline forked before our current state        {"followedTimeline": 33, "followedXlogpos": 454746433152, "timeline": 32, "xlogpos": 454827696368}
Aug 15 10:25:11 node-4 keeper[3426683]: 2023-08-15T10:25:11.103Z        INFO        postgresql/postgresql.go:384        stopping database
Aug 15 10:25:11 node-4 keeper[1624036]: waiting for server to shut down.... done
Aug 15 10:25:11 node-4 keeper[1624036]: server stopped
Aug 15 10:25:11 node-4 keeper[3426683]: 2023-08-15T10:25:11.389Z        INFO        cmd/keeper.go:925        syncing from followed db        {"followedDB": "140f41c1", "keeper": "node_5"}
Aug 15 10:25:11 node-4 keeper[3426683]: 2023-08-15T10:25:11.389Z        INFO        postgresql/postgresql.go:964        running pg_basebackup
Aug 15 10:25:11 node-4 keeper[3426683]: pg_basebackup: initiating base backup, waiting for checkpoint to complete

Master logs

Logs of the master while it was not serving the other nodes' pg_basebackup requests:

Click to expand logs

Aug 15 10:26:49 benaco-node-5 keeper[2851117]: 2023-08-15T10:26:49.899Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:26:49 benaco-node-5 keeper[2851117]: 2023-08-15T10:26:49.916Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:26:49 benaco-node-5 keeper[2851117]: 2023-08-15T10:26:49.916Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:26:51 benaco-node-5 keeper[2851117]: 2023-08-15T10:26:51.946Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:26:51 benaco-node-5 keeper[2851117]: 2023-08-15T10:26:51.947Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:26:51 benaco-node-5 keeper[2851117]: 2023-08-15T10:26:51.963Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:26:51 benaco-node-5 keeper[2851117]: 2023-08-15T10:26:51.964Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed

Logs of the master keeper during the entirety of the event, from the initial No space left on device to recovery by my manual restart of the keeper:

Click to expand logs

Aug 15 09:54:07 node-5 keeper[2851117]: 2023-08-15T09:54:07.306Z        INFO        cmd/keeper.go:1543        already master
Aug 15 09:54:07 node-5 keeper[2851117]: 2023-08-15T09:54:07.320Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 09:54:07 node-5 keeper[2851117]: 2023-08-15T09:54:07.320Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 09:54:07 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:54:07 node-5 keeper[2851286]: could not write to log file: No space left on device
...
Aug 15 09:54:09 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:54:09 node-5 keeper[2851117]: 2023-08-15T09:54:09.351Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:54:09 node-5 keeper[2851117]: 2023-08-15T09:54:09.352Z        INFO        cmd/keeper.go:1543        already master
Aug 15 09:54:09 node-5 keeper[2851117]: 2023-08-15T09:54:09.366Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 09:54:09 node-5 keeper[2851117]: 2023-08-15T09:54:09.366Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 09:54:09 node-5 keeper[2851117]: 2023-08-15T09:54:09.377Z        ERROR        cmd/keeper.go:1742        failed to save db local state        {"error": "write /var/lib/postgres/node_5/dbstate848970997: no space left on device"}
Aug 15 09:54:09 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:54:10 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:54:10 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:54:10 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:54:11 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:54:11 node-5 keeper[2851117]: 2023-08-15T09:54:11.403Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:54:11 node-5 keeper[2851117]: 2023-08-15T09:54:11.403Z        INFO        cmd/keeper.go:1543        already master
Aug 15 09:54:11 node-5 keeper[2851117]: 2023-08-15T09:54:11.419Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 09:54:11 node-5 keeper[2851117]: 2023-08-15T09:54:11.419Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 09:54:11 node-5 keeper[2851117]: 2023-08-15T09:54:11.430Z        ERROR        cmd/keeper.go:1742        failed to save db local state        {"error": "write /var/lib/postgres/node_5/dbstate696989648: no space left on device"}
Aug 15 09:54:12 node-5 keeper[2851286]: could not write to log file: No space left on device
...
Aug 15 09:58:51 node-5 keeper[2851117]: 2023-08-15T09:58:51.980Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:58:51 node-5 keeper[2851117]: 2023-08-15T09:58:51.981Z        INFO        cmd/keeper.go:1543        already master
Aug 15 09:58:51 node-5 keeper[2851117]: 2023-08-15T09:58:51.994Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 09:58:51 node-5 keeper[2851117]: 2023-08-15T09:58:51.995Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 09:58:52 node-5 keeper[2851117]: 2023-08-15T09:58:52.004Z        ERROR        cmd/keeper.go:1742        failed to save db local state        {"error": "write /var/lib/postgres/node_5/dbstate453193463: no space left on device"}
Aug 15 09:58:53 node-5 keeper[2851286]: could not write to log file: No space left on device
Aug 15 09:58:54 node-5 keeper[2851117]: 2023-08-15T09:58:54.024Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:58:54 node-5 keeper[2851117]: 2023-08-15T09:58:54.024Z        INFO        cmd/keeper.go:1543        already master
Aug 15 09:58:54 node-5 keeper[2851117]: 2023-08-15T09:58:54.041Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 09:58:54 node-5 keeper[2851117]: 2023-08-15T09:58:54.042Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 09:58:54 node-5 keeper[2851117]: 2023-08-15T09:58:54.054Z        ERROR        cmd/keeper.go:1742        failed to save db local state        {"error": "write /var/lib/postgres/node_5/dbstate195438570: no space left on device"}
Aug 15 09:58:56 node-5 keeper[2851117]: 2023-08-15T09:58:56.071Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:58:56 node-5 keeper[2851117]: 2023-08-15T09:58:56.073Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:58:56 node-5 keeper[2851117]: 2023-08-15T09:58:56.073Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 09:58:56 node-5 keeper[2851117]: 2023-08-15T09:58:56.076Z        ERROR        cmd/keeper.go:1527        failed to start postgres        {"error": "error writing postgresql.conf file: write /var/lib/postgres/node_5/postgres/postgresql.conf900267073: no space left on device"}
Aug 15 09:58:57 node-5 keeper[2851117]: 2023-08-15T09:58:57.072Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:58:58 node-5 keeper[2851117]: 2023-08-15T09:58:58.073Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:58:58 node-5 keeper[2851117]: 2023-08-15T09:58:58.092Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:58:58 node-5 keeper[2851117]: 2023-08-15T09:58:58.093Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 09:58:58 node-5 keeper[2851117]: 2023-08-15T09:58:58.096Z        ERROR        cmd/keeper.go:1527        failed to start postgres        {"error": "error writing postgresql.conf file: write /var/lib/postgres/node_5/postgres/postgresql.conf974015148: no space left on device"}
Aug 15 09:58:59 node-5 keeper[2851117]: 2023-08-15T09:58:59.074Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:00 node-5 keeper[2851117]: 2023-08-15T09:59:00.075Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:00 node-5 keeper[2851117]: 2023-08-15T09:59:00.118Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:59:00 node-5 keeper[2851117]: 2023-08-15T09:59:00.118Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 09:59:00 node-5 keeper[2851117]: 2023-08-15T09:59:00.124Z        ERROR        cmd/keeper.go:1527        failed to start postgres        {"error": "error writing postgresql.conf file: write /var/lib/postgres/node_5/postgres/postgresql.conf941834779: no space left on device"}
Aug 15 09:59:01 node-5 keeper[2851117]: 2023-08-15T09:59:01.076Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:02 node-5 keeper[2851117]: 2023-08-15T09:59:02.077Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:02 node-5 keeper[2851117]: 2023-08-15T09:59:02.148Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:59:02 node-5 keeper[2851117]: 2023-08-15T09:59:02.149Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 09:59:02 node-5 keeper[2851117]: 2023-08-15T09:59:02.152Z        ERROR        cmd/keeper.go:1527        failed to start postgres        {"error": "error writing postgresql.conf file: write /var/lib/postgres/node_5/postgres/postgresql.conf076239550: no space left on device"}
Aug 15 09:59:03 node-5 keeper[2851117]: 2023-08-15T09:59:03.078Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:04 node-5 keeper[2851117]: 2023-08-15T09:59:04.079Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:04 node-5 keeper[2851117]: 2023-08-15T09:59:04.171Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:59:04 node-5 keeper[2851117]: 2023-08-15T09:59:04.171Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 09:59:04 node-5 keeper[2851117]: 2023-08-15T09:59:04.175Z        ERROR        cmd/keeper.go:1527        failed to start postgres        {"error": "error writing postgresql.conf file: write /var/lib/postgres/node_5/postgres/postgresql.conf252173061: no space left on device"}
Aug 15 09:59:05 node-5 keeper[2851117]: 2023-08-15T09:59:05.080Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:06 node-5 keeper[2851117]: 2023-08-15T09:59:06.080Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:06 node-5 keeper[2851117]: 2023-08-15T09:59:06.197Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 09:59:06 node-5 keeper[2851117]: 2023-08-15T09:59:06.198Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 09:59:06 node-5 keeper[2851117]: 2023-08-15T09:59:06.203Z        ERROR        cmd/keeper.go:1527        failed to start postgres        {"error": "error writing postgresql.conf file: write /var/lib/postgres/node_5/postgres/postgresql.conf224427168: no space left on device"}
Aug 15 09:59:07 node-5 keeper[2851117]: 2023-08-15T09:59:07.081Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:08 node-5 keeper[2851117]: 2023-08-15T09:59:08.082Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:08 node-5 keeper[2851117]: 2023-08-15T09:59:08.207Z        INFO        cmd/keeper.go:1141        current db UID different than cluster data db UID        {"db": "3397fb23", "cdDB": "140f41c1"}
Aug 15 09:59:08 node-5 keeper[2851117]: 2023-08-15T09:59:08.207Z        INFO        cmd/keeper.go:1296        resyncing the database cluster
Aug 15 09:59:08 node-5 keeper[2851117]: 2023-08-15T09:59:08.208Z        ERROR        cmd/keeper.go:1305        failed to save db local state        {"error": "write /var/lib/postgres/node_5/dbstate649249151: no space left on device"}
Aug 15 09:59:09 node-5 keeper[2851117]: 2023-08-15T09:59:09.083Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:10 node-5 keeper[2851117]: 2023-08-15T09:59:10.084Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:10 node-5 keeper[2851117]: 2023-08-15T09:59:10.212Z        INFO        cmd/keeper.go:1141        current db UID different than cluster data db UID        {"db": "3397fb23", "cdDB": "140f41c1"}
Aug 15 09:59:10 node-5 keeper[2851117]: 2023-08-15T09:59:10.212Z        INFO        cmd/keeper.go:1296        resyncing the database cluster
Aug 15 09:59:10 node-5 keeper[2851117]: 2023-08-15T09:59:10.212Z        ERROR        cmd/keeper.go:1305        failed to save db local state        {"error": "write /var/lib/postgres/node_5/dbstate210388178: no space left on device"}
Aug 15 09:59:11 node-5 keeper[2851117]: 2023-08-15T09:59:11.085Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:12 node-5 keeper[2851117]: 2023-08-15T09:59:12.086Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 09:59:12 node-5 keeper[2851117]: 2023-08-15T09:59:12.216Z        INFO        cmd/keeper.go:1141        current db UID different than cluster data db UID        {"db": "3397fb23", "cdDB": "140f41c1"}
Aug 15 09:59:12 node-5 keeper[2851117]: 2023-08-15T09:59:12.216Z        INFO        cmd/keeper.go:1296        resyncing the database cluster
...
Aug 15 10:06:07 node-5 keeper[2851117]: 2023-08-15T10:06:07.270Z        INFO        cmd/keeper.go:1296        resyncing the database cluster
Aug 15 10:06:07 node-5 keeper[2851117]: 2023-08-15T10:06:07.270Z        ERROR        cmd/keeper.go:1305        failed to save db local state        {"error": "write /var/lib/postgres/node_5/dbstate789537122: no space left on device"}
Aug 15 10:06:07 node-5 keeper[2851117]: 2023-08-15T10:06:07.440Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:06:08 node-5 keeper[2851117]: 2023-08-15T10:06:08.441Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:06:09 node-5 keeper[2851117]: 2023-08-15T10:06:09.274Z        INFO        cmd/keeper.go:1141        current db UID different than cluster data db UID        {"db": "3397fb23", "cdDB": "140f41c1"}
Aug 15 10:06:09 node-5 keeper[2851117]: 2023-08-15T10:06:09.274Z        INFO        cmd/keeper.go:1296        resyncing the database cluster
Aug 15 10:06:09 node-5 keeper[2851117]: 2023-08-15T10:06:09.288Z        INFO        cmd/keeper.go:899        syncing using pg_rewind        {"masterDB": "32e06e90", "keeper": "node_6"}
Aug 15 10:06:09 node-5 keeper[2851117]: 2023-08-15T10:06:09.288Z        INFO        postgresql/postgresql.go:921        running pg_rewind
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: executing "/nix/store/swc4d2nvp800dibijq09ksbw26nwg6yp-postgresql-14.1/bin/postgres" for target server to complete crash recovery
Aug 15 10:06:09 node-5 keeper[1081939]: 2023-08-15 10:06:09.314 GMT [1081939] LOG:  skipping missing configuration file "/var/lib/postgres/node_5/postgres/postgresql.auto.conf"
Aug 15 10:06:09 node-5 keeper[1081939]: 2023-08-15 10:06:09.318 UTC [1081939] LOG:  database system shutdown was interrupted; last known up at 2023-08-15 09:58:55 UTC
Aug 15 10:06:09 node-5 keeper[1081939]: 2023-08-15 10:06:09.319 UTC [1081939] LOG:  database system was not properly shut down; automatic recovery in progress
Aug 15 10:06:09 node-5 keeper[1081939]: 2023-08-15 10:06:09.319 UTC [1081939] LOG:  redo starts at 69/C835E230
Aug 15 10:06:09 node-5 keeper[1081939]: 2023-08-15 10:06:09.359 UTC [1081939] LOG:  invalid record length at 69/CAC1E670: wanted 24, got 0
Aug 15 10:06:09 node-5 keeper[1081939]: 2023-08-15 10:06:09.359 UTC [1081939] LOG:  redo done at 69/CAC1E648 system usage: CPU: user: 0.02 s, system: 0.01 s, elapsed: 0.04 s
Aug 15 10:06:09 node-5 keeper[1081939]: PostgreSQL stand-alone backend 14.1
Aug 15 10:06:09 node-5 keeper[1081939]: backend>
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: fetched file "global/pg_control", length 8192
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: fetched file "pg_wal/00000020.history", length 1379
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: Source timeline history:
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: Target timeline history:
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: 1: 0/0 - 5/B8C7E6D0
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: 2: 5/B8C7E6D0 - 8/F66E8E98
...
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: received chunk for file "pg_wal/0000002000000069000000CC", offset 4194304, size 1048576
Aug 15 10:06:09 node-5 keeper[1081936]: pg_rewind: fatal: could not write file "/var/lib/postgres/node_5/postgres/pg_wal/0000002000000069000000CC": No space left on device
Aug 15 10:06:09 node-5 keeper[2851117]: 2023-08-15T10:06:09.541Z        ERROR        cmd/keeper.go:902        error syncing with pg_rewind        {"error": "error: exit status 1"}
Aug 15 10:06:09 node-5 keeper[2851117]: 2023-08-15T10:06:09.779Z        INFO        cmd/keeper.go:925        syncing from followed db        {"followedDB": "32e06e90", "keeper": "node_6"}
Aug 15 10:06:09 node-5 keeper[2851117]: 2023-08-15T10:06:09.780Z        INFO        postgresql/postgresql.go:964        running pg_basebackup
Aug 15 10:06:09 node-5 keeper[2851117]: pg_basebackup: initiating base backup, waiting for checkpoint to complete
Aug 15 10:07:41 node-5 keeper[2851117]: WARNING:  skipping special file "./postgresql.auto.conf"
Aug 15 10:07:41 node-5 keeper[2851117]: pg_basebackup: checkpoint completed
Aug 15 10:07:41 node-5 keeper[2851117]: pg_basebackup: write-ahead log start point: 69/D4000098 on timeline 32
Aug 15 10:07:41 node-5 keeper[2851117]: pg_basebackup: starting background WAL receiver
Aug 15 10:07:41 node-5 keeper[2851117]:       0/3622590 kB (0%), 0/1 tablespace (...aco_node_5/postgres/backup_label)
Aug 15 10:07:41 node-5 keeper[2851117]: WARNING:  skipping special file "./postgresql.auto.conf"
Aug 15 10:07:42 node-5 keeper[2851117]:  131258/3622590 kB (3%), 0/1 tablespace (...de_5/postgres/base/14756/16490.1)
Aug 15 10:07:43 node-5 keeper[2851117]:  419610/3622590 kB (11%), 0/1 tablespace (...de_5/postgres/base/14756/16490.1)
Aug 15 10:07:44 node-5 keeper[2851117]:  713658/3622590 kB (19%), 0/1 tablespace (...de_5/postgres/base/14756/16490.1)
Aug 15 10:07:45 node-5 keeper[2851117]:  979354/3622590 kB (27%), 0/1 tablespace (...de_5/postgres/base/14756/16490.1)
Aug 15 10:07:46 node-5 keeper[2851117]: 1275102/3622590 kB (35%), 0/1 tablespace (...node_5/postgres/base/14756/16490)
Aug 15 10:07:47 node-5 keeper[2851117]: 1567422/3622590 kB (43%), 0/1 tablespace (...node_5/postgres/base/14756/16490)
Aug 15 10:07:48 node-5 keeper[2851117]: 1914206/3622590 kB (52%), 0/1 tablespace (...node_5/postgres/base/14756/16490)
Aug 15 10:07:49 node-5 keeper[2851117]: 2207486/3622590 kB (60%), 0/1 tablespace (...node_5/postgres/base/14756/16490)
Aug 15 10:07:50 node-5 keeper[2851117]: 2527241/3622590 kB (69%), 0/1 tablespace (...node_5/postgres/base/14756/26274)
Aug 15 10:07:51 node-5 keeper[2851117]: 2817748/3622590 kB (77%), 0/1 tablespace (...node_5/postgres/base/14756/26160)
Aug 15 10:07:52 node-5 keeper[2851117]: 3082790/3622590 kB (85%), 0/1 tablespace (...node_5/postgres/base/14756/16493)
Aug 15 10:07:53 node-5 keeper[2851117]: 3311206/3622590 kB (91%), 0/1 tablespace (...node_5/postgres/base/14756/16493)
Aug 15 10:07:54 node-5 keeper[2851117]: 3604134/3622590 kB (99%), 0/1 tablespace (...node_5/postgres/base/14756/16493)
Aug 15 10:07:54 node-5 keeper[2851117]: 3625760/3625760 kB (100%), 0/1 tablespace (...ode_5/postgres/global/pg_control)
Aug 15 10:07:54 node-5 keeper[2851117]: 3625760/3625760 kB (100%), 1/1 tablespace
Aug 15 10:07:54 node-5 keeper[2851117]: pg_basebackup: write-ahead log end point: 69/D5DFAC98
Aug 15 10:07:54 node-5 keeper[2851117]: pg_basebackup: waiting for background process to finish streaming ...
Aug 15 10:07:54 node-5 keeper[2851117]: pg_basebackup: syncing data to disk ...
Aug 15 10:07:54 node-5 keeper[2851117]: 2023-08-15T10:07:54.509Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:07:55 node-5 keeper[2851117]: 2023-08-15T10:07:55.509Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:07:56 node-5 keeper[2851117]: 2023-08-15T10:07:56.510Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:07:57 node-5 keeper[2851117]: 2023-08-15T10:07:57.511Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:07:58 node-5 keeper[2851117]: 2023-08-15T10:07:58.511Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:07:59 node-5 keeper[2851117]: 2023-08-15T10:07:59.512Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:08:00 node-5 keeper[2851117]: 2023-08-15T10:08:00.513Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.514Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:08:01 node-5 keeper[2851117]: pg_basebackup: renaming backup_manifest.tmp to backup_manifest
Aug 15 10:08:01 node-5 keeper[2851117]: pg_basebackup: base backup completed
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.546Z        INFO        cmd/keeper.go:931        sync succeeded
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.552Z        INFO        postgresql/postgresql.go:844        writing standby signal file
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.552Z        INFO        postgresql/postgresql.go:319        starting database
Aug 15 10:08:01 node-5 keeper[1082418]: 2023-08-15 10:08:01.563 UTC [1082418] LOG:  redirecting log output to logging collector process
Aug 15 10:08:01 node-5 keeper[1082418]: 2023-08-15 10:08:01.563 UTC [1082418] HINT:  Future log output will appear in directory "/var/log/postgres".
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.801Z        INFO        cmd/keeper.go:1557        our db requested role is standby        {"followedDB": "32e06e90"}
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.801Z        INFO        cmd/keeper.go:1576        already standby
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.815Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:08:01 node-5 keeper[2851117]: 2023-08-15T10:08:01.815Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:08:03 node-5 keeper[2851117]: 2023-08-15T10:08:03.843Z        INFO        cmd/keeper.go:1557        our db requested role is standby        {"followedDB": "32e06e90"}
Aug 15 10:08:03 node-5 keeper[2851117]: 2023-08-15T10:08:03.844Z        INFO        cmd/keeper.go:1576        already standby
...
Aug 15 10:19:53 node-5 keeper[2851117]: 2023-08-15T10:19:53.774Z        INFO        cmd/keeper.go:1576        already standby
Aug 15 10:19:53 node-5 keeper[2851117]: 2023-08-15T10:19:53.791Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:19:53 node-5 keeper[2851117]: 2023-08-15T10:19:53.791Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:19:55 node-5 keeper[2851117]: 2023-08-15T10:19:55.821Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:19:55 node-5 keeper[2851117]: 2023-08-15T10:19:55.822Z        INFO        cmd/keeper.go:1537        promoting to master
Aug 15 10:19:55 node-5 keeper[2851117]: 2023-08-15T10:19:55.822Z        INFO        postgresql/postgresql.go:532        promoting database
Aug 15 10:19:56 node-5 keeper[1090879]: waiting for server to promote....
Aug 15 10:19:56 node-5 keeper[2851117]: 2023-08-15T10:19:56.234Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:19:57 node-5 keeper[1090879]: .
Aug 15 10:19:57 node-5 keeper[2851117]: 2023-08-15T10:19:57.235Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:19:58 node-5 keeper[1090879]: .
...
Aug 15 10:20:55 node-5 keeper[2851117]: 2023-08-15T10:20:55.282Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:20:55 node-5 keeper[1090879]:  stopped waiting
Aug 15 10:20:55 node-5 keeper[1090879]: pg_ctl: server did not promote in time
Aug 15 10:20:55 node-5 keeper[2851117]: 2023-08-15T10:20:55.898Z        ERROR        cmd/keeper.go:1539        failed to promote instance        {"error": "error: exit status 1"}
Aug 15 10:20:56 node-5 keeper[2851117]: 2023-08-15T10:20:56.283Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:20:57 node-5 keeper[2851117]: 2023-08-15T10:20:57.285Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:20:57 node-5 keeper[2851117]: 2023-08-15T10:20:57.913Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:20:57 node-5 keeper[2851117]: 2023-08-15T10:20:57.913Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 10:20:57 node-5 keeper[2851117]: 2023-08-15T10:20:57.919Z        INFO        postgresql/postgresql.go:319        starting database
Aug 15 10:20:57 node-5 keeper[1091196]: 2023-08-15 10:20:57.931 UTC [1091196] LOG:  redirecting log output to logging collector process
Aug 15 10:20:57 node-5 keeper[1091196]: 2023-08-15 10:20:57.931 UTC [1091196] HINT:  Future log output will appear in directory "/var/log/postgres".
Aug 15 10:20:58 node-5 keeper[2851117]: 2023-08-15T10:20:58.129Z        INFO        cmd/keeper.go:1537        promoting to master
Aug 15 10:20:58 node-5 keeper[2851117]: 2023-08-15T10:20:58.129Z        INFO        postgresql/postgresql.go:532        promoting database
Aug 15 10:20:58 node-5 keeper[1091203]: waiting for server to promote....
Aug 15 10:20:58 node-5 keeper[2851117]: 2023-08-15T10:20:58.286Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:20:59 node-5 keeper[1091203]: .
Aug 15 10:20:59 node-5 keeper[2851117]: 2023-08-15T10:20:59.287Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:21:00 node-5 keeper[1091203]: .
...
Aug 15 10:21:57 node-5 keeper[2851117]: 2023-08-15T10:21:57.336Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:21:58 node-5 keeper[1091203]:  stopped waiting
Aug 15 10:21:58 node-5 keeper[1091203]: pg_ctl: server did not promote in time
Aug 15 10:21:58 node-5 keeper[2851117]: 2023-08-15T10:21:58.205Z        ERROR        cmd/keeper.go:1539        failed to promote instance        {"error": "error: exit status 1"}
Aug 15 10:21:58 node-5 keeper[2851117]: 2023-08-15T10:21:58.337Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:21:59 node-5 keeper[2851117]: 2023-08-15T10:21:59.338Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:22:00 node-5 keeper[2851117]: 2023-08-15T10:22:00.228Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:22:00 node-5 keeper[2851117]: 2023-08-15T10:22:00.229Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 10:22:00 node-5 keeper[2851117]: 2023-08-15T10:22:00.234Z        INFO        postgresql/postgresql.go:319        starting database
Aug 15 10:22:00 node-5 keeper[1091541]: 2023-08-15 10:22:00.242 UTC [1091541] LOG:  redirecting log output to logging collector process
Aug 15 10:22:00 node-5 keeper[1091541]: 2023-08-15 10:22:00.242 UTC [1091541] HINT:  Future log output will appear in directory "/var/log/postgres".
Aug 15 10:22:00 node-5 keeper[2851117]: 2023-08-15T10:22:00.339Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "pq: the database system is not yet accepting connections"}
Aug 15 10:22:00 node-5 keeper[2851117]: 2023-08-15T10:22:00.444Z        INFO        cmd/keeper.go:1537        promoting to master
Aug 15 10:22:00 node-5 keeper[2851117]: 2023-08-15T10:22:00.444Z        INFO        postgresql/postgresql.go:532        promoting database
Aug 15 10:22:01 node-5 keeper[1091549]: waiting for server to promote....
Aug 15 10:22:01 node-5 keeper[2851117]: 2023-08-15T10:22:01.340Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:22:02 node-5 keeper[1091549]: .
...
Aug 15 10:25:04 node-5 keeper[2851117]: 2023-08-15T10:25:04.483Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:25:05 node-5 keeper[1092235]:  stopped waiting
Aug 15 10:25:05 node-5 keeper[1092235]: pg_ctl: server did not promote in time
Aug 15 10:25:05 node-5 keeper[2851117]: 2023-08-15T10:25:05.145Z        ERROR        cmd/keeper.go:1539        failed to promote instance        {"error": "error: exit status 1"}
Aug 15 10:25:05 node-5 keeper[2851117]: 2023-08-15T10:25:05.483Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:25:06 node-5 keeper[2851117]: 2023-08-15T10:25:06.484Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.165Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.166Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.172Z        INFO        postgresql/postgresql.go:319        starting database
Aug 15 10:25:07 node-5 keeper[1093152]: 2023-08-15 10:25:07.179 UTC [1093152] LOG:  redirecting log output to logging collector process
Aug 15 10:25:07 node-5 keeper[1093152]: 2023-08-15 10:25:07.179 UTC [1093152] HINT:  Future log output will appear in directory "/var/log/postgres".
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.380Z        INFO        cmd/keeper.go:1537        promoting to master
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.380Z        INFO        postgresql/postgresql.go:532        promoting database
Aug 15 10:25:07 node-5 keeper[1093160]: waiting for server to promote.... done
Aug 15 10:25:07 node-5 keeper[1093160]: server promoted
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.600Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.607Z        INFO        cmd/keeper.go:1689        not allowing connection as normal users since synchronous replication is enabled, instance was down and not all sync standbys are synced
Aug 15 10:25:07 node-5 keeper[2851117]: 2023-08-15T10:25:07.607Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:25:09 node-5 keeper[2851117]: 2023-08-15T10:25:09.634Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:25:09 node-5 keeper[2851117]: 2023-08-15T10:25:09.634Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:25:09 node-5 keeper[2851117]: 2023-08-15T10:25:09.651Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:25:09 node-5 keeper[2851117]: 2023-08-15T10:25:09.657Z        INFO        cmd/keeper.go:1689        not allowing connection as normal users since synchronous replication is enabled, instance was down and not all sync standbys are synced
Aug 15 10:25:09 node-5 keeper[2851117]: 2023-08-15T10:25:09.657Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.691Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.692Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.697Z        INFO        cmd/keeper.go:1008        creating replication slot        {"slot": "stolon_6f2488cf"}
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.702Z        INFO        cmd/keeper.go:1008        creating replication slot        {"slot": "stolon_e1e06025"}
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.719Z        INFO        cmd/keeper.go:1659        needed synchronous_standby_names changed        {"prevSyncStandbyNames": "2 (stolon_32e06e90,stolon_c6cb2f35)", "syncStandbyNames": "stolonfakestandby"}
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.720Z        INFO        cmd/keeper.go:1671        postgres parameters changed, reloading postgres instance
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.726Z        INFO        cmd/keeper.go:1698        postgres hba entries changed, reloading postgres instance
Aug 15 10:25:11 node-5 keeper[2851117]: 2023-08-15T10:25:11.726Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Aug 15 10:25:11 node-5 keeper[1093240]: server signaled
Aug 15 10:25:13 node-5 keeper[2851117]: 2023-08-15T10:25:13.765Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:25:13 node-5 keeper[2851117]: 2023-08-15T10:25:13.765Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:25:13 node-5 keeper[2851117]: 2023-08-15T10:25:13.782Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:25:13 node-5 keeper[2851117]: 2023-08-15T10:25:13.782Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:25:15 node-5 keeper[2851117]: 2023-08-15T10:25:15.810Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:25:15 node-5 keeper[2851117]: 2023-08-15T10:25:15.811Z        INFO        cmd/keeper.go:1543        already master
...
Aug 15 10:30:04 node-5 keeper[2851117]: 2023-08-15T10:30:04.855Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:30:04 node-5 keeper[2851117]: 2023-08-15T10:30:04.855Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:06 node-5 keeper[2851117]: 2023-08-15T10:30:06.885Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:06 node-5 keeper[2851117]: 2023-08-15T10:30:06.886Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:06 node-5 keeper[2851117]: 2023-08-15T10:30:06.901Z        INFO        cmd/keeper.go:1659        needed synchronous_standby_names changed        {"prevSyncStandbyNames": "stolonfakestandby", "syncStandbyNames": "stolon_e1e06025"}
Aug 15 10:30:06 node-5 keeper[2851117]: 2023-08-15T10:30:06.901Z        INFO        cmd/keeper.go:1671        postgres parameters changed, reloading postgres instance
Aug 15 10:30:06 node-5 keeper[2851117]: 2023-08-15T10:30:06.901Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:06 node-5 keeper[2851117]: 2023-08-15T10:30:06.901Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Aug 15 10:30:06 node-5 keeper[1096714]: server signaled
Aug 15 10:30:08 node-5 keeper[2851117]: 2023-08-15T10:30:08.936Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:08 node-5 keeper[2851117]: 2023-08-15T10:30:08.937Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:08 node-5 keeper[2851117]: 2023-08-15T10:30:08.951Z        INFO        cmd/keeper.go:1659        needed synchronous_standby_names changed        {"prevSyncStandbyNames": "stolon_e1e06025", "syncStandbyNames": "2 (stolon_6f2488cf,stolon_e1e06025)"}
Aug 15 10:30:08 node-5 keeper[2851117]: 2023-08-15T10:30:08.951Z        INFO        cmd/keeper.go:1671        postgres parameters changed, reloading postgres instance
Aug 15 10:30:08 node-5 keeper[2851117]: 2023-08-15T10:30:08.951Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:08 node-5 keeper[2851117]: 2023-08-15T10:30:08.951Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Aug 15 10:30:08 node-5 keeper[1096820]: server signaled
Aug 15 10:30:10 node-5 keeper[2851117]: 2023-08-15T10:30:10.988Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:10 node-5 keeper[2851117]: 2023-08-15T10:30:10.989Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:11 node-5 keeper[2851117]: 2023-08-15T10:30:11.005Z        INFO        cmd/keeper.go:1659        needed synchronous_standby_names changed        {"prevSyncStandbyNames": "2 (stolon_6f2488cf,stolon_e1e06025)", "syncStandbyNames": "stolon_e1e06025"}
Aug 15 10:30:11 node-5 keeper[2851117]: 2023-08-15T10:30:11.005Z        INFO        cmd/keeper.go:1671        postgres parameters changed, reloading postgres instance
Aug 15 10:30:11 node-5 keeper[2851117]: 2023-08-15T10:30:11.005Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:11 node-5 keeper[2851117]: 2023-08-15T10:30:11.005Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Aug 15 10:30:11 node-5 keeper[1096842]: server signaled
Aug 15 10:30:13 node-5 keeper[2851117]: 2023-08-15T10:30:13.044Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:13 node-5 keeper[2851117]: 2023-08-15T10:30:13.045Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:13 node-5 keeper[2851117]: 2023-08-15T10:30:13.061Z        INFO        cmd/keeper.go:1659        needed synchronous_standby_names changed        {"prevSyncStandbyNames": "stolon_e1e06025", "syncStandbyNames": "2 (stolon_6f2488cf,stolon_e1e06025)"}
Aug 15 10:30:13 node-5 keeper[2851117]: 2023-08-15T10:30:13.061Z        INFO        cmd/keeper.go:1671        postgres parameters changed, reloading postgres instance
Aug 15 10:30:13 node-5 keeper[2851117]: 2023-08-15T10:30:13.061Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:13 node-5 keeper[2851117]: 2023-08-15T10:30:13.061Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Aug 15 10:30:13 node-5 keeper[1096863]: server signaled
Aug 15 10:30:15 node-5 keeper[2851117]: 2023-08-15T10:30:15.097Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:15 node-5 keeper[2851117]: 2023-08-15T10:30:15.098Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:15 node-5 keeper[2851117]: 2023-08-15T10:30:15.111Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:30:15 node-5 keeper[2851117]: 2023-08-15T10:30:15.111Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:17 node-5 keeper[2851117]: 2023-08-15T10:30:17.143Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:17 node-5 keeper[2851117]: 2023-08-15T10:30:17.143Z        INFO        cmd/keeper.go:1543        already master
...
Aug 15 10:30:31 node-5 keeper[2851117]: 2023-08-15T10:30:31.457Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:31 node-5 keeper[2851117]: 2023-08-15T10:30:31.469Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:30:31 node-5 keeper[2851117]: 2023-08-15T10:30:31.469Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
    [This is where I issued `systemctl restart stolon-keeper.service`]
Aug 15 10:30:33 node-5 systemd[1]: Stopping stolon-keeper.service...
Aug 15 10:30:33 node-5 keeper[2851117]: 2023-08-15T10:30:33.368Z        INFO        postgresql/postgresql.go:384        stopping database
Aug 15 10:30:33 node-5 keeper[1097088]: waiting for server to shut down.... done
Aug 15 10:30:33 node-5 keeper[1097088]: server stopped
Aug 15 10:30:33 node-5 systemd[1]: stolon-keeper.service: Deactivated successfully.
Aug 15 10:30:33 node-5 systemd[1]: Stopped stolon-keeper.service.
Aug 15 10:30:33 node-5 systemd[1]: stolon-keeper.service: Consumed 1d 22h 12min 41.405s CPU time, received 270.5G IP traffic, sent 4.4T IP traffic.
Aug 15 10:30:33 node-5 systemd[1]: Started stolon-keeper.service.
Aug 15 10:30:33 node-5 keeper[1097096]: 2023-08-15T10:30:33.663Z        WARN        cmd/keeper.go:2058        superuser name and replication user name are the same. Different users are suggested.
Aug 15 10:30:33 node-5 keeper[1097096]: 2023-08-15T10:30:33.664Z        INFO        cmd/keeper.go:2091        exclusive lock on data dir taken
Aug 15 10:30:33 node-5 keeper[1097096]: 2023-08-15T10:30:33.664Z        INFO        cmd/keeper.go:569        keeper uid        {"uid": "node_5"}
Aug 15 10:30:33 node-5 keeper[1097096]: 2023-08-15T10:30:33.669Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:30:33 node-5 keeper[1097096]: 2023-08-15T10:30:33.672Z        INFO        cmd/keeper.go:1094        our db boot UID is different than the cluster data one, waiting for it to be updated        {"bootUUID": "f0a92617-3e63-41f5-bf04-cb1313408fb6", "clusterBootUUID": "def68dec-a5fe-4b09-8561-e952f9bf347d"}
Aug 15 10:30:34 node-5 keeper[1097096]: 2023-08-15T10:30:34.669Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.669Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "dial unix /tmp/.s.PGSQL.5432: connect: no such file or directory"}
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.692Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.693Z        INFO        cmd/keeper.go:1522        not allowing connection as normal users since synchronous replication is enabled and instance was down
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.700Z        INFO        postgresql/postgresql.go:319        starting database
Aug 15 10:30:35 node-5 keeper[1097135]: 2023-08-15 10:30:35.707 UTC [1097135] LOG:  redirecting log output to logging collector process
Aug 15 10:30:35 node-5 keeper[1097135]: 2023-08-15 10:30:35.707 UTC [1097135] HINT:  Future log output will appear in directory "/var/log/postgres".
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.908Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.922Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.928Z        INFO        cmd/keeper.go:1689        not allowing connection as normal users since synchronous replication is enabled, instance was down and not all sync standbys are synced
Aug 15 10:30:35 node-5 keeper[1097096]: 2023-08-15T10:30:35.928Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:37 node-5 keeper[1097096]: 2023-08-15T10:30:37.968Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:37 node-5 keeper[1097096]: 2023-08-15T10:30:37.969Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:37 node-5 keeper[1097096]: 2023-08-15T10:30:37.984Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:30:37 node-5 keeper[1097096]: 2023-08-15T10:30:37.990Z        INFO        cmd/keeper.go:1689        not allowing connection as normal users since synchronous replication is enabled, instance was down and not all sync standbys are synced
Aug 15 10:30:37 node-5 keeper[1097096]: 2023-08-15T10:30:37.990Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:40 node-5 keeper[1097096]: 2023-08-15T10:30:40.021Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:40 node-5 keeper[1097096]: 2023-08-15T10:30:40.022Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:40 node-5 keeper[1097096]: 2023-08-15T10:30:40.036Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:30:40 node-5 keeper[1097096]: 2023-08-15T10:30:40.043Z        INFO        cmd/keeper.go:1698        postgres hba entries changed, reloading postgres instance
Aug 15 10:30:40 node-5 keeper[1097096]: 2023-08-15T10:30:40.043Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Aug 15 10:30:40 node-5 keeper[1097497]: server signaled
Aug 15 10:30:42 node-5 keeper[1097096]: 2023-08-15T10:30:42.079Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:42 node-5 keeper[1097096]: 2023-08-15T10:30:42.079Z        INFO        cmd/keeper.go:1543        already master
Aug 15 10:30:42 node-5 keeper[1097096]: 2023-08-15T10:30:42.095Z        INFO        cmd/keeper.go:1676        postgres parameters not changed
Aug 15 10:30:42 node-5 keeper[1097096]: 2023-08-15T10:30:42.096Z        INFO        cmd/keeper.go:1703        postgres hba entries not changed
Aug 15 10:30:44 node-5 keeper[1097096]: 2023-08-15T10:30:44.124Z        INFO        cmd/keeper.go:1505        our db requested role is master
Aug 15 10:30:44 node-5 keeper[1097096]: 2023-08-15T10:30:44.125Z        INFO        cmd/keeper.go:1543        already master

Environment

Stolon version: Stolon master commit 4bb4107

The text was updated successfully, but these errors were encountered:

nh2 · 2023-12-08T23:47:26Z

This happened again today, but this time when the disk was not full on the machine that stopped serving pg_basebackup requests.

Logs:

Dec 08 19:34:40 node-5 keeper[8753]: 2023-12-08T19:34:40.334Z        ERROR        cmd/keeper.go:1042        error retrieving cluster data        {"error": "Unexpected response code: 500"}
Dec 08 19:38:20 node-5 keeper[8753]: 2023-12-08T19:38:20.423Z        ERROR        cmd/keeper.go:1042        error retrieving cluster data        {"error": "Unexpected response code: 500"}
Dec 08 20:44:03 node-5 keeper[8753]: 2023-12-08T20:44:03.792Z        ERROR        cmd/keeper.go:720        cannot get configured pg parameters        {"error": "pq: canceling statement due to user request"}
Dec 08 20:44:03 node-5 keeper[8753]: 2023-12-08T20:44:03.928Z        ERROR        cmd/keeper.go:871        failed to update keeper info        {"error": "cannot set or renew session for ttl, unable to operate on sessions"}
Dec 08 22:08:20 node-5 keeper[8753]: 2023-12-08T22:08:20.932Z        ERROR        cmd/keeper.go:871        failed to update keeper info        {"error": "cannot set or renew session for ttl, unable to operate on sessions"}
Dec 08 23:33:35 node-5 keeper[8753]: 2023-12-08T23:33:35.942Z        INFO        cmd/keeper.go:1537        promoting to master
Dec 08 23:33:35 node-5 keeper[8753]: 2023-12-08T23:33:35.942Z        INFO        postgresql/postgresql.go:532        promoting database
Dec 08 23:33:36 node-5 keeper[4154967]: waiting for server to promote.... done
Dec 08 23:33:36 node-5 keeper[4154967]: server promoted
Dec 08 23:33:36 node-5 keeper[8753]: 2023-12-08T23:33:36.065Z        INFO        cmd/keeper.go:1659        needed synchronous_standby_names changed        {"prevSyncStandbyNames": "", "syncStandbyNames": "2 (stolon_816e776e,stolon_b07431bd)"}
Dec 08 23:33:36 node-5 keeper[8753]: 2023-12-08T23:33:36.065Z        INFO        cmd/keeper.go:1671        postgres parameters changed, reloading postgres instance
Dec 08 23:33:36 node-5 keeper[8753]: 2023-12-08T23:33:36.065Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Dec 08 23:33:36 node-5 keeper[4154980]: server signaled
Dec 08 23:33:40 node-5 keeper[8753]: 2023-12-08T23:33:40.173Z        INFO        cmd/keeper.go:1008        creating replication slot        {"slot": "stolon_1669dd8f"}
Dec 08 23:33:40 node-5 keeper[8753]: 2023-12-08T23:33:40.187Z        INFO        cmd/keeper.go:1659        needed synchronous_standby_names changed        {"prevSyncStandbyNames": "2 (stolon_816e776e,stolon_b07431bd)", "syncStandbyNames": "stolonfakestandby"}
Dec 08 23:33:40 node-5 keeper[8753]: 2023-12-08T23:33:40.187Z        INFO        cmd/keeper.go:1671        postgres parameters changed, reloading postgres instance
Dec 08 23:33:40 node-5 keeper[8753]: 2023-12-08T23:33:40.187Z        INFO        postgresql/postgresql.go:421        reloading database configuration
Dec 08 23:33:40 node-5 keeper[4155110]: server signaled
Dec 08 23:33:44 node-5 keeper[8753]: 2023-12-08T23:33:44.278Z        INFO        cmd/keeper.go:1008        creating replication slot        {"slot": "stolon_dad62528"}
Dec 08 23:40:03 node-5 systemd[1]: Stopping stolon-keeper.service...
Dec 08 23:40:03 node-5 keeper[8753]: 2023-12-08T23:40:03.109Z        ERROR        cmd/keeper.go:843        failed to stop pg instance        {"error": "cannot get instance state: signal: terminated"}
Dec 08 23:40:03 node-5 systemd[1]: stolon-keeper.service: Deactivated successfully.
Dec 08 23:40:03 node-5 systemd[1]: Stopped stolon-keeper.service.

The issue started 23:33. At 23:40 I restarted the problematic stolon-keeper.

rezaxd · 2024-04-26T17:43:50Z

I have the same issue. Slaves can't sync with basebackup.
Master logs:

2024-04-26T17:42:48.210Z        ERROR   cmd/keeper.go:720       cannot get configured pg parameters     {"error": "pq: the database system is starting up"}
2024-04-26T17:42:48.752Z        INFO    cmd/keeper.go:1505      our db requested role is master
2024-04-26T17:42:48.754Z        INFO    cmd/keeper.go:1543      already master
2024-04-26 17:42:48.755 UTC [17047] FATAL:  the database system is starting up

rezaxd · 2024-04-29T09:12:43Z

In my situation master fixed using restart sentinels and remove slave keepers. For followers, remove keeper, restart sentinels and pg_resetwal fixed problem.

nh2 added the bug label Aug 15, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stolon does not recover after temporary full disk on master keeper #912

Stolon does not recover after temporary full disk on master keeper #912

nh2 commented Aug 15, 2023

nh2 commented Dec 8, 2023

rezaxd commented Apr 26, 2024

rezaxd commented Apr 29, 2024 •

edited

Stolon does not recover after temporary full disk on master keeper #912

Stolon does not recover after temporary full disk on master keeper #912

Comments

nh2 commented Aug 15, 2023

What happened

What you expected to happen

How to reproduce it (as minimally and precisely as possible)

Logs

Follower logs

Master logs

Environment

nh2 commented Dec 8, 2023

rezaxd commented Apr 26, 2024

rezaxd commented Apr 29, 2024 • edited

rezaxd commented Apr 29, 2024 •

edited