Re: logical decoding and replication of sequences

On Thu, Apr 07, 2022 at 08:34:50PM +0200, Tomas Vondra wrote:
> I've pushed a revert af all the commits related to this - decoding of
> sequences and test_decoding / built-in replication changes.

Two July buildfarm runs failed with PANIC during standby promotion:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tern&dt=2022-07-19%2004%3A13%3A18
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tern&dt=2022-07-31%2011%3A33%3A13

The attached patch hacks things so an ordinary x86_64 GNU/Linux machine
reproduces this consistently. "git bisect" then traced the regression to the
above revert commit (2c7ea57e56ca5f668c32d4266e0a3e45b455bef5). The pg_ctl
test suite passes under this hack in all supported branches, and it passed on
v15 until that revert. Would you investigate?

The buildfarm animal uses keep_error_builds. From kept data directories, I
deduced these events:

- After the base backup, auto-analyze ran on the primary and wrote WAL.
- Standby streamed and wrote up to 0/301FFF.
- Standby received the promote signal. Terminated streaming. WAL page at 0/302000 remained all-zeros.
- Somehow, end-of-recovery became a PANIC.

Key portions from buildfarm logs:

=== good run standby2 log
2022-07-21 22:55:16.860 UTC [25034912:5] LOG: received promote request
2022-07-21 22:55:16.878 UTC [26804682:2] FATAL: terminating walreceiver process due to administrator command
2022-07-21 22:55:16.878 UTC [25034912:6] LOG: invalid record length at 0/3000060: wanted 24, got 0
2022-07-21 22:55:16.878 UTC [25034912:7] LOG: redo done at 0/3000028 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.42 s
2022-07-21 22:55:16.878 UTC [25034912:8] LOG: selected new timeline ID: 2
2022-07-21 22:55:17.004 UTC [25034912:9] LOG: archive recovery complete
2022-07-21 22:55:17.005 UTC [23724044:1] LOG: checkpoint starting: force
2022-07-21 22:55:17.008 UTC [14549364:4] LOG: database system is ready to accept connections
2022-07-21 22:55:17.093 UTC [23724044:2] LOG: checkpoint complete: wrote 3 buffers (2.3%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.019 s, sync=0.001 s, total=0.089 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16384 kB, estimate=16384 kB
2022-07-21 22:55:17.143 UTC [27394418:1] [unknown] LOG: connection received: host=[local]
2022-07-21 22:55:17.144 UTC [27394418:2] [unknown] LOG: connection authorized: user=nm database=postgres application_name=003_promote.pl
2022-07-21 22:55:17.147 UTC [27394418:3] 003_promote.pl LOG: statement: SELECT pg_is_in_recovery()
2022-07-21 22:55:17.148 UTC [27394418:4] 003_promote.pl LOG: disconnection: session time: 0:00:00.005 user=nm database=postgres host=[local]
2022-07-21 22:55:58.301 UTC [14549364:5] LOG: received immediate shutdown request
2022-07-21 22:55:58.337 UTC [14549364:6] LOG: database system is shut down

=== failed run standby2 log, with my annotations
2022-07-19 05:28:22.136 UTC [7340406:5] LOG: received promote request
2022-07-19 05:28:22.163 UTC [8519860:2] FATAL: terminating walreceiver process due to administrator command
2022-07-19 05:28:22.166 UTC [7340406:6] LOG: invalid magic number 0000 in log segment 000000010000000000000003, offset 131072
New compared to the good run. XLOG_PAGE_MAGIC didn't match. This implies the WAL ended at a WAL page boundary.
2022-07-19 05:28:22.166 UTC [7340406:7] LOG: redo done at 0/301F168 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.18 s
2022-07-19 05:28:22.166 UTC [7340406:8] LOG: last completed transaction was at log time 2022-07-19 05:28:13.956716+00
New compared to the good run. The good run had no transactions to replay. The bad run replayed records from an auto-analyze.
2022-07-19 05:28:22.166 UTC [7340406:9] PANIC: invalid record length at 0/301F168: wanted 24, got 0
More WAL overall in bad run, due to auto-analyze. End of recovery wrongly considered a PANIC.
2022-07-19 05:28:22.583 UTC [8388800:4] LOG: startup process (PID 7340406) was terminated by signal 6: IOT/Abort trap
2022-07-19 05:28:22.584 UTC [8388800:5] LOG: terminating any other active server processes
2022-07-19 05:28:22.587 UTC [8388800:6] LOG: shutting down due to startup process failure
2022-07-19 05:28:22.627 UTC [8388800:7] LOG: database system is shut down

Let me know if I've left out details you want; I may be able to dig more out
of the buildfarm artifacts.