BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.

On 07/08/2024 15:19, PG Bug reporting form wrote:

Sometimes pg_rewind mistakenly assumes that nothing needs to be done, which
results in the replica having data that is not on the master.

...
+ pg_rewind --progress --debug '--source-pgdata=standby1'
'--target-pgdata=standby2'
pg_rewind: Source timeline history:
pg_rewind: Target timeline history:
pg_rewind: 1: 0/0 - 0/0
pg_rewind: servers diverged at WAL location 0/10392E8 on timeline 1
pg_rewind: no rewind required

...
Same query
+ psql -d postgres -a --no-psqlrc -p 5001
select count(*) from a;
count
--------
100000
(1 row)

+ echo 'Different results'
Different results
+ psql -d postgres -a --no-psqlrc -p 5002
select count(*) from a;
count
--------
100340
(1 row)

+ echo 'Stop standby1'
Stop standby1
+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-07 17:15:03.077 +05 [19703]
DEBUG: logger shutting down
done
server stopped
+ echo 'Stop standby2'
Stop standby2
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-07 17:15:03.117 +05 [19713]
DEBUG: logger shutting down
done
server stopped
```

I cannot reproduce this. On my laptop, the reported "servers diverged at
WAL location" is always higher, and it performs rewind as expected:

g_rewind: Source timeline history:
pg_rewind: Target timeline history:
pg_rewind: 1: 0/0 - 0/0
pg_rewind: servers diverged at WAL location 0/1138F00 on timeline 1
pg_rewind: rewinding from last common checkpoint at 0/1138E88 on timeline 1

However while looking at the code, I noticed that the debug-output of
the Source timeline history is broken. See attached patch to fix it.
With that fix, I get:

pg_rewind: Source timeline history:
pg_rewind: 1: 0/0 - 0/1138F00
pg_rewind: 2: 0/1138F00 - 0/0
pg_rewind: Target timeline history:
pg_rewind: 1: 0/0 - 0/0
pg_rewind: 0 a: 1 0/0-0/1138F00 - b: 1 0/0-0/0
pg_rewind: servers diverged at WAL location 0/1138F00 on timeline 1
pg_rewind: rewinding from last common checkpoint at 0/1138E88 on timeline 1

That just fixes the debugging output, though, it doesn't change what it
actually does.

Can you try the attached fix show the output you get with that please?
Or alternatively, show the contents of the
standby1/pg_wal/00000002.history file.

--
Heikki Linnakangas
Neon (https://neon.tech)

<div><div>Unfortunately, the playback is not very stable, but sometimes it shoots. I added some commands to show last WAL rows</div><div>script</div><div>```bash</div><div><div>#!/bin/sh -eux</div><div> </div><div># Goto script's directory</div><div>cd "$(dirname "$0")"</div><div># Stop master if exists</div><div>test -f master/postmaster.pid &amp;&amp; pg_ctl -w -D master stop -m fast || echo $?</div><div># Remove master directory</div><div>rm -rf master</div><div># Create master directory</div><div>mkdir -p master</div><div># Initialize master, data checksums are mandatory</div><div>pg_ctl initdb -D master -o "--data-checksums -N -A trust --wal-segsize 1"</div><div># Debug to see recycling WAL, keep only 5 WAL files (because segsize 1MB)</div><div>cat &gt;&gt;master/postgresql.conf &lt;&lt;EOF</div><div>hot_standby = on</div><div>logging_collector = on</div><div>log_min_messages = debug</div><div>#synchronous_standby_names = postgres</div><div>wal_keep_size = 5MB</div><div>EOF</div><div># Accept replication connections on master</div><div>cat &gt;&gt; master/pg_hba.conf &lt;&lt;EOF</div><div>local replication all trust</div><div>host replication all 127.0.0.1/32 trust</div><div>host replication all ::1/128 trust</div><div>EOF</div><div># Start master</div><div>pg_ctl -w -D master start -o "-p 5000"</div><div># Stop standby1 if exists</div><div>test -f standby1/postmaster.pid &amp;&amp; pg_ctl -w -D standby1 stop -m fast || echo $?</div><div># Remove standby1 directory</div><div>rm -rf standby1</div><div># Base backup is taken with xlog files included</div><div>pg_basebackup -D standby1 -p 5000 -X fetch --verbose --write-recovery-conf</div><div># Start standby1</div><div>pg_ctl -w -D standby1 start -o "-p 5001"</div><div># Stop standby2 if exists</div><div>test -f standby2/postmaster.pid &amp;&amp; pg_ctl -w -D standby2 stop -m fast || echo $?</div><div># Remove standby2 directory</div><div>rm -rf standby2</div><div># Base backup is taken with xlog files included</div><div>pg_basebackup -D standby2 -p 5000 -X fetch --verbose --write-recovery-conf</div><div># Start standby2</div><div>pg_ctl -w -D standby2 start -o "-p 5002"</div><div># Create table and insert lot of rows</div><div>psql -d postgres -a --no-psqlrc -p 5000 &lt;&lt;EOF</div><div>create table a (a int, b int);</div><div>insert into a select i, i from generate_series(1, 100000) i;</div><div>EOF</div><div># Stop master to recycle WAL files</div><div>pg_ctl -w -D master stop -m fast</div><div># Stop standby1 to recycle WAL files</div><div>pg_ctl -w -D standby1 stop -m fast</div><div># Stop standby2 to recycle WAL files</div><div>pg_ctl -w -D standby2 stop -m fast</div><div># Start master</div><div>pg_ctl -w -D master start -o "-p 5000"</div><div># Start standby1</div><div>pg_ctl -w -D standby1 start -o "-p 5001"</div><div># Start standby2</div><div>pg_ctl -w -D standby2 start -o "-p 5002"</div><div># Find latest master WAL file</div><div>LAST_MASTER_WAL_FILE="$(pg_controldata master | grep "Latest checkpoint's REDO WAL file:" | cut -d : -f 2 | grep -oP "\w+")"</div><div># Now promote standby1</div><div>pg_ctl -w -D standby1 promote</div><div># Wait until standby1 is promoted</div><div>while ! pg_isready -p 5001; do sleep 1; done</div><div># Find latest standby1 WAL file</div><div>LAST_STANDBY_WAL_FILE="$(pg_controldata standby1 | grep "Latest checkpoint's REDO WAL file:" | cut -d : -f 2 | grep -oP "\w+")"</div><div># Print last timeline history</div><div>cat "$(find standby1/pg_wal -name "*.history" -type f -print0 | xargs -r -0 ls -1 -t | head -1)"</div><div># Print control information of master</div><div>pg_controldata master | grep "checkpoint" | grep "location"</div><div># Print control information of standby1</div><div>pg_controldata standby1 | grep "checkpoint" | grep "location"</div><div># Print control information of standby2</div><div>pg_controldata standby2 | grep "checkpoint" | grep "location"</div><div># Print last 10 lines from dumped master WAL file</div><div>pg_waldump -p master "$LAST_MASTER_WAL_FILE" | tail -n 10</div><div># Print last 10 lines from dumped standby1 WAL files</div><div>pg_waldump -p standby1 "$LAST_MASTER_WAL_FILE" | tail -n 10</div><div>pg_waldump -p standby1 "$LAST_STANDBY_WAL_FILE" | tail -n 10</div><div># Print last 10 lines from dumped standby2 WAL file</div><div>pg_waldump -p standby2 "$LAST_MASTER_WAL_FILE" | tail -n 10</div><div># Insert some rows</div><div>psql -d postgres -a --no-psqlrc -p 5000 &lt;&lt;EOF</div><div>--set synchronous_standby_names = 'postgres';</div><div>--select pg_reload_conf();</div><div>insert into a select i, i from generate_series(1, 340) i;</div><div>--commit;</div><div>EOF</div><div># Standby2 node need to be stopped as well.</div><div>pg_ctl -w -D standby2 stop -m fast</div><div># Stop the master after standby promotion</div><div>pg_ctl -w -D master stop -m fast</div><div># Standby1 node need to be stopped as well.</div><div>pg_ctl -w -D standby1 stop -m fast</div><div># Print control information of master</div><div>pg_controldata master | grep "checkpoint" | grep "location"</div><div># Print control information of standby1</div><div>pg_controldata standby1 | grep "checkpoint" | grep "location"</div><div># Print control information of standby2</div><div>pg_controldata standby2 | grep "checkpoint" | grep "location"</div><div># Print last 10 lines from dumped master WAL file</div><div>pg_waldump -p master "$LAST_MASTER_WAL_FILE" | tail -n 10</div><div># Print last 10 lines from dumped standby1 WAL files</div><div>pg_waldump -p standby1 "$LAST_MASTER_WAL_FILE" | tail -n 10</div><div>pg_waldump -p standby1 "$LAST_STANDBY_WAL_FILE" | tail -n 10</div><div># Print last 10 lines from dumped standby2 WAL file</div><div>pg_waldump -p standby2 "$LAST_MASTER_WAL_FILE" | tail -n 10</div><div># Do rewind using standby1 pgdata as source</div><div>pg_rewind --progress --debug --source-pgdata=standby1 --target-pgdata=standby2</div><div># Parameters for standby2 postgresql.conf</div><div>cat &gt;&gt; standby2/postgresql.conf &lt;&lt;EOF</div><div>primary_conninfo = 'port=5001'</div><div>EOF</div><div># Place standby2 signal file</div><div>touch standby2/standby.signal</div><div># Start standby1</div><div>pg_ctl -w -D standby1 start -o "-p 5001"</div><div># Start standby2</div><div>pg_ctl -w -D standby2 start -o "-p 5002"</div><div># Same query</div><div>psql -d postgres -a --no-psqlrc -p 5001 &lt;&lt;EOF</div><div>select count(*) from a;</div><div>EOF</div><div># Different results</div><div>psql -d postgres -a --no-psqlrc -p 5002 &lt;&lt;EOF</div><div>select count(*) from a;</div><div>EOF</div><div># Stop standby1</div><div>pg_ctl -w -D standby1 stop -m fast</div><div># Stop standby2</div><div>pg_ctl -w -D standby2 stop -m fast</div></div><div>```</div><div>output</div><div>```bash</div><div><div>+ dirname /var/lib/postgresql/ADBDEV/5716.1/r16_2.sh</div><div>+ cd /var/lib/postgresql/ADBDEV/5716.1</div><div>+ test -f master/postmaster.pid</div><div>+ echo 1</div><div>1</div><div>+ rm -rf master</div><div>+ mkdir -p master</div><div>+ pg_ctl initdb -D master -o '--data-checksums -N -A trust --wal-segsize 1'</div><div>The files belonging to this database system will be owned by user "postgres".</div><div>This user must also own the server process.</div><div> </div><div>The database cluster will be initialized with locale "ru_RU.UTF-8".</div><div>The default database encoding has accordingly been set to "UTF8".</div><div>The default text search configuration will be set to "russian".</div><div> </div><div>Data page checksums are enabled.</div><div> </div><div>fixing permissions on existing directory master ... ok</div><div>creating subdirectories ... ok</div><div>selecting dynamic shared memory implementation ... posix</div><div>selecting default max_connections ... 100</div><div>selecting default shared_buffers ... 128MB</div><div>selecting default time zone ... Asia/Yekaterinburg</div><div>creating configuration files ... ok</div><div>running bootstrap script ... ok</div><div>performing post-bootstrap initialization ... ok</div><div> </div><div>Sync to disk skipped.</div><div>The data directory might become corrupt if the operating system crashes.</div><div> </div><div>Success. You can now start the database server using:</div><div> </div><div>    /usr/local/bin/pg_ctl -D master -l logfile start</div><div> </div><div>+ cat</div><div>+ cat</div><div>+ pg_ctl -w -D master start -o '-p 5000'</div><div>waiting for server to start....2024-08-08 12:52:03.032 +05 [1911] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:03.032 +05 [1911] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:03.035 +05 [1911] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:03.035 +05 [1911] DEBUG:  created dynamic shared memory control segment 1884847300 (26976 bytes)</div><div>2024-08-08 12:52:03.035 +05 [1911] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:03.035 +05 [1911] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:03.035 +05 [1911] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ test -f standby1/postmaster.pid</div><div>+ echo 1</div><div>1</div><div>+ rm -rf standby1</div><div>+ pg_basebackup -D standby1 -p 5000 -X fetch --verbose --write-recovery-conf</div><div>pg_basebackup: initiating base backup, waiting for checkpoint to complete</div><div>pg_basebackup: checkpoint completed</div><div>pg_basebackup: write-ahead log start point: 0/800028 on timeline 1</div><div>pg_basebackup: write-ahead log end point: 0/800100</div><div>pg_basebackup: syncing data to disk ...</div><div>pg_basebackup: renaming backup_manifest.tmp to backup_manifest</div><div>pg_basebackup: base backup completed</div><div>+ pg_ctl -w -D standby1 start -o '-p 5001'</div><div>waiting for server to start....2024-08-08 12:52:03.886 +05 [1924] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:03.886 +05 [1924] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:03.888 +05 [1924] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:03.889 +05 [1924] DEBUG:  created dynamic shared memory control segment 689671304 (26976 bytes)</div><div>2024-08-08 12:52:03.889 +05 [1924] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:03.889 +05 [1924] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:03.889 +05 [1924] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ test -f standby2/postmaster.pid</div><div>+ echo 1</div><div>1</div><div>+ rm -rf standby2</div><div>+ pg_basebackup -D standby2 -p 5000 -X fetch --verbose --write-recovery-conf</div><div>pg_basebackup: initiating base backup, waiting for checkpoint to complete</div><div>pg_basebackup: checkpoint completed</div><div>pg_basebackup: write-ahead log start point: 0/900028 on timeline 1</div><div>pg_basebackup: write-ahead log end point: 0/900100</div><div>pg_basebackup: syncing data to disk ...</div><div>pg_basebackup: renaming backup_manifest.tmp to backup_manifest</div><div>pg_basebackup: base backup completed</div><div>+ pg_ctl -w -D standby2 start -o '-p 5002'</div><div>waiting for server to start....2024-08-08 12:52:04.870 +05 [1936] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:04.870 +05 [1936] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:04.873 +05 [1936] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:04.873 +05 [1936] DEBUG:  created dynamic shared memory control segment 111286480 (26976 bytes)</div><div>2024-08-08 12:52:04.873 +05 [1936] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:04.874 +05 [1936] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:04.874 +05 [1936] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ psql -d postgres -a --no-psqlrc -p 5000</div><div>create table a (a int, b int);</div><div>CREATE TABLE</div><div>insert into a select i, i from generate_series(1, 100000) i;</div><div>INSERT 0 100000</div><div>+ pg_ctl -w -D master stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:05.333 +05 [1912] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div><div>+ pg_ctl -w -D standby1 stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:05.483 +05 [1925] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div><div>+ pg_ctl -w -D standby2 stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:05.585 +05 [1937] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div><div>+ pg_ctl -w -D master start -o '-p 5000'</div><div>waiting for server to start....2024-08-08 12:52:05.628 +05 [1952] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:05.628 +05 [1952] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:05.631 +05 [1952] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:05.631 +05 [1952] DEBUG:  created dynamic shared memory control segment 1418826688 (26976 bytes)</div><div>2024-08-08 12:52:05.631 +05 [1952] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:05.632 +05 [1952] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:05.632 +05 [1952] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ pg_ctl -w -D standby1 start -o '-p 5001'</div><div>waiting for server to start....2024-08-08 12:52:05.736 +05 [1962] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:05.736 +05 [1962] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:05.739 +05 [1962] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:05.739 +05 [1962] DEBUG:  created dynamic shared memory control segment 1087487228 (26976 bytes)</div><div>2024-08-08 12:52:05.739 +05 [1962] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:05.739 +05 [1962] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:05.739 +05 [1962] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ pg_ctl -w -D standby2 start -o '-p 5002'</div><div>waiting for server to start....2024-08-08 12:52:05.841 +05 [1971] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:05.841 +05 [1971] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:05.844 +05 [1971] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:05.844 +05 [1971] DEBUG:  created dynamic shared memory control segment 3045047604 (26976 bytes)</div><div>2024-08-08 12:52:05.845 +05 [1971] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:05.845 +05 [1971] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:05.845 +05 [1971] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ pg_controldata master</div><div>+ grep 'Latest checkpoint'"'"'s REDO WAL file:'</div><div>+ cut -d : -f+  2grep</div><div> -oP '\w+'</div><div>+ LAST_MASTER_WAL_FILE=000000010000000000000010</div><div>+ pg_ctl -w -D standby1 promote</div><div>waiting for server to promote.... done</div><div>server promoted</div><div>+ pg_isready -p 5001</div><div>/tmp:5001 - accepting connections</div><div>+ pg_controldata standby1</div><div>+ grep 'Latest checkpoint'"'"'s REDO WAL file:'</div><div>+ cut -d : -f 2</div><div>+ grep -oP '\w+'</div><div>+ LAST_STANDBY_WAL_FILE=000000020000000000000010</div><div>+ find standby1/pg_wal -name '*.history' -type f -print0</div><div>+ xargs -r -0 ls -1 -t</div><div>+ head -1</div><div>+ cat standby1/pg_wal/00000002.history</div><div>1    0/10392E8    no recovery target specified</div><div>+ pg_controldata master</div><div>+ grep checkpoint</div><div>+ grep location</div><div>Latest checkpoint location:           0/1039270</div><div>Latest checkpoint's REDO location:    0/1039270</div><div>+ pg_controldata standby1</div><div>+ grep checkpoint</div><div>+ grep location</div><div>Latest checkpoint location:           0/1039350</div><div>Latest checkpoint's REDO location:    0/1039318</div><div>+ pg_controldata standby2</div><div>+ grep checkpoint</div><div>+ grep location</div><div>Latest checkpoint location:           0/1039270</div><div>Latest checkpoint's REDO location:    0/1039270</div><div>+ pg_waldump -p master 000000010000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 12:52:05.194389 +05</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>+ pg_waldump -p standby1 000000010000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 12:52:05.194389 +05</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>+ pg_waldump -p standby1 000000020000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/10393C8: unexpected pageaddr 0/1038000 in WAL segment 000000020000000000000010, LSN 0/103A000, offset 237568</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 12:52:05.194389 +05</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 12:52:05.946660 +05</div><div>rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online</div><div>rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW</div><div>+ pg_waldump -p standby2 000000010000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 12:52:05.194389 +05</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>+ psql -d postgres -a --no-psqlrc -p 5000</div><div>--set synchronous_standby_names = 'postgres';</div><div>--select pg_reload_conf();</div><div>insert into a select i, i from generate_series(1, 340) i;</div><div>INSERT 0 340</div><div>--commit;</div><div>+ pg_ctl -w -D standby2 stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:06.096 +05 [1972] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div><div>+ pg_ctl -w -D master stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:06.203 +05 [1953] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div><div>+ pg_ctl -w -D standby1 stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:06.302 +05 [1963] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div><div>+ pg_controldata master</div><div>+ grep checkpoint</div><div>+ grep location</div><div>Latest checkpoint location:           0/1041370</div><div>Latest checkpoint's REDO location:    0/1041370</div><div>+ pg_controldata standby1</div><div>+ grep checkpoint</div><div>+ grep location</div><div>Latest checkpoint location:           0/103B2F0</div><div>Latest checkpoint's REDO location:    0/103B2F0</div><div>+ pg_controldata standby2</div><div>+ grep checkpoint</div><div>+ grep location</div><div>Latest checkpoint location:           0/1039270</div><div>Latest checkpoint's REDO location:    0/1039270</div><div>+ pg_waldump -p master 000000010000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/1041370: invalid record length at 0/10413E8: expected at least 24, got 0</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 12:52:06.085591 +05</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01041370, prev 0/01041348, desc: CHECKPOINT_SHUTDOWN redo 0/1041370; tli 1; prev tli 1; fpw true; xid 0:733; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>+ pg_waldump -p standby1 000000010000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 12:52:05.194389 +05</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>+ pg_waldump -p standby1 000000020000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/103B2F0: invalid record length at 0/103B368: expected at least 24, got 0</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 12:52:05.194389 +05</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 12:52:05.946660 +05</div><div>rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online</div><div>rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW</div><div>rmgr: XLOG        len (rec/tot):     49/  7061, tx:          0, lsn: 0/01039740, prev 0/010393C8, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1249 blk 17 FPW</div><div>rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/0103B2F0, prev 0/01039740, desc: CHECKPOINT_SHUTDOWN redo 0/103B2F0; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown</div><div>+ pg_waldump -p standby2 000000010000000000000010</div><div>+ tail -n 10</div><div>pg_waldump: error: error in WAL record at 0/1041348: invalid record length at 0/1041370: expected at least 24, got 0</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041108, prev 0/010410C8, desc: INSERT off: 214, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443</div><div>rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 12:52:06.085591 +05</div><div>+ pg_rewind --progress --debug '--source-pgdata=standby1' '--target-pgdata=standby2'</div><div>pg_rewind: Source timeline history:</div><div>pg_rewind: Target timeline history:</div><div>pg_rewind: 1: 0/0 - 0/0</div><div>pg_rewind: servers diverged at WAL location 0/10392E8 on timeline 1</div><div>pg_rewind: no rewind required</div><div>+ cat</div><div>+ touch standby2/standby.signal</div><div>+ pg_ctl -w -D standby1 start -o '-p 5001'</div><div>waiting for server to start....2024-08-08 12:52:06.432 +05 [2044] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:06.432 +05 [2044] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:06.436 +05 [2044] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:06.436 +05 [2044] DEBUG:  created dynamic shared memory control segment 8407908 (26976 bytes)</div><div>2024-08-08 12:52:06.436 +05 [2044] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:06.436 +05 [2044] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:06.436 +05 [2044] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ pg_ctl -w -D standby2 start -o '-p 5002'</div><div>waiting for server to start....2024-08-08 12:52:06.539 +05 [2054] DEBUG:  registering background worker "logical replication launcher"</div><div>2024-08-08 12:52:06.539 +05 [2054] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory</div><div>2024-08-08 12:52:06.542 +05 [2054] DEBUG:  dynamic shared memory system will support 674 segments</div><div>2024-08-08 12:52:06.542 +05 [2054] DEBUG:  created dynamic shared memory control segment 615788588 (26976 bytes)</div><div>2024-08-08 12:52:06.542 +05 [2054] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4</div><div>2024-08-08 12:52:06.543 +05 [2054] LOG:  redirecting log output to logging collector process</div><div>2024-08-08 12:52:06.543 +05 [2054] HINT:  Future log output will appear in directory "log".</div><div> done</div><div>server started</div><div>+ psql -d postgres -a --no-psqlrc -p 5001</div><div>select count(*) from a;</div><div> count  </div><div>--------</div><div> 100000</div><div>(1 row)</div><div> </div><div>+ psql -d postgres -a --no-psqlrc -p 5002</div><div>select count(*) from a;</div><div> count  </div><div>--------</div><div> 100340</div><div>(1 row)</div><div> </div><div>+ pg_ctl -w -D standby1 stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:06.792 +05 [2045] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div><div>+ pg_ctl -w -D standby2 stop -m fast</div><div>waiting for server to shut down....2024-08-08 12:52:06.830 +05 [2055] DEBUG:  logger shutting down</div><div> done</div><div>server stopped</div></div><div>```</div><div>postgres is compiled from last REL_16_STABLE branch</div></div><div><br /></div><div><br /></div><div>08.08.2024, 12:03, "Heikki Linnakangas" &lt;hlinnaka@iki.fi&gt;:</div><blockquote><p>On 07/08/2024 15:19, PG Bug reporting form wrote:<br /></p><blockquote class="210e7a848e8fcb45wmi-quote"> Sometimes pg_rewind mistakenly assumes that nothing needs to be done, which<br /> results in the replica having data that is not on the master.<br /> <br /> ...<br /> + pg_rewind --progress --debug '--source-pgdata=standby1'<br /> '--target-pgdata=standby2'<br /> pg_rewind: Source timeline history:<br /> pg_rewind: Target timeline history:<br /> pg_rewind: 1: 0/0 - 0/0<br /> pg_rewind: servers diverged at WAL location 0/10392E8 on timeline 1<br /> pg_rewind: no rewind required<br /><br /> ...<br /> Same query<br /> + psql -d postgres -a --no-psqlrc -p 5001<br /> select count(*) from a;<br />   count<br /> --------<br />   100000<br /> (1 row)<br /> <br /> + echo 'Different results'<br /> Different results<br /> + psql -d postgres -a --no-psqlrc -p 5002<br /> select count(*) from a;<br />   count<br /> --------<br />   100340<br /> (1 row)<br /> <br /> + echo 'Stop standby1'<br /> Stop standby1<br /> + pg_ctl -w -D standby1 stop -m fast<br /> waiting for server to shut down....<span class="1f1ea193f6735cf0wmi-callto">2024-08-07 17</span>:15:03.077 +05 [19703]<br /> DEBUG: logger shutting down<br />   done<br /> server stopped<br /> + echo 'Stop standby2'<br /> Stop standby2<br /> + pg_ctl -w -D standby2 stop -m fast<br /> waiting for server to shut down....<span class="1f1ea193f6735cf0wmi-callto">2024-08-07 17</span>:15:03.117 +05 [19713]<br /> DEBUG: logger shutting down<br />   done<br /> server stopped<br /> ```<br /></blockquote><p><br />I cannot reproduce this. On my laptop, the reported "servers diverged at <br />WAL location" is always higher, and it performs rewind as expected:<br /><br />g_rewind: Source timeline history:<br />pg_rewind: Target timeline history:<br />pg_rewind: 1: 0/0 - 0/0<br />pg_rewind: servers diverged at WAL location 0/1138F00 on timeline 1<br />pg_rewind: rewinding from last common checkpoint at 0/1138E88 on timeline 1<br /><br />However while looking at the code, I noticed that the debug-output of <br />the Source timeline history is broken. See attached patch to fix it. <br />With that fix, I get:<br /><br />pg_rewind: Source timeline history:<br />pg_rewind: 1: 0/0 - 0/1138F00<br />pg_rewind: 2: 0/1138F00 - 0/0<br />pg_rewind: Target timeline history:<br />pg_rewind: 1: 0/0 - 0/0<br />pg_rewind: 0 a: 1 0/0-0/1138F00 - b: 1 0/0-0/0<br />pg_rewind: servers diverged at WAL location 0/1138F00 on timeline 1<br />pg_rewind: rewinding from last common checkpoint at 0/1138E88 on timeline 1<br /><br />That just fixes the debugging output, though, it doesn't change what it <br />actually does.<br /><br />Can you try the attached fix show the output you get with that please? <br />Or alternatively, show the contents of the <br />standby1/pg_wal/<span class="1f1ea193f6735cf0wmi-callto">00000002</span>.history file.<br /><br /></p><span class="f55bbb4eeef208e8wmi-sign">-- <br />Heikki Linnakangas<br />Neon (<a href="https://neon.tech/&quot;&gt;https://neon.tech&lt;/a&gt;)&lt;br /></span></blockquote>

On 08/08/2024 10:57, Georgy Shelkovy wrote:

Unfortunately, the playback is not very stable, but sometimes it shoots.
I added some commands to show last WAL rows

Thanks. I still haven't been able to reproduce it, but here's a theory:

When determining whether the target needs rewinding, pg_rewind looks at
the target's last checkpoint record, or if it's a standby, its
minRecoveryPoint. It's possible that standby2's minRecoveryPoint is
indeed before the point of divergence. That means it has replayed the
340 insert records, but all the changes are still only sitting in the
shared buffer cache. When you shut it down, those 340 inserts are gone
on standby2. When you restart it, they will be applied again from the WAL.

In that case, pg_rewind's conclusion that no rewind is needed is
correct. standby2 is strictly behind standby1, and could catch up
directly to it. However, when you restart standby2, it will first replay
the WAL it had streamed from master.

Can you show the full output of pg_controldata on all the servers,
please? In your latest snippet, you showed just the checkpoint
locations, but if just remove the "grep checkpoint | grep location"
filters, it would print the whole thing. I'm particularly interested in
the minRecoveryPoint on standby2, in the cases when it works and when it
doesn't.

I'm not sure what the right behavior would be if that's the issue.
Perhaps pg_rewind should truncate the WAL in standby2/pg_wal/ in that
case, so that when you start it up again, it would not replay the local
WAL but would connect to standby2 directly. Also, perhaps a fast
shutdown of a standby server should update minRecoveryPoint before exiting.

--
Heikki Linnakangas
Neon (https://neon.tech)

+ cd /var/lib/postgresql/ADBDEV/5716.1
+ test -f master/postmaster.pid
+ echo 1
1
+ rm -rf master
+ mkdir -p master
+ pg_ctl initdb -D master -o '--data-checksums -N -A trust --wal-segsize 1'
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale "ru_RU.UTF-8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "russian".

Data page checksums are enabled.

fixing permissions on existing directory master ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Asia/Yekaterinburg
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok

Sync to disk skipped.
The data directory might become corrupt if the operating system crashes.

Success. You can now start the database server using:

/usr/local/bin/pg_ctl -D master -l logfile start

+ cat
+ cat
+ pg_ctl -w -D master start -o '-p 5000'
waiting for server to start....2024-08-08 14:36:05.716 +05 [2259] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:05.716 +05 [2259] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:05.719 +05 [2259] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:05.719 +05 [2259] DEBUG:  created dynamic shared memory control segment 511288034 (26976 bytes)
2024-08-08 14:36:05.719 +05 [2259] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:05.720 +05 [2259] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:05.720 +05 [2259] HINT:  Future log output will appear in directory "log".
 done
server started
+ test -f standby1/postmaster.pid
+ echo 1
1
+ rm -rf standby1
+ pg_basebackup -D standby1 -p 5000 -X fetch --verbose --write-recovery-conf
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/800028 on timeline 1
pg_basebackup: write-ahead log end point: 0/800100
pg_basebackup: syncing data to disk ...
pg_basebackup: renaming backup_manifest.tmp to backup_manifest
pg_basebackup: base backup completed
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 14:36:06.573 +05 [2272] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:06.573 +05 [2272] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:06.576 +05 [2272] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:06.576 +05 [2272] DEBUG:  created dynamic shared memory control segment 132029364 (26976 bytes)
2024-08-08 14:36:06.576 +05 [2272] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:06.576 +05 [2272] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:06.576 +05 [2272] HINT:  Future log output will appear in directory "log".
 done
server started
+ test -f standby2/postmaster.pid
+ echo 1
1
+ rm -rf standby2
+ pg_basebackup -D standby2 -p 5000 -X fetch --verbose --write-recovery-conf
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/900028 on timeline 1
pg_basebackup: write-ahead log end point: 0/900100
pg_basebackup: syncing data to disk ...
pg_basebackup: renaming backup_manifest.tmp to backup_manifest
pg_basebackup: base backup completed
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 14:36:07.412 +05 [2284] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:07.412 +05 [2284] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:07.415 +05 [2284] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:07.415 +05 [2284] DEBUG:  created dynamic shared memory control segment 1345573086 (26976 bytes)
2024-08-08 14:36:07.415 +05 [2284] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:07.415 +05 [2284] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:07.415 +05 [2284] HINT:  Future log output will appear in directory "log".
 done
server started
+ psql -d postgres -a --no-psqlrc -p 5000
create table a (a int, b int);
CREATE TABLE
insert into a select i, i from generate_series(1, 100000) i;
INSERT 0 100000
+ pg_ctl -w -D master stop -m fast
waiting for server to shut down....2024-08-08 14:36:07.933 +05 [2260] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 14:36:08.011 +05 [2273] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 14:36:08.111 +05 [2285] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D master start -o '-p 5000'
waiting for server to start....2024-08-08 14:36:08.154 +05 [2300] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:08.154 +05 [2300] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:08.157 +05 [2300] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:08.157 +05 [2300] DEBUG:  created dynamic shared memory control segment 1848579776 (26976 bytes)
2024-08-08 14:36:08.157 +05 [2300] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:08.157 +05 [2300] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:08.157 +05 [2300] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 14:36:08.259 +05 [2310] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:08.259 +05 [2310] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:08.262 +05 [2310] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:08.263 +05 [2310] DEBUG:  created dynamic shared memory control segment 2087008324 (26976 bytes)
2024-08-08 14:36:08.263 +05 [2310] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:08.263 +05 [2310] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:08.263 +05 [2310] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 14:36:08.366 +05 [2319] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:08.366 +05 [2319] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:08.369 +05 [2319] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:08.369 +05 [2319] DEBUG:  created dynamic shared memory control segment 1104889730 (26976 bytes)
2024-08-08 14:36:08.369 +05 [2319] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:08.369 +05 [2319] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:08.369 +05 [2319] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_controldata master
+ grep 'Latest checkpoint'"'"'s REDO WAL file:'
+ cut -d : -f 2
+ grep -oP '\w+'
+ LAST_MASTER_WAL_FILE=000000010000000000000010
+ pg_ctl -w -D standby1 promote
waiting for server to promote.... done
server promoted
+ pg_isready -p 5001
/tmp:5001 - accepting connections
+ pg_controldata standby1
+ grep 'Latest checkpoint'"'"'s REDO WAL file:'
+ cut -d : -f 2
+ grep -oP '\w+'
+ LAST_STANDBY_WAL_FILE=000000020000000000000010
+ find standby1/pg_wal -name '*.history' -type f -print0
+ xargs -r -0 ls -1 -t
+ head -1
+ cat standby1/pg_wal/00000002.history
1	0/10392E8	no recovery target specified
+ pg_controldata master
+ grep checkpoint
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 14:36:07 2024
+ pg_controldata standby1
+ grep checkpoint
Latest checkpoint location:           0/1039350
Latest checkpoint's REDO location:    0/1039318
Latest checkpoint's REDO WAL file:    000000020000000000000010
Latest checkpoint's TimeLineID:       2
Latest checkpoint's PrevTimeLineID:   2
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
Latest checkpoint's oldestXID's DB:   1
Latest checkpoint's oldestActiveXID:  732
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:            Thu Aug  8 14:36:08 2024
+ pg_controldata standby2
+ grep checkpoint
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 14:36:07 2024
+ pg_waldump -p master 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 14:36:07.722423 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 14:36:07.722423 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000020000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/10393C8: unexpected pageaddr 0/1038000 in WAL segment 000000020000000000000010, LSN 0/103A000, offset 237568
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 14:36:07.722423 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 14:36:08.470837 +05
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online
rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW
+ pg_waldump -p standby2 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 14:36:07.722423 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ psql -d postgres -a --no-psqlrc -p 5000
--set synchronous_standby_names = 'postgres';
--select pg_reload_conf();
insert into a select i, i from generate_series(1, 340) i;
INSERT 0 340
--commit;
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 14:36:08.621 +05 [2320] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D master stop -m fast
waiting for server to shut down....2024-08-08 14:36:08.728 +05 [2301] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 14:36:08.827 +05 [2311] DEBUG:  logger shutting down
 done
server stopped
+ pg_controldata master
+ grep checkpoint
Latest checkpoint location:           0/1041370
Latest checkpoint's REDO location:    0/1041370
Latest checkpoint's REDO WAL file:    000000010000000000000010
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:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 14:36:08 2024
+ pg_controldata standby1
+ grep checkpoint
Latest checkpoint location:           0/103B2F0
Latest checkpoint's REDO location:    0/103B2F0
Latest checkpoint's REDO WAL file:    000000020000000000000010
Latest checkpoint's TimeLineID:       2
Latest checkpoint's PrevTimeLineID:   2
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 14:36:08 2024
+ pg_controldata standby2
+ grep checkpoint
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 14:36:07 2024
+ pg_waldump -p master 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1041370: invalid record length at 0/10413E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 14:36:08.610124 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01041370, prev 0/01041348, desc: CHECKPOINT_SHUTDOWN redo 0/1041370; tli 1; prev tli 1; fpw true; xid 0:733; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 14:36:07.722423 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000020000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/103B2F0: invalid record length at 0/103B368: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 14:36:07.722423 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 14:36:08.470837 +05
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online
rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW
rmgr: XLOG        len (rec/tot):     49/  7061, tx:          0, lsn: 0/01039740, prev 0/010393C8, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1249 blk 17 FPW
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/0103B2F0, prev 0/01039740, desc: CHECKPOINT_SHUTDOWN redo 0/103B2F0; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby2 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1041348: invalid record length at 0/1041370: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041108, prev 0/010410C8, desc: INSERT off: 214, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 14:36:08.610124 +05
+ pg_rewind --progress --debug '--source-pgdata=standby1' '--target-pgdata=standby2'
pg_rewind: Source timeline history:
pg_rewind: Target timeline history:
pg_rewind: 1: 0/0 - 0/0
pg_rewind: servers diverged at WAL location 0/10392E8 on timeline 1
pg_rewind: no rewind required
+ cat
+ touch standby2/standby.signal
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 14:36:08.957 +05 [2386] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:08.957 +05 [2386] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:08.961 +05 [2386] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:08.961 +05 [2386] DEBUG:  created dynamic shared memory control segment 2166747262 (26976 bytes)
2024-08-08 14:36:08.961 +05 [2386] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:08.961 +05 [2386] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:08.961 +05 [2386] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 14:36:09.063 +05 [2396] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 14:36:09.063 +05 [2396] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 14:36:09.067 +05 [2396] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 14:36:09.067 +05 [2396] DEBUG:  created dynamic shared memory control segment 373333278 (26976 bytes)
2024-08-08 14:36:09.067 +05 [2396] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 14:36:09.067 +05 [2396] LOG:  redirecting log output to logging collector process
2024-08-08 14:36:09.067 +05 [2396] HINT:  Future log output will appear in directory "log".
 done
server started
+ psql -d postgres -a --no-psqlrc -p 5001
select count(*) from a;
 count  
--------
 100000
(1 row)

+ psql -d postgres -a --no-psqlrc -p 5002
select count(*) from a;
 count  
--------
 100340
(1 row)

+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 14:36:09.316 +05 [2387] DEBUG: logger shutting down
done
server stopped
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 14:36:09.355 +05 [2397] DEBUG: logger shutting down
done
server stopped

On 08/08/2024 12:38, Georgy Shelkovy wrote:

On second run I got bug

Can you show the full pg_controldata output please? See attached script.

--
Heikki Linnakangas
Neon (https://neon.tech)

+ dirname /var/lib/postgresql/ADBDEV/5716.1/r.sh
+ cd /var/lib/postgresql/ADBDEV/5716.1
+ test -f master/postmaster.pid
+ echo 1
1
+ rm -rf master
+ mkdir -p master
+ pg_ctl initdb -D master -o '--data-checksums -N -A trust --wal-segsize 1'
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale "ru_RU.UTF-8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "russian".

Data page checksums are enabled.

fixing permissions on existing directory master ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Asia/Yekaterinburg
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok

Sync to disk skipped.
The data directory might become corrupt if the operating system crashes.

Success. You can now start the database server using:

/usr/local/bin/pg_ctl -D master -l logfile start

+ cat
+ cat
+ pg_ctl -w -D master start -o '-p 5000'
waiting for server to start....2024-08-08 15:10:45.196 +05 [6149] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:45.196 +05 [6149] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:45.199 +05 [6149] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:45.199 +05 [6149] DEBUG:  created dynamic shared memory control segment 1116447354 (26976 bytes)
2024-08-08 15:10:45.199 +05 [6149] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:45.200 +05 [6149] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:45.200 +05 [6149] HINT:  Future log output will appear in directory "log".
 done
server started
+ test -f standby1/postmaster.pid
+ echo 1
1
+ rm -rf standby1
+ pg_basebackup -D standby1 -p 5000 -X fetch --verbose --write-recovery-conf
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/800028 on timeline 1
pg_basebackup: write-ahead log end point: 0/800100
pg_basebackup: syncing data to disk ...
pg_basebackup: renaming backup_manifest.tmp to backup_manifest
pg_basebackup: base backup completed
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 15:10:46.074 +05 [6162] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:46.074 +05 [6162] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:46.077 +05 [6162] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:46.077 +05 [6162] DEBUG:  created dynamic shared memory control segment 9608254 (26976 bytes)
2024-08-08 15:10:46.077 +05 [6162] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:46.078 +05 [6162] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:46.078 +05 [6162] HINT:  Future log output will appear in directory "log".
 done
server started
+ test -f standby2/postmaster.pid
+ echo 1
1
+ rm -rf standby2
+ pg_basebackup -D standby2 -p 5000 -X fetch --verbose --write-recovery-conf
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/900028 on timeline 1
pg_basebackup: write-ahead log end point: 0/900100
pg_basebackup: syncing data to disk ...
pg_basebackup: renaming backup_manifest.tmp to backup_manifest
pg_basebackup: base backup completed
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 15:10:46.901 +05 [6174] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:46.902 +05 [6174] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:46.905 +05 [6174] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:46.905 +05 [6174] DEBUG:  created dynamic shared memory control segment 3025743584 (26976 bytes)
2024-08-08 15:10:46.905 +05 [6174] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:46.905 +05 [6174] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:46.905 +05 [6174] HINT:  Future log output will appear in directory "log".
 done
server started
+ psql -d postgres -a --no-psqlrc -p 5000
create table a (a int, b int);
CREATE TABLE
insert into a select i, i from generate_series(1, 100000) i;
INSERT 0 100000
+ pg_ctl -w -D master stop -m fast
waiting for server to shut down....2024-08-08 15:10:47.441 +05 [6150] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 15:10:47.605 +05 [6163] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 15:10:47.706 +05 [6175] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D master start -o '-p 5000'
waiting for server to start....2024-08-08 15:10:47.750 +05 [6191] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:47.750 +05 [6191] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:47.754 +05 [6191] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:47.754 +05 [6191] DEBUG:  created dynamic shared memory control segment 2761104416 (26976 bytes)
2024-08-08 15:10:47.754 +05 [6191] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:47.754 +05 [6191] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:47.754 +05 [6191] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 15:10:47.855 +05 [6201] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:47.855 +05 [6201] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:47.858 +05 [6201] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:47.858 +05 [6201] DEBUG:  created dynamic shared memory control segment 3628939506 (26976 bytes)
2024-08-08 15:10:47.858 +05 [6201] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:47.858 +05 [6201] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:47.858 +05 [6201] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 15:10:47.961 +05 [6210] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:47.961 +05 [6210] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:47.964 +05 [6210] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:47.964 +05 [6210] DEBUG:  created dynamic shared memory control segment 949670120 (26976 bytes)
2024-08-08 15:10:47.964 +05 [6210] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:47.964 +05 [6210] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:47.964 +05 [6210] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_controldata master
+ grep 'Latest checkpoint'"'"'s REDO WAL file:'
+ cut -d : -f 2
+ grep -oP '\w+'
+ LAST_MASTER_WAL_FILE=000000010000000000000010
+ pg_ctl -w -D standby1 promote
waiting for server to promote.... done
server promoted
+ pg_isready -p 5001
/tmp:5001 - accepting connections
+ pg_controldata standby1
+ grep 'Latest checkpoint'"'"'s REDO WAL file:'
+ cut -d : -f 2
+ grep -oP '\w+'
+ LAST_STANDBY_WAL_FILE=000000020000000000000010
+ find standby1/pg_wal -name '*.history' -type f -print0
+ xargs -r -0 ls -1 -t
+ head -1
+ cat standby1/pg_wal/00000002.history
1	0/10392E8	no recovery target specified
+ pg_controldata master
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400709019478280190
Database cluster state:               in production
pg_control last modified:             Thu Aug  8 15:10:47 2024
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:47 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:                off
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:                1048576
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:            2f01e28d7195244edef0e2f31398b8fab7bc085454f5c48b545036635a78cbde
+ pg_controldata standby1
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400709019478280190
Database cluster state:               in production
pg_control last modified:             Thu Aug  8 15:10:48 2024
Latest checkpoint location:           0/1039350
Latest checkpoint's REDO location:    0/1039318
Latest checkpoint's REDO WAL file:    000000020000000000000010
Latest checkpoint's TimeLineID:       2
Latest checkpoint's PrevTimeLineID:   2
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
Latest checkpoint's oldestXID's DB:   1
Latest checkpoint's oldestActiveXID:  732
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:            Thu Aug  8 15:10:48 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:                off
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:                1048576
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:            2f01e28d7195244edef0e2f31398b8fab7bc085454f5c48b545036635a78cbde
+ pg_controldata standby2
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400709019478280190
Database cluster state:               in archive recovery
pg_control last modified:             Thu Aug  8 15:10:47 2024
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:47 2024
Fake LSN counter for unlogged rels:   0/3E8
Minimum recovery ending location:     0/10392E8
Min recovery ending loc's timeline:   1
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
wal_level setting:                    replica
wal_log_hints setting:                off
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:                1048576
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:            2f01e28d7195244edef0e2f31398b8fab7bc085454f5c48b545036635a78cbde
+ pg_waldump -p master 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:47.217249 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:47.217249 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000020000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/10393C8: unexpected pageaddr 0/1038000 in WAL segment 000000020000000000000010, LSN 0/103A000, offset 237568
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:47.217249 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 15:10:48.066210 +05
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online
rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW
+ pg_waldump -p standby2 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:47.217249 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ psql -d postgres -a --no-psqlrc -p 5000
--set synchronous_standby_names = 'postgres';
--select pg_reload_conf();
insert into a select i, i from generate_series(1, 340) i;
INSERT 0 340
--commit;
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 15:10:48.216 +05 [6211] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D master stop -m fast
waiting for server to shut down....2024-08-08 15:10:48.323 +05 [6192] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 15:10:48.423 +05 [6202] DEBUG:  logger shutting down
 done
server stopped
+ pg_controldata master
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400709019478280190
Database cluster state:               shut down
pg_control last modified:             Thu Aug  8 15:10:48 2024
Latest checkpoint location:           0/1041370
Latest checkpoint's REDO location:    0/1041370
Latest checkpoint's REDO WAL file:    000000010000000000000010
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:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:48 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:                off
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:                1048576
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:            2f01e28d7195244edef0e2f31398b8fab7bc085454f5c48b545036635a78cbde
+ pg_controldata standby1
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400709019478280190
Database cluster state:               shut down
pg_control last modified:             Thu Aug  8 15:10:48 2024
Latest checkpoint location:           0/103B2F0
Latest checkpoint's REDO location:    0/103B2F0
Latest checkpoint's REDO WAL file:    000000020000000000000010
Latest checkpoint's TimeLineID:       2
Latest checkpoint's PrevTimeLineID:   2
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:48 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:                off
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:                1048576
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:            2f01e28d7195244edef0e2f31398b8fab7bc085454f5c48b545036635a78cbde
+ pg_controldata standby2
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400709019478280190
Database cluster state:               shut down in recovery
pg_control last modified:             Thu Aug  8 15:10:48 2024
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:47 2024
Fake LSN counter for unlogged rels:   0/3E8
Minimum recovery ending location:     0/10392E8
Min recovery ending loc's timeline:   1
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
wal_level setting:                    replica
wal_log_hints setting:                off
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:                1048576
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:            2f01e28d7195244edef0e2f31398b8fab7bc085454f5c48b545036635a78cbde
+ pg_waldump -p master 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1041370: invalid record length at 0/10413E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 15:10:48.205136 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01041370, prev 0/01041348, desc: CHECKPOINT_SHUTDOWN redo 0/1041370; tli 1; prev tli 1; fpw true; xid 0:733; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:47.217249 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000020000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/103B2F0: invalid record length at 0/103B368: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:47.217249 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 15:10:48.066210 +05
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online
rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW
rmgr: XLOG        len (rec/tot):     49/  7061, tx:          0, lsn: 0/01039740, prev 0/010393C8, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1249 blk 17 FPW
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/0103B2F0, prev 0/01039740, desc: CHECKPOINT_SHUTDOWN redo 0/103B2F0; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby2 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1041348: invalid record length at 0/1041370: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041108, prev 0/010410C8, desc: INSERT off: 214, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 15:10:48.205136 +05
+ pg_rewind --progress --debug '--source-pgdata=standby1' '--target-pgdata=standby2'
pg_rewind: Source timeline history:
pg_rewind: Target timeline history:
pg_rewind: 1: 0/0 - 0/0
pg_rewind: servers diverged at WAL location 0/10392E8 on timeline 1
pg_rewind: no rewind required
+ cat
+ touch standby2/standby.signal
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 15:10:48.551 +05 [6271] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:48.551 +05 [6271] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:48.555 +05 [6271] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:48.555 +05 [6271] DEBUG:  created dynamic shared memory control segment 2561165532 (26976 bytes)
2024-08-08 15:10:48.555 +05 [6271] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:48.555 +05 [6271] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:48.555 +05 [6271] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 15:10:48.657 +05 [6281] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:48.658 +05 [6281] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:48.660 +05 [6281] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:48.661 +05 [6281] DEBUG:  created dynamic shared memory control segment 4080806306 (26976 bytes)
2024-08-08 15:10:48.661 +05 [6281] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:48.661 +05 [6281] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:48.661 +05 [6281] HINT:  Future log output will appear in directory "log".
 done
server started
+ psql -d postgres -a --no-psqlrc -p 5001
select count(*) from a;
 count  
--------
 100000
(1 row)

+ psql -d postgres -a --no-psqlrc -p 5002
select count(*) from a;
 count  
--------
 100340
(1 row)

+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 15:10:48.910 +05 [6272] DEBUG: logger shutting down
done
server stopped
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 15:10:48.948 +05 [6282] DEBUG: logger shutting down
done
server stopped

+ dirname /var/lib/postgresql/ADBDEV/5716.1/r.sh
+ cd /var/lib/postgresql/ADBDEV/5716.1
+ test -f master/postmaster.pid
+ echo 1
1
+ rm -rf master
+ mkdir -p master
+ pg_ctl initdb -D master -o '--data-checksums -N -A trust --wal-segsize 1'
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale "ru_RU.UTF-8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "russian".

Data page checksums are enabled.

fixing permissions on existing directory master ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Asia/Yekaterinburg
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok

Sync to disk skipped.
The data directory might become corrupt if the operating system crashes.

Success. You can now start the database server using:

/usr/local/bin/pg_ctl -D master -l logfile start

+ cat
+ cat
+ pg_ctl -w -D master start -o '-p 5000'
waiting for server to start....2024-08-08 15:10:39.690 +05 [5988] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:39.690 +05 [5988] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:39.693 +05 [5988] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:39.693 +05 [5988] DEBUG:  created dynamic shared memory control segment 2583133654 (26976 bytes)
2024-08-08 15:10:39.693 +05 [5988] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:39.693 +05 [5988] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:39.693 +05 [5988] HINT:  Future log output will appear in directory "log".
 done
server started
+ test -f standby1/postmaster.pid
+ echo 1
1
+ rm -rf standby1
+ pg_basebackup -D standby1 -p 5000 -X fetch --verbose --write-recovery-conf
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/800028 on timeline 1
pg_basebackup: write-ahead log end point: 0/800100
pg_basebackup: syncing data to disk ...
pg_basebackup: renaming backup_manifest.tmp to backup_manifest
pg_basebackup: base backup completed
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 15:10:40.550 +05 [6001] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:40.550 +05 [6001] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:40.553 +05 [6001] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:40.553 +05 [6001] DEBUG:  created dynamic shared memory control segment 3459934430 (26976 bytes)
2024-08-08 15:10:40.554 +05 [6001] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:40.554 +05 [6001] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:40.554 +05 [6001] HINT:  Future log output will appear in directory "log".
 done
server started
+ test -f standby2/postmaster.pid
+ echo 1
1
+ rm -rf standby2
+ pg_basebackup -D standby2 -p 5000 -X fetch --verbose --write-recovery-conf
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/900028 on timeline 1
pg_basebackup: write-ahead log end point: 0/900100
pg_basebackup: syncing data to disk ...
pg_basebackup: renaming backup_manifest.tmp to backup_manifest
pg_basebackup: base backup completed
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 15:10:41.416 +05 [6013] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:41.416 +05 [6013] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:41.419 +05 [6013] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:41.419 +05 [6013] DEBUG:  created dynamic shared memory control segment 138579396 (26976 bytes)
2024-08-08 15:10:41.419 +05 [6013] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:41.420 +05 [6013] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:41.420 +05 [6013] HINT:  Future log output will appear in directory "log".
 done
server started
+ psql -d postgres -a --no-psqlrc -p 5000
create table a (a int, b int);
CREATE TABLE
insert into a select i, i from generate_series(1, 100000) i;
INSERT 0 100000
+ pg_ctl -w -D master stop -m fast
waiting for server to shut down....2024-08-08 15:10:41.998 +05 [5989] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 15:10:42.131 +05 [6002] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 15:10:42.225 +05 [6014] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D master start -o '-p 5000'
waiting for server to start....2024-08-08 15:10:42.266 +05 [6029] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:42.266 +05 [6029] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:42.270 +05 [6029] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:42.270 +05 [6029] DEBUG:  created dynamic shared memory control segment 269428598 (26976 bytes)
2024-08-08 15:10:42.270 +05 [6029] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:42.270 +05 [6029] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:42.270 +05 [6029] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 15:10:42.372 +05 [6039] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:42.372 +05 [6039] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:42.376 +05 [6039] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:42.376 +05 [6039] DEBUG:  created dynamic shared memory control segment 1142189908 (26976 bytes)
2024-08-08 15:10:42.376 +05 [6039] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:42.376 +05 [6039] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:42.376 +05 [6039] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 15:10:42.478 +05 [6048] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:42.478 +05 [6048] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:42.481 +05 [6048] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:42.482 +05 [6048] DEBUG:  created dynamic shared memory control segment 156393578 (26976 bytes)
2024-08-08 15:10:42.482 +05 [6048] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:42.482 +05 [6048] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:42.482 +05 [6048] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_controldata master
+ grep 'Latest checkpoint'"'"'s REDO WAL file:'
+ cut -d : -f 2
+ grep -oP '\w+'
+ LAST_MASTER_WAL_FILE=000000010000000000000010
+ pg_ctl -w -D standby1 promote
waiting for server to promote.... done
server promoted
+ pg_isready -p 5001
/tmp:5001 - accepting connections
+ pg_controldata standby1
+ grep 'Latest checkpoint'"'"'s REDO WAL file:'
+ cut -d : -f 2
+ grep -oP '\w+'
+ LAST_STANDBY_WAL_FILE=000000020000000000000010
+ find standby1/pg_wal -name '*.history' -type f -print0
+ xargs -r -0 ls -1 -t
+ head -1
+ cat standby1/pg_wal/00000002.history
1	0/10392E8	no recovery target specified
+ pg_controldata master
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400708995903891293
Database cluster state:               in production
pg_control last modified:             Thu Aug  8 15:10:42 2024
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:41 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:                off
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:                1048576
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:            b4dda080ead40b8ca338d9e5f6360b7489c33604ef1f8c3459cd7e1eba76a115
+ pg_controldata standby1
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400708995903891293
Database cluster state:               in production
pg_control last modified:             Thu Aug  8 15:10:42 2024
Latest checkpoint location:           0/1039350
Latest checkpoint's REDO location:    0/1039318
Latest checkpoint's REDO WAL file:    000000020000000000000010
Latest checkpoint's TimeLineID:       2
Latest checkpoint's PrevTimeLineID:   2
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
Latest checkpoint's oldestXID's DB:   1
Latest checkpoint's oldestActiveXID:  732
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:            Thu Aug  8 15:10:42 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:                off
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:                1048576
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:            b4dda080ead40b8ca338d9e5f6360b7489c33604ef1f8c3459cd7e1eba76a115
+ pg_controldata standby2
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400708995903891293
Database cluster state:               in archive recovery
pg_control last modified:             Thu Aug  8 15:10:42 2024
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:41 2024
Fake LSN counter for unlogged rels:   0/3E8
Minimum recovery ending location:     0/10392E8
Min recovery ending loc's timeline:   1
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
wal_level setting:                    replica
wal_log_hints setting:                off
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:                1048576
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:            b4dda080ead40b8ca338d9e5f6360b7489c33604ef1f8c3459cd7e1eba76a115
+ pg_waldump -p master 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:41.733402 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:41.733402 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000020000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/10393C8: unexpected pageaddr 0/1038000 in WAL segment 000000020000000000000010, LSN 0/103A000, offset 237568
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:41.733402 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 15:10:42.583043 +05
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online
rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW
+ pg_waldump -p standby2 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:41.733402 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ psql -d postgres -a --no-psqlrc -p 5000
--set synchronous_standby_names = 'postgres';
--select pg_reload_conf();
insert into a select i, i from generate_series(1, 340) i;
INSERT 0 340
--commit;
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 15:10:42.733 +05 [6049] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D master stop -m fast
waiting for server to shut down....2024-08-08 15:10:42.840 +05 [6030] DEBUG:  logger shutting down
 done
server stopped
+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 15:10:42.940 +05 [6040] DEBUG:  logger shutting down
 done
server stopped
+ pg_controldata master
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400708995903891293
Database cluster state:               shut down
pg_control last modified:             Thu Aug  8 15:10:42 2024
Latest checkpoint location:           0/1041370
Latest checkpoint's REDO location:    0/1041370
Latest checkpoint's REDO WAL file:    000000010000000000000010
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:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:42 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:                off
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:                1048576
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:            b4dda080ead40b8ca338d9e5f6360b7489c33604ef1f8c3459cd7e1eba76a115
+ pg_controldata standby1
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400708995903891293
Database cluster state:               shut down
pg_control last modified:             Thu Aug  8 15:10:42 2024
Latest checkpoint location:           0/103B2F0
Latest checkpoint's REDO location:    0/103B2F0
Latest checkpoint's REDO WAL file:    000000020000000000000010
Latest checkpoint's TimeLineID:       2
Latest checkpoint's PrevTimeLineID:   2
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:42 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:                off
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:                1048576
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:            b4dda080ead40b8ca338d9e5f6360b7489c33604ef1f8c3459cd7e1eba76a115
+ pg_controldata standby2
pg_control version number:            1300
Catalog version number:               202307071
Database system identifier:           7400708995903891293
Database cluster state:               shut down in recovery
pg_control last modified:             Thu Aug  8 15:10:42 2024
Latest checkpoint location:           0/1039270
Latest checkpoint's REDO location:    0/1039270
Latest checkpoint's REDO WAL file:    000000010000000000000010
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0:732
Latest checkpoint's NextOID:          16387
Latest checkpoint's NextMultiXactId:  1
Latest checkpoint's NextMultiOffset:  0
Latest checkpoint's oldestXID:        722
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:            Thu Aug  8 15:10:41 2024
Fake LSN counter for unlogged rels:   0/3E8
Minimum recovery ending location:     0/103E670
Min recovery ending loc's timeline:   1
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
wal_level setting:                    replica
wal_log_hints setting:                off
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:                1048576
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:            b4dda080ead40b8ca338d9e5f6360b7489c33604ef1f8c3459cd7e1eba76a115
+ pg_waldump -p master 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1041370: invalid record length at 0/10413E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 15:10:42.721978 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01041370, prev 0/01041348, desc: CHECKPOINT_SHUTDOWN redo 0/1041370; tli 1; prev tli 1; fpw true; xid 0:733; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1039270: invalid record length at 0/10392E8: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039048, prev 0/01039008, desc: INSERT off: 101, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039088, prev 0/01039048, desc: INSERT off: 102, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010390C8, prev 0/01039088, desc: INSERT off: 103, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039108, prev 0/010390C8, desc: INSERT off: 104, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039148, prev 0/01039108, desc: INSERT off: 105, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039188, prev 0/01039148, desc: INSERT off: 106, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:41.733402 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby1 000000020000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/103B2F0: invalid record length at 0/103B368: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/010391C8, prev 0/01039188, desc: INSERT off: 107, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Heap        len (rec/tot):     63/    63, tx:        731, lsn: 0/01039208, prev 0/010391C8, desc: INSERT off: 108, flags: 0x00, blkref #0: rel 1663/5/16384 blk 442
rmgr: Transaction len (rec/tot):     34/    34, tx:        731, lsn: 0/01039248, prev 0/01039208, desc: COMMIT 2024-08-08 15:10:41.733402 +05
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039270, prev 0/01039248, desc: CHECKPOINT_SHUTDOWN redo 0/1039270; tli 1; prev tli 1; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
rmgr: XLOG        len (rec/tot):     42/    42, tx:          0, lsn: 0/010392E8, prev 0/01039270, desc: END_OF_RECOVERY tli 2; prev tli 1; time 2024-08-08 15:10:42.583043 +05
rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/01039318, prev 0/010392E8, desc: RUNNING_XACTS nextXid 732 latestCompletedXid 731 oldestRunningXid 732
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/01039350, prev 0/01039318, desc: CHECKPOINT_ONLINE redo 0/1039318; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 732; online
rmgr: XLOG        len (rec/tot):     49/   885, tx:          0, lsn: 0/010393C8, prev 0/01039350, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1259 blk 0 FPW
rmgr: XLOG        len (rec/tot):     49/  7061, tx:          0, lsn: 0/01039740, prev 0/010393C8, desc: FPI_FOR_HINT , blkref #0: rel 1663/5/1249 blk 17 FPW
rmgr: XLOG        len (rec/tot):    114/   114, tx:          0, lsn: 0/0103B2F0, prev 0/01039740, desc: CHECKPOINT_SHUTDOWN redo 0/103B2F0; tli 2; prev tli 2; fpw true; xid 0:732; oid 16387; multi 1; offset 0; oldest xid 722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 0; shutdown
+ pg_waldump -p standby2 000000010000000000000010
+ tail -n 10
pg_waldump: error: error in WAL record at 0/1041348: invalid record length at 0/1041370: expected at least 24, got 0
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041108, prev 0/010410C8, desc: INSERT off: 214, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041148, prev 0/01041108, desc: INSERT off: 215, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041188, prev 0/01041148, desc: INSERT off: 216, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010411C8, prev 0/01041188, desc: INSERT off: 217, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041208, prev 0/010411C8, desc: INSERT off: 218, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041248, prev 0/01041208, desc: INSERT off: 219, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041288, prev 0/01041248, desc: INSERT off: 220, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/010412C8, prev 0/01041288, desc: INSERT off: 221, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Heap        len (rec/tot):     63/    63, tx:        732, lsn: 0/01041308, prev 0/010412C8, desc: INSERT off: 222, flags: 0x00, blkref #0: rel 1663/5/16384 blk 443
rmgr: Transaction len (rec/tot):     34/    34, tx:        732, lsn: 0/01041348, prev 0/01041308, desc: COMMIT 2024-08-08 15:10:42.721978 +05
+ pg_rewind --progress --debug '--source-pgdata=standby1' '--target-pgdata=standby2'
pg_rewind: Source timeline history:
pg_rewind: Target timeline history:
pg_rewind: 1: 0/0 - 0/0
pg_rewind: servers diverged at WAL location 0/10392E8 on timeline 1
pg_rewind: rewinding from last common checkpoint at 0/1039270 on timeline 1
pg_rewind: reading source file list
pg_rewind: reading target file list
pg_rewind: reading WAL in target
pg_rewind: entry "base/5/pg_internal.init" excluded from source file list
pg_rewind: entry "postmaster.opts" excluded from source file list
pg_rewind: entry "pg_subtrans/0000" excluded from source file list
pg_rewind: entry "backup_manifest" excluded from source file list
pg_rewind: entry "global/pg_internal.init" excluded from source file list
pg_rewind: backup_label.old (COPY)
pg_rewind: base/1/1247_fsm (COPY)
pg_rewind: base/1/1247_vm (COPY)
pg_rewind: base/1/1249_fsm (COPY)
pg_rewind: base/1/1249_vm (COPY)
pg_rewind: base/1/1255_fsm (COPY)
pg_rewind: base/1/1255_vm (COPY)
pg_rewind: base/1/1259_fsm (COPY)
pg_rewind: base/1/1259_vm (COPY)
pg_rewind: base/1/12896_fsm (COPY)
pg_rewind: base/1/12896_vm (COPY)
pg_rewind: base/1/12901_fsm (COPY)
pg_rewind: base/1/12901_vm (COPY)
pg_rewind: base/1/12906_fsm (COPY)
pg_rewind: base/1/12906_vm (COPY)
pg_rewind: base/1/12911_fsm (COPY)
pg_rewind: base/1/12911_vm (COPY)
pg_rewind: base/1/2600_fsm (COPY)
pg_rewind: base/1/2600_vm (COPY)
pg_rewind: base/1/2601_fsm (COPY)
pg_rewind: base/1/2601_vm (COPY)
pg_rewind: base/1/2602_fsm (COPY)
pg_rewind: base/1/2602_vm (COPY)
pg_rewind: base/1/2603_fsm (COPY)
pg_rewind: base/1/2603_vm (COPY)
pg_rewind: base/1/2605_fsm (COPY)
pg_rewind: base/1/2605_vm (COPY)
pg_rewind: base/1/2606_fsm (COPY)
pg_rewind: base/1/2606_vm (COPY)
pg_rewind: base/1/2607_fsm (COPY)
pg_rewind: base/1/2607_vm (COPY)
pg_rewind: base/1/2608_fsm (COPY)
pg_rewind: base/1/2608_vm (COPY)
pg_rewind: base/1/2609_fsm (COPY)
pg_rewind: base/1/2609_vm (COPY)
pg_rewind: base/1/2610_fsm (COPY)
pg_rewind: base/1/2610_vm (COPY)
pg_rewind: base/1/2612_fsm (COPY)
pg_rewind: base/1/2612_vm (COPY)
pg_rewind: base/1/2615_fsm (COPY)
pg_rewind: base/1/2615_vm (COPY)
pg_rewind: base/1/2616_fsm (COPY)
pg_rewind: base/1/2616_vm (COPY)
pg_rewind: base/1/2617_fsm (COPY)
pg_rewind: base/1/2617_vm (COPY)
pg_rewind: base/1/2618_fsm (COPY)
pg_rewind: base/1/2618_vm (COPY)
pg_rewind: base/1/2619_fsm (COPY)
pg_rewind: base/1/2619_vm (COPY)
pg_rewind: base/1/2753_fsm (COPY)
pg_rewind: base/1/2753_vm (COPY)
pg_rewind: base/1/2836_fsm (COPY)
pg_rewind: base/1/2836_vm (COPY)
pg_rewind: base/1/2838_fsm (COPY)
pg_rewind: base/1/2838_vm (COPY)
pg_rewind: base/1/2840_fsm (COPY)
pg_rewind: base/1/2840_vm (COPY)
pg_rewind: base/1/3079_fsm (COPY)
pg_rewind: base/1/3079_vm (COPY)
pg_rewind: base/1/3394_fsm (COPY)
pg_rewind: base/1/3394_vm (COPY)
pg_rewind: base/1/3456_fsm (COPY)
pg_rewind: base/1/3456_vm (COPY)
pg_rewind: base/1/3541_fsm (COPY)
pg_rewind: base/1/3541_vm (COPY)
pg_rewind: base/1/3600_fsm (COPY)
pg_rewind: base/1/3600_vm (COPY)
pg_rewind: base/1/3601_fsm (COPY)
pg_rewind: base/1/3601_vm (COPY)
pg_rewind: base/1/3602_fsm (COPY)
pg_rewind: base/1/3602_vm (COPY)
pg_rewind: base/1/3603_fsm (COPY)
pg_rewind: base/1/3603_vm (COPY)
pg_rewind: base/1/3764_fsm (COPY)
pg_rewind: base/1/3764_vm (COPY)
pg_rewind: base/1/pg_filenode.map (COPY)
pg_rewind: base/4/1247_fsm (COPY)
pg_rewind: base/4/1247_vm (COPY)
pg_rewind: base/4/1249_fsm (COPY)
pg_rewind: base/4/1249_vm (COPY)
pg_rewind: base/4/1255_fsm (COPY)
pg_rewind: base/4/1255_vm (COPY)
pg_rewind: base/4/1259_fsm (COPY)
pg_rewind: base/4/1259_vm (COPY)
pg_rewind: base/4/12896_fsm (COPY)
pg_rewind: base/4/12896_vm (COPY)
pg_rewind: base/4/12901_fsm (COPY)
pg_rewind: base/4/12901_vm (COPY)
pg_rewind: base/4/12906_fsm (COPY)
pg_rewind: base/4/12906_vm (COPY)
pg_rewind: base/4/12911_fsm (COPY)
pg_rewind: base/4/12911_vm (COPY)
pg_rewind: base/4/2600_fsm (COPY)
pg_rewind: base/4/2600_vm (COPY)
pg_rewind: base/4/2601_fsm (COPY)
pg_rewind: base/4/2601_vm (COPY)
pg_rewind: base/4/2602_fsm (COPY)
pg_rewind: base/4/2602_vm (COPY)
pg_rewind: base/4/2603_fsm (COPY)
pg_rewind: base/4/2603_vm (COPY)
pg_rewind: base/4/2605_fsm (COPY)
pg_rewind: base/4/2605_vm (COPY)
pg_rewind: base/4/2606_fsm (COPY)
pg_rewind: base/4/2606_vm (COPY)
pg_rewind: base/4/2607_fsm (COPY)
pg_rewind: base/4/2607_vm (COPY)
pg_rewind: base/4/2608_fsm (COPY)
pg_rewind: base/4/2608_vm (COPY)
pg_rewind: base/4/2609_fsm (COPY)
pg_rewind: base/4/2609_vm (COPY)
pg_rewind: base/4/2610_fsm (COPY)
pg_rewind: base/4/2610_vm (COPY)
pg_rewind: base/4/2612_fsm (COPY)
pg_rewind: base/4/2612_vm (COPY)
pg_rewind: base/4/2615_fsm (COPY)
pg_rewind: base/4/2615_vm (COPY)
pg_rewind: base/4/2616_fsm (COPY)
pg_rewind: base/4/2616_vm (COPY)
pg_rewind: base/4/2617_fsm (COPY)
pg_rewind: base/4/2617_vm (COPY)
pg_rewind: base/4/2618_fsm (COPY)
pg_rewind: base/4/2618_vm (COPY)
pg_rewind: base/4/2619_fsm (COPY)
pg_rewind: base/4/2619_vm (COPY)
pg_rewind: base/4/2753_fsm (COPY)
pg_rewind: base/4/2753_vm (COPY)
pg_rewind: base/4/2836_fsm (COPY)
pg_rewind: base/4/2836_vm (COPY)
pg_rewind: base/4/2838_fsm (COPY)
pg_rewind: base/4/2838_vm (COPY)
pg_rewind: base/4/2840_fsm (COPY)
pg_rewind: base/4/2840_vm (COPY)
pg_rewind: base/4/3079_fsm (COPY)
pg_rewind: base/4/3079_vm (COPY)
pg_rewind: base/4/3394_fsm (COPY)
pg_rewind: base/4/3394_vm (COPY)
pg_rewind: base/4/3456_fsm (COPY)
pg_rewind: base/4/3456_vm (COPY)
pg_rewind: base/4/3541_fsm (COPY)
pg_rewind: base/4/3541_vm (COPY)
pg_rewind: base/4/3600_fsm (COPY)
pg_rewind: base/4/3600_vm (COPY)
pg_rewind: base/4/3601_fsm (COPY)
pg_rewind: base/4/3601_vm (COPY)
pg_rewind: base/4/3602_fsm (COPY)
pg_rewind: base/4/3602_vm (COPY)
pg_rewind: base/4/3603_fsm (COPY)
pg_rewind: base/4/3603_vm (COPY)
pg_rewind: base/4/3764_fsm (COPY)
pg_rewind: base/4/3764_vm (COPY)
pg_rewind: base/4/pg_filenode.map (COPY)
pg_rewind: base/5/1247_fsm (COPY)
pg_rewind: base/5/1247_vm (COPY)
pg_rewind: base/5/1249_fsm (COPY)
pg_rewind: base/5/1249_vm (COPY)
pg_rewind: base/5/1255_fsm (COPY)
pg_rewind: base/5/1255_vm (COPY)
pg_rewind: base/5/1259_fsm (COPY)
pg_rewind: base/5/1259_vm (COPY)
pg_rewind: base/5/12896_fsm (COPY)
pg_rewind: base/5/12896_vm (COPY)
pg_rewind: base/5/12901_fsm (COPY)
pg_rewind: base/5/12901_vm (COPY)
pg_rewind: base/5/12906_fsm (COPY)
pg_rewind: base/5/12906_vm (COPY)
pg_rewind: base/5/12911_fsm (COPY)
pg_rewind: base/5/12911_vm (COPY)
pg_rewind: base/5/16384_fsm (COPY)
pg_rewind: base/5/2600_fsm (COPY)
pg_rewind: base/5/2600_vm (COPY)
pg_rewind: base/5/2601_fsm (COPY)
pg_rewind: base/5/2601_vm (COPY)
pg_rewind: base/5/2602_fsm (COPY)
pg_rewind: base/5/2602_vm (COPY)
pg_rewind: base/5/2603_fsm (COPY)
pg_rewind: base/5/2603_vm (COPY)
pg_rewind: base/5/2605_fsm (COPY)
pg_rewind: base/5/2605_vm (COPY)
pg_rewind: base/5/2606_fsm (COPY)
pg_rewind: base/5/2606_vm (COPY)
pg_rewind: base/5/2607_fsm (COPY)
pg_rewind: base/5/2607_vm (COPY)
pg_rewind: base/5/2608_fsm (COPY)
pg_rewind: base/5/2608_vm (COPY)
pg_rewind: base/5/2609_fsm (COPY)
pg_rewind: base/5/2609_vm (COPY)
pg_rewind: base/5/2610_fsm (COPY)
pg_rewind: base/5/2610_vm (COPY)
pg_rewind: base/5/2612_fsm (COPY)
pg_rewind: base/5/2612_vm (COPY)
pg_rewind: base/5/2615_fsm (COPY)
pg_rewind: base/5/2615_vm (COPY)
pg_rewind: base/5/2616_fsm (COPY)
pg_rewind: base/5/2616_vm (COPY)
pg_rewind: base/5/2617_fsm (COPY)
pg_rewind: base/5/2617_vm (COPY)
pg_rewind: base/5/2618_fsm (COPY)
pg_rewind: base/5/2618_vm (COPY)
pg_rewind: base/5/2619_fsm (COPY)
pg_rewind: base/5/2619_vm (COPY)
pg_rewind: base/5/2753_fsm (COPY)
pg_rewind: base/5/2753_vm (COPY)
pg_rewind: base/5/2836_fsm (COPY)
pg_rewind: base/5/2836_vm (COPY)
pg_rewind: base/5/2838_fsm (COPY)
pg_rewind: base/5/2838_vm (COPY)
pg_rewind: base/5/2840_fsm (COPY)
pg_rewind: base/5/2840_vm (COPY)
pg_rewind: base/5/3079_fsm (COPY)
pg_rewind: base/5/3079_vm (COPY)
pg_rewind: base/5/3394_fsm (COPY)
pg_rewind: base/5/3394_vm (COPY)
pg_rewind: base/5/3456_fsm (COPY)
pg_rewind: base/5/3456_vm (COPY)
pg_rewind: base/5/3541_fsm (COPY)
pg_rewind: base/5/3541_vm (COPY)
pg_rewind: base/5/3600_fsm (COPY)
pg_rewind: base/5/3600_vm (COPY)
pg_rewind: base/5/3601_fsm (COPY)
pg_rewind: base/5/3601_vm (COPY)
pg_rewind: base/5/3602_fsm (COPY)
pg_rewind: base/5/3602_vm (COPY)
pg_rewind: base/5/3603_fsm (COPY)
pg_rewind: base/5/3603_vm (COPY)
pg_rewind: base/5/3764_fsm (COPY)
pg_rewind: base/5/3764_vm (COPY)
pg_rewind: base/5/pg_filenode.map (COPY)
pg_rewind: current_logfiles (COPY)
pg_rewind: global/1213_fsm (COPY)
pg_rewind: global/1213_vm (COPY)
pg_rewind: global/1260_fsm (COPY)
pg_rewind: global/1260_vm (COPY)
pg_rewind: global/1261_fsm (COPY)
pg_rewind: global/1261_vm (COPY)
pg_rewind: global/1262_fsm (COPY)
pg_rewind: global/1262_vm (COPY)
pg_rewind: global/2396_fsm (COPY)
pg_rewind: global/2396_vm (COPY)
pg_rewind: global/pg_filenode.map (COPY)
pg_rewind: log/postgresql-2024-08-08_151039.log (COPY)
pg_rewind: log/postgresql-2024-08-08_151040.log (COPY)
pg_rewind: log/postgresql-2024-08-08_151042.log (COPY)
pg_rewind: pg_hba.conf (COPY)
pg_rewind: pg_ident.conf (COPY)
pg_rewind: pg_logical/replorigin_checkpoint (COPY)
pg_rewind: pg_multixact/members/0000 (COPY)
pg_rewind: pg_multixact/offsets/0000 (COPY)
pg_rewind: pg_stat/pgstat.stat (COPY)
pg_rewind: pg_wal/00000001000000000000000B (COPY)
pg_rewind: pg_wal/00000001000000000000000C (COPY)
pg_rewind: pg_wal/00000001000000000000000D (COPY)
pg_rewind: pg_wal/00000001000000000000000E (COPY)
pg_rewind: pg_wal/00000001000000000000000F (COPY)
pg_rewind: pg_wal/000000010000000000000010 (COPY)
pg_rewind: pg_wal/00000002.history (COPY)
pg_rewind: pg_wal/000000020000000000000010 (COPY)
pg_rewind: pg_wal/archive_status/00000001000000000000000B.done (COPY)
pg_rewind: pg_wal/archive_status/00000001000000000000000C.done (COPY)
pg_rewind: pg_wal/archive_status/00000001000000000000000D.done (COPY)
pg_rewind: pg_wal/archive_status/00000001000000000000000E.done (COPY)
pg_rewind: pg_wal/archive_status/00000001000000000000000F.done (COPY)
pg_rewind: pg_xact/0000 (COPY)
pg_rewind: postgresql.auto.conf (COPY)
pg_rewind: postgresql.conf (COPY)
pg_rewind: base/5/1249 (NONE)
pg_rewind: block 17
pg_rewind: base/5/16384 (TRUNCATE)
pg_rewind: block 442
pg_rewind: standby.signal (REMOVE)
pg_rewind: postmaster.opts (REMOVE)
pg_rewind: pg_subtrans/0000 (REMOVE)
pg_rewind: log/postgresql-2024-08-08_151041.log (REMOVE)
pg_rewind: backup_manifest (REMOVE)
pg_rewind: need to copy 10 MB (total source directory size is 32 MB)
11050/11050 kB (100%) copied
pg_rewind: creating backup label and updating control file
pg_rewind: syncing target data directory
pg_rewind: Done!
+ cat
+ touch standby2/standby.signal
+ pg_ctl -w -D standby1 start -o '-p 5001'
waiting for server to start....2024-08-08 15:10:43.295 +05 [6109] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:43.295 +05 [6109] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:43.298 +05 [6109] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:43.298 +05 [6109] DEBUG:  created dynamic shared memory control segment 3967514876 (26976 bytes)
2024-08-08 15:10:43.298 +05 [6109] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:43.299 +05 [6109] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:43.299 +05 [6109] HINT:  Future log output will appear in directory "log".
 done
server started
+ pg_ctl -w -D standby2 start -o '-p 5002'
waiting for server to start....2024-08-08 15:10:43.402 +05 [6119] DEBUG:  registering background worker "logical replication launcher"
2024-08-08 15:10:43.402 +05 [6119] DEBUG:  mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory
2024-08-08 15:10:43.405 +05 [6119] DEBUG:  dynamic shared memory system will support 674 segments
2024-08-08 15:10:43.405 +05 [6119] DEBUG:  created dynamic shared memory control segment 2123275348 (26976 bytes)
2024-08-08 15:10:43.405 +05 [6119] DEBUG:  max_safe_fds = 986, usable_fds = 1000, already_open = 4
2024-08-08 15:10:43.406 +05 [6119] LOG:  redirecting log output to logging collector process
2024-08-08 15:10:43.406 +05 [6119] HINT:  Future log output will appear in directory "log".
 done
server started
+ psql -d postgres -a --no-psqlrc -p 5001
select count(*) from a;
 count  
--------
 100000
(1 row)

+ psql -d postgres -a --no-psqlrc -p 5002
select count(*) from a;
 count  
--------
 100000
(1 row)

+ pg_ctl -w -D standby1 stop -m fast
waiting for server to shut down....2024-08-08 15:10:43.650 +05 [6110] DEBUG: logger shutting down
done
server stopped
+ pg_ctl -w -D standby2 stop -m fast
waiting for server to shut down....2024-08-08 15:10:43.691 +05 [6120] DEBUG: logger shutting down
done
server stopped

On 08/08/2024 14:58, Georgy Shelkovy wrote:

this is good log of previous run for comparison

Thanks! That confirms my theory that the minRecoveryPoint in the "bad"
case is at the LSN where the histories diverged, while in the "good"
case, it's later. So pg_rewind is not wrong when it says that no rewind
is required. It's still confusing though. Here's a visualization of the
scenarios:

Legend:

TLI 1: this the WAL produced on the master
TLI 2: WAL produced on standby1
*: point of divergence
^: minRecoveryPoint on standby2

Good:

----------- TLI 2
/
----------*------------ TLI
^
Bad:

----------- TLI 2
/
----------*------------ TLI 1
^

There's a third possibility, which actually produces an assertion
failure. I was able to reproduce this case by adding some sleeps in the
script and in walreceiver startup code:

----------- TLI 2
/
----------*------------ TLI 1
^

pg_rewind: Source timeline history:
pg_rewind: 1: 0/0 - 0/1138F00
pg_rewind: 2: 0/1138F00 - 0/0
pg_rewind: Target timeline history:
pg_rewind: 1: 0/0 - 0/0
pg_rewind: servers diverged at WAL location 0/1138F00 on timeline 1
pg_rewind: ../src/bin/pg_rewind/pg_rewind.c:443: int main(int, char **):
Assertion `target_wal_endrec == divergerec' failed.

Except for the assertion failure, I think that's essentially the same as
the "Bad" case. On a non-assertion build, pg_rewind would report "no
rewind required" which seems correct.

So it seems true that rewind is not required in those cases. However, if
the WAL is already written on the standby's disk, just not replayed yet,
then when you restart the server, it will replay the WAL from timeline
1. That does seem surprising. Perhaps pg_rewind should just update the
minRecoveryPoint and minRecoveryTLI in control file in that case, to
force WAL recovery to follow the timeline switch to TLI 2.

I will try to write a TAP test for the "Bad" and the assertion failure
case, fix the assertion failure, and test how updating the
minRecoveryPoint would behave.

--
Heikki Linnakangas
Neon (https://neon.tech)

On 08/08/2024 16:07, Heikki Linnakangas wrote:

So it seems true that rewind is not required in those cases. However, if
the WAL is already written on the standby's disk, just not replayed yet,
then when you restart the server, it will replay the WAL from timeline
1. That does seem surprising. Perhaps pg_rewind should just update the
minRecoveryPoint and minRecoveryTLI in control file in that case, to
force WAL recovery to follow the timeline switch to TLI 2.

I will try to write a TAP test for the "Bad" and the assertion failure
case, fix the assertion failure, and test how updating the
minRecoveryPoint would behave.

I've divided this into three separate issues:

1. I think the assertion in pg_rewind is simply bogus, and we should
remove it. Attached 0002-Remove-bogus-assertion-in-pg_rewind.patch does
that, and adds a test case to cover it.

2. Independently of pg_rewind: When you start PostgreSQL, it will first
try to recover all the WAL it has locally in pg_wal. That goes wrong if
you have set a recovery target TLI. For example, imagine this situation:

- Recovery target TLI is 2, set explicitly in postgresql.conf
- The switchpoint from TLI 1 to 2 happened at WAL position 0/1510198
(the switchpoint is found in 00000002.history)
- There is a WAL file 000000010000000000000001 under pg_wal, which
contains valid WAL up to 0/1590000

When you start the server, it will first recover all the WAL from
000000010000000000000001, up to 0/1590000. Then it will connect to the
primary to fetch mor WAL, but it will fail to make any progress because
it already blew past the switch point.

It's obviously wrong to replay the WAL from timeline 1 beyond the 1->2
switchpoint, when the recovery target is TLI 2. The attached
0003-Don-t-read-past-current-TLI-during-archive-recovery.patch fixes
that. However, the logic to find the right WAL segment file and read the
WAL is extremely complicated, and I don't feel comfortable that I got
all the cases right. Review would be highly appreciated.

The patch includes a test case to demonstrate the case, with no
pg_rewind. It does include one "manual" step to copy a timeline history
file into pg_wal, marked with XXX, however. So I'm not sure how possible
this scenario is in production setups .

3. When pg_rewind has nothing to do, the target server is left
unmodified, in a state such that when you restart it, it will replay all
the WAL it has locally in pg_wal first, before connecting to the
primary. Even though the target is a direct ancestor of the source and
hence it *can* follow the WAL to the source's position without
rewinding, it doesn't mean that it *will* actually do so.

The attached changes it so that it updates the control file in that
case, setting minRecoveryPoint and minRecoveryPointTLI to point to the
source's current WAL position. That way, when you start it up, it will
follow the timeline history to reach that point. (This requires fixing
issue 2, because otherwise it still won't follow the history correctly
to reach the minRecoveryPointTLI)

To make the test pass, it actually would be sufficient to copy the
timeline history file into pg_wal (which the patch also does). But
updating the minRecoveryPoint seems good to ensure that it follows the
right timeline. Otherwise it relies on the logic at startup to find the
latest timeline, and that the latest timeline is the one you tried to
rewind to. I think it would go wrong if there was another
higher-numbered history file present in pg_wal for some reason.

All in all, I don't feel very confident about all this. The assertion
seems straightforward, so barring objections I'll commit and backpatch
that. The timeline-following at startup (issue 2) seems pretty clearly
wrong, but I'm not sure it's worth the risk to backpatch. Similarly
issue 3 might not be worth the risk to backpatch, especially if we don't
also backpatch 2. I would love to hear comments on those.

Georgy, if you have the possibility to test this patches with your repro
script, that would be highly appreciated.

--
Heikki Linnakangas
Neon (https://neon.tech)

On Fri, 2024-08-09 at 18:26 +0300, Heikki Linnakangas wrote:

3. When pg_rewind has nothing to do, the target server is left
unmodified, in a state such that when you restart it, it will replay
all
the WAL it has locally in pg_wal first, before connecting to the
primary. Even though the target is a direct ancestor of the source
and
hence it *can* follow the WAL to the source's position without
rewinding, it doesn't mean that it *will* actually do so.

The attached  changes it so that it updates the control file in that
case, setting minRecoveryPoint and minRecoveryPointTLI to point to
the
source's current WAL position. That way, when you start it up, it
will
follow the timeline history to reach that point. (This requires
fixing
issue 2, because otherwise it still won't follow the history
correctly
to reach the minRecoveryPointTLI)

Hello, I am currently researching a very similar issue. It seems like
your patches work correctly (thank you for those), but I've found a
weird edge case for patch 0004.

Basically, if you don't do anything to the primary after promotion (so
that its last checkpoint is *exactly* at the switchpoint), pg_rewind
with patch 0004 sets minRecoveryPoint to the exact LSN of the
switchpoint. After that the standby won't start, producing errors like
`requested timeline 2 does not contain minimum recovery point 0/4711F38
on timeline 2`.

This happens because of this check in xlogrecovery.c:
```
if (!XLogRecPtrIsInvalid(ControlFile->minRecoveryPoint) &&
tliOfPointInHistory(ControlFile->minRecoveryPoint - 1,
expectedTLEs) !=
ControlFile->minRecoveryPointTLI)
ereport(FATAL, /* ... */);
```
Because it checks TLI of minRecoveryPoint - 1, it expects to see the
timeline before the switch (timeline 1), but we actually want it to go
to timeline 2.
It seems like minRecoveryPoint is supposed to indicate minimum allowed
end of WAL, so when setting it to ensure some WAL is processed (like
the checkpoint WAL on another timeline) we have to set it to LSN+1
instead. Do you think this is the correct fix, or if instead -1 in
xlogrecovery.c should be removed?

Attached is a patch to 010 TAP test that reproduces this behavior.