Thread
Commits
Same data as JSON:
GET /api/v1/messages/:b64id/commits
the thread's linked commits as JSON, with link sources.
API reference →
-
Fix pg_rewind debug output to print the source timeline history
- e8240dbd86f7 16.5 landed
- b5a5027c9796 15.9 landed
- bb5592cacede 14.14 landed
- c943e2aae7c5 13.17 landed
- 8b86e289f7f0 12.21 landed
- a7bf3e668527 17.0 landed
- 49dc191bd1ae 18.0 landed
-
BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
PG Bug reporting form <noreply@postgresql.org> — 2024-08-07T12:19:42Z
The following bug has been logged on the website: Bug reference: 18575 Logged by: Georgy Silkly Email address: g.shelkovy@arenadata.io PostgreSQL version: 16.3 Operating system: docker alpine Description: Sometimes pg_rewind mistakenly assumes that nothing needs to be done, which results in the replica having data that is not on the master. Steps to reproduce script ```bash #!/bin/sh -eux echo "Goto script's directory" cd "$(dirname "$0")" echo "Stop master if exists" test -f master/postmaster.pid && pg_ctl -w -D master stop -m fast || echo $? echo "Remove master directory" rm -rf master echo "Create master directory" mkdir -p master echo "Initialize master, data checksums are mandatory" pg_ctl initdb -D master -o "--data-checksums -N -A trust --wal-segsize 1" echo "Debug to see recycling WAL, keep only 5 WAL files (because segsize 1MB)" cat >>master/postgresql.conf <<EOF hot_standby = on logging_collector = on log_min_messages = debug wal_keep_size = 5MB EOF echo "Accept replication connections on master" cat >> master/pg_hba.conf <<EOF local replication all trust host replication all 127.0.0.1/32 trust host replication all ::1/128 trust EOF echo "Start master" pg_ctl -w -D master start -o "-p 5000" echo "Stop standby1 if exists" test -f standby1/postmaster.pid && pg_ctl -w -D standby1 stop -m fast || echo $? echo "Remove standby1 directory" rm -rf standby1 echo "Base backup is taken with xlog files included" pg_basebackup -D standby1 -p 5000 -X fetch --verbose --write-recovery-conf echo "Start standby1" pg_ctl -w -D standby1 start -o "-p 5001" echo "Stop standby2 if exists" test -f standby2/postmaster.pid && pg_ctl -w -D standby2 stop -m fast || echo $? echo "Remove standby2 directory" rm -rf standby2 echo "Base backup is taken with xlog files included" pg_basebackup -D standby2 -p 5000 -X fetch --verbose --write-recovery-conf echo "Start standby2" pg_ctl -w -D standby2 start -o "-p 5002" echo "Create table and insert lot of rows" psql -d postgres -a --no-psqlrc -p 5000 <<EOF create table a (a int, b int); insert into a select i, i from generate_series(1, 100000) i; EOF echo "Stop master to recycle WAL files" pg_ctl -w -D master stop -m fast echo "Stop standby1 to recycle WAL files" pg_ctl -w -D standby1 stop -m fast echo "Stop standby2 to recycle WAL files" pg_ctl -w -D standby2 stop -m fast echo "Start master" pg_ctl -w -D master start -o "-p 5000" echo "Start standby1" pg_ctl -w -D standby1 start -o "-p 5001" echo "Start standby2" pg_ctl -w -D standby2 start -o "-p 5002" echo "Now promote standby1" pg_ctl -w -D standby1 promote echo "Wait until standby1 is promoted" while ! pg_isready -p 5001; do sleep 1; done echo "Insert some rows" psql -d postgres -a --no-psqlrc -p 5000 <<EOF insert into a select i, i from generate_series(1, 340) i; EOF echo "Standby2 node need to be stopped as well." pg_ctl -w -D standby2 stop -m fast echo "Stop the master after standby promotion" pg_ctl -w -D master stop -m fast echo "Standby1 node need to be stopped as well." pg_ctl -w -D standby1 stop -m fast echo "Do rewind using standby1 pgdata as source" pg_rewind --progress --debug --source-pgdata=standby1 --target-pgdata=standby2 echo "Parameters for standby2 postgresql.conf" cat >> standby2/postgresql.conf <<EOF primary_conninfo = 'port=5001' EOF echo "Place standby2 signal file" touch standby2/standby.signal echo "Start standby1" pg_ctl -w -D standby1 start -o "-p 5001" echo "Start standby2" pg_ctl -w -D standby2 start -o "-p 5002" echo "Same query" psql -d postgres -a --no-psqlrc -p 5001 <<EOF select count(*) from a; EOF echo "Different results" psql -d postgres -a --no-psqlrc -p 5002 <<EOF select count(*) from a; EOF echo "Stop standby1" pg_ctl -w -D standby1 stop -m fast echo "Stop standby2" pg_ctl -w -D standby2 stop -m fast ``` output ```bash + echo 'Goto script'"'"'s directory' Goto script's directory + dirname /var/lib/postgresql/r.sh + cd /var/lib/postgresql + echo 'Stop master if exists' Stop master if exists + test -f master/postmaster.pid + echo 1 1 + echo 'Remove master directory' Remove master directory + rm -rf master + echo 'Create master directory' Create master directory + mkdir -p master + echo 'Initialize master, data checksums are mandatory' Initialize master, data checksums are mandatory + 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 + echo 'Debug to see recycling WAL, keep only 5 WAL files (because segsize 1MB)' Debug to see recycling WAL, keep only 5 WAL files (because segsize 1MB) + cat + echo 'Accept replication connections on master' Accept replication connections on master + cat + echo 'Start master' Start master + pg_ctl -w -D master start -o '-p 5000' waiting for server to start....2024-08-07 17:14:59.431 +05 [19618] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:14:59.431 +05 [19618] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:14:59.434 +05 [19618] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:14:59.434 +05 [19618] DEBUG: created dynamic shared memory control segment 1581037720 (26976 bytes) 2024-08-07 17:14:59.434 +05 [19618] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:14:59.434 +05 [19618] LOG: redirecting log output to logging collector process 2024-08-07 17:14:59.434 +05 [19618] HINT: Future log output will appear in directory "log". done server started + echo 'Stop standby1 if exists' Stop standby1 if exists + test -f standby1/postmaster.pid + echo 1 1 + echo 'Remove standby1 directory' Remove standby1 directory + rm -rf standby1 + echo 'Base backup is taken with xlog files included' Base backup is taken with xlog files included + 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 + echo 'Start standby1' Start standby1 + pg_ctl -w -D standby1 start -o '-p 5001' waiting for server to start....2024-08-07 17:15:00.282 +05 [19631] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:15:00.282 +05 [19631] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:15:00.286 +05 [19631] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:15:00.286 +05 [19631] DEBUG: created dynamic shared memory control segment 1807324640 (26976 bytes) 2024-08-07 17:15:00.286 +05 [19631] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:15:00.286 +05 [19631] LOG: redirecting log output to logging collector process 2024-08-07 17:15:00.286 +05 [19631] HINT: Future log output will appear in directory "log". done server started + echo 'Stop standby2 if exists' Stop standby2 if exists + test -f standby2/postmaster.pid + echo 1 1 + echo 'Remove standby2 directory' Remove standby2 directory + rm -rf standby2 + echo 'Base backup is taken with xlog files included' Base backup is taken with xlog files included + 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 + echo 'Start standby2' Start standby2 + pg_ctl -w -D standby2 start -o '-p 5002' waiting for server to start....2024-08-07 17:15:01.123 +05 [19643] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:15:01.123 +05 [19643] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:15:01.126 +05 [19643] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:15:01.126 +05 [19643] DEBUG: created dynamic shared memory control segment 2259555868 (26976 bytes) 2024-08-07 17:15:01.126 +05 [19643] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:15:01.126 +05 [19643] LOG: redirecting log output to logging collector process 2024-08-07 17:15:01.126 +05 [19643] HINT: Future log output will appear in directory "log". done server started + echo 'Create table and insert lot of rows' Create table and insert lot of rows + 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 + echo 'Stop master to recycle WAL files' Stop master to recycle WAL files + pg_ctl -w -D master stop -m fast waiting for server to shut down....2024-08-07 17:15:01.650 +05 [19619] DEBUG: logger shutting down done server stopped + echo 'Stop standby1 to recycle WAL files' Stop standby1 to recycle WAL files + pg_ctl -w -D standby1 stop -m fast waiting for server to shut down....2024-08-07 17:15:01.731 +05 [19632] DEBUG: logger shutting down done server stopped + echo 'Stop standby2 to recycle WAL files' Stop standby2 to recycle WAL files + pg_ctl -w -D standby2 stop -m fast waiting for server to shut down....2024-08-07 17:15:01.831 +05 [19644] DEBUG: logger shutting down done server stopped + echo 'Start master' Start master + pg_ctl -w -D master start -o '-p 5000' waiting for server to start....2024-08-07 17:15:01.872 +05 [19660] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:15:01.872 +05 [19660] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:15:01.876 +05 [19660] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:15:01.876 +05 [19660] DEBUG: created dynamic shared memory control segment 2766949016 (26976 bytes) 2024-08-07 17:15:01.876 +05 [19660] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:15:01.876 +05 [19660] LOG: redirecting log output to logging collector process 2024-08-07 17:15:01.876 +05 [19660] HINT: Future log output will appear in directory "log". done server started + echo 'Start standby1' Start standby1 + pg_ctl -w -D standby1 start -o '-p 5001' waiting for server to start....2024-08-07 17:15:01.979 +05 [19670] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:15:01.979 +05 [19670] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:15:01.982 +05 [19670] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:15:01.982 +05 [19670] DEBUG: created dynamic shared memory control segment 1083876086 (26976 bytes) 2024-08-07 17:15:01.982 +05 [19670] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:15:01.983 +05 [19670] LOG: redirecting log output to logging collector process 2024-08-07 17:15:01.983 +05 [19670] HINT: Future log output will appear in directory "log". done server started + echo 'Start standby2' Start standby2 + pg_ctl -w -D standby2 start -o '-p 5002' waiting for server to start....2024-08-07 17:15:02.085 +05 [19679] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:15:02.085 +05 [19679] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:15:02.088 +05 [19679] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:15:02.088 +05 [19679] DEBUG: created dynamic shared memory control segment 4052049392 (26976 bytes) 2024-08-07 17:15:02.088 +05 [19679] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:15:02.089 +05 [19679] LOG: redirecting log output to logging collector process 2024-08-07 17:15:02.089 +05 [19679] HINT: Future log output will appear in directory "log". done server started + echo 'Now promote standby1' Now promote standby1 + pg_ctl -w -D standby1 promote waiting for server to promote.... done server promoted + echo 'Wait until standby1 is promoted' Wait until standby1 is promoted + pg_isready -p 5001 /tmp:5001 - accepting connections + echo 'Insert some rows' Insert some rows + psql -d postgres -a --no-psqlrc -p 5000 insert into a select i, i from generate_series(1, 340) i; INSERT 0 340 + echo 'Standby2 node need to be stopped as well.' Standby2 node need to be stopped as well. + pg_ctl -w -D standby2 stop -m fast waiting for server to shut down....2024-08-07 17:15:02.411 +05 [19680] DEBUG: logger shutting down done server stopped + echo 'Stop the master after standby promotion' Stop the master after standby promotion + pg_ctl -w -D master stop -m fast waiting for server to shut down....2024-08-07 17:15:02.517 +05 [19661] DEBUG: logger shutting down done server stopped + echo 'Standby1 node need to be stopped as well.' Standby1 node need to be stopped as well. + pg_ctl -w -D standby1 stop -m fast waiting for server to shut down....2024-08-07 17:15:02.617 +05 [19671] DEBUG: logger shutting down done server stopped + echo 'Do rewind using standby1 pgdata as source' Do rewind using standby1 pgdata as source + 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 + echo 'Parameters for standby2 postgresql.conf' Parameters for standby2 postgresql.conf + cat + echo 'Place standby2 signal file' Place standby2 signal file + touch standby2/standby.signal + echo 'Start standby1' Start standby1 + pg_ctl -w -D standby1 start -o '-p 5001' waiting for server to start....2024-08-07 17:15:02.723 +05 [19702] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:15:02.723 +05 [19702] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:15:02.726 +05 [19702] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:15:02.726 +05 [19702] DEBUG: created dynamic shared memory control segment 3627107606 (26976 bytes) 2024-08-07 17:15:02.726 +05 [19702] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:15:02.726 +05 [19702] LOG: redirecting log output to logging collector process 2024-08-07 17:15:02.726 +05 [19702] HINT: Future log output will appear in directory "log". done server started + echo 'Start standby2' Start standby2 + pg_ctl -w -D standby2 start -o '-p 5002' waiting for server to start....2024-08-07 17:15:02.830 +05 [19712] DEBUG: registering background worker "logical replication launcher" 2024-08-07 17:15:02.830 +05 [19712] DEBUG: mmap(146800640) with MAP_HUGETLB failed, huge pages disabled: Out of memory 2024-08-07 17:15:02.833 +05 [19712] DEBUG: dynamic shared memory system will support 674 segments 2024-08-07 17:15:02.833 +05 [19712] DEBUG: created dynamic shared memory control segment 2291233354 (26976 bytes) 2024-08-07 17:15:02.833 +05 [19712] DEBUG: max_safe_fds = 986, usable_fds = 1000, already_open = 4 2024-08-07 17:15:02.833 +05 [19712] LOG: redirecting log output to logging collector process 2024-08-07 17:15:02.833 +05 [19712] HINT: Future log output will appear in directory "log". done server started + echo 'Same query' 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 ``` -
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Heikki Linnakangas <hlinnaka@iki.fi> — 2024-08-08T07:03:29Z
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)
-
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Georgy Shelkovy <g.shelkovy@arenadata.io> — 2024-08-08T07:57:12Z
<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 && 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 >>master/postgresql.conf <<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 >> master/pg_hba.conf <<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 && 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 && 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 <<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 <<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 >> standby2/postgresql.conf <<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 <<EOF</div><div>select count(*) from a;</div><div>EOF</div><div># Different results</div><div>psql -d postgres -a --no-psqlrc -p 5002 <<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" <hlinnaka@iki.fi>:</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/">https://neon.tech</a>)<br /></span></blockquote>
-
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Heikki Linnakangas <hlinnaka@iki.fi> — 2024-08-08T09:29:53Z
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)
-
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Georgy Shelkovy <g.shelkovy@arenadata.io> — 2024-08-08T09:38:21Z
On second run I got bug 08.08.2024, 14:30, "Heikki Linnakangas" <hlinnaka@iki.fi>: 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) -
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Heikki Linnakangas <hlinnaka@iki.fi> — 2024-08-08T09:47:56Z
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)
-
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Georgy Shelkovy <g.shelkovy@arenadata.io> — 2024-08-08T10:12:32Z
sorry, my mistake, after 10-15 runs I got bug 08.08.2024, 14:48, "Heikki Linnakangas" <hlinnaka@iki.fi>: 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) -
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Georgy Shelkovy <g.shelkovy@arenadata.io> — 2024-08-08T11:58:20Z
this is good log of previous run for comparison 08.08.2024, 15:12, "Georgy Shelkovy" <g.shelkovy@arenadata.io>: sorry, my mistake, after 10-15 runs I got bug 08.08.2024, 14:48, "Heikki Linnakangas" <hlinnaka@iki.fi>: 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) -
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Heikki Linnakangas <hlinnaka@iki.fi> — 2024-08-08T13:07:19Z
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) -
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Heikki Linnakangas <hlinnaka@iki.fi> — 2024-08-09T15:26:29Z
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)
-
Re: BUG #18575: Sometimes pg_rewind mistakenly assumes that nothing needs to be done.
Maxim Michkov <m.michkov@arenadata.io> — 2025-09-02T14:12:14Z
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.