Re: 041_checkpoint_at_promote.pl might fail due to race condition on child kill

Hello Fujii-san and Ayush,

30.10.2026 13:55, Fujii Masao wrote:
> On Fri, Oct 30, 2026 at 3:59 PM Ayush Tiwari
> <ayushtiwari(dot)slg01(at)gmail(dot)com> wrote:
>> Did multiple runs with it, and the changes lgtm.
> I've pushed the patch. Thanks!

Please look at a new failure of 041_checkpoint_at_promote produced by
tamandua recently [1]:
[03:10:10.869](0.025s) ok 4 - psql query died successfully after SIGKILL
[03:13:15.804](184.935s) # die: timed out waiting for file
/home/bf/bf-build/tamandua/REL_19_STABLE/pgsql.build/testrun/recovery/041_checkpoint_at_promote/log/041_checkpoint_at_promote_standby1.log
contents to match: (?^:all server processes terminated; reinitializing) at
/home/bf/bf-build/tamandua/REL_19_STABLE/pgsql/src/test/recovery/t/041_checkpoint_at_promote.pl line 166.
[03:13:15.806](0.003s) 1..4
timed out waiting for file
/home/bf/bf-build/tamandua/REL_19_STABLE/pgsql.build/testrun/recovery/041_checkpoint_at_promote/log/041_checkpoint_at_promote_standby1.log
contents to match: (?^:all server processes terminated; reinitializing) at
/home/bf/bf-build/tamandua/REL_19_STABLE/pgsql/src/test/recovery/t/041_checkpoint_at_promote.pl line 166.
# No postmaster PID for node "master"

041_checkpoint_at_promote_standby1.log contains:
2026-11-12 03:10:10.826 CET [3578531][client backend][6/2:0] LOG: statement: SELECT pg_backend_pid();
2026-11-12 03:10:10.861 CET [3577203][postmaster][:0] LOG:  client backend (PID 3578531) was terminated by signal 9: Killed
2026-11-12 03:10:10.861 CET [3577203][postmaster][:0] DETAIL: Failed process was running: SELECT pg_backend_pid();
2026-11-12 03:10:10.862 CET [3577203][postmaster][:0] LOG: terminating any other active server processes
2026-11-12 03:10:10.928 CET [3577203][postmaster][:0] LOG:  database system is ready to accept connections

There is no "terminating any other active server processes" message
indeed, the server was not shut down.

I managed to reproduce this locally (with the patch attached and with the
same parallel loop as before) and discovered that this can happen when
PMState goes from PM_HOT_STANDBY to PM_RUN (via PM_WAIT_BACKENDS) instead
of PM_HOT_STANDBY -> PM_WAIT_BACKENDS -> PM_WAIT_DEAD_END ->
PM_NO_CHILDREN -> "all server processes terminated; reinitializing".

This can be explained by two race conditions, with one precondition: the
startup process doesn't exit before pg_ctl kill.
1) The startup process becomes zombie for the postmaster if it exits when
waitpid() doesn't wait.
...
2026-11-14 13:29:02.900 UTC [695404][startup][:0] DEBUG: proc_exit(-1): 0 callbacks to make
...
2026-11-14 13:29:03.088 UTC [695367][postmaster][:0] DEBUG:  sending signal 3/SIGQUIT to startup process with pid 695404
2026-11-14 13:29:03.100 UTC [695367][postmaster][:0] LOG: !!!signal_child| delayed signal 3/SIGQUIT to startup process
with pid 695404
...
2026-11-14 13:29:03.170 UTC [695367][postmaster][:0] DEBUG:  startup process 695404 is still running
...
2026-11-14 13:29:03.198 UTC [695367][postmaster][:0] DEBUG: updating PMState from PM_WAIT_BACKENDS to PM_RUN

2) SIGQUIT sent to the startup process when it's being executed inside
exit(0), after the point when signal handlers of a process are not called
anymore, so SIGQUIT is ignored:
...
2026-11-14 07:54:44.900 EST [1110043][startup][:0] LOG: !!!proc_exit| delayed exit(0) for startup process
...
2026-11-14 07:54:44.900 EST [1110043][startup][:0] DEBUG: proc_exit(-1): 0 callbacks to make
2026-11-14 07:54:44.900 EST [1110037][postmaster][:0] LOG: !!!signal_child| delayed signal 3/SIGQUIT to startup process
with pid 1110043
...
2026-11-14 07:54:44.900 EST [1110037][postmaster][:0] DEBUG: startup process 1110043 is still running
...
2026-11-14 07:54:44.903 EST [1110037][postmaster][:0] LOG: !!!waitpid| ret: 1110043, status: 0
2026-11-14 07:54:44.903 EST [1110037][postmaster][:0] DEBUG: releasing pm child slot 89
2026-11-14 07:54:44.903 EST [1110037][postmaster][:0] DEBUG: updating PMState from PM_WAIT_BACKENDS to PM_RUN

Corresponding logs for these 2 cases and also a normal run's log are
attached for reference.

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=tamandua&dt=2026-11-12%2002%3A04%3A37

Best regards,
Alexander