| From: | Alexander Lakhin <exclusion(at)gmail(dot)com> |
|---|---|
| To: | Michael Paquier <michael(at)paquier(dot)xyz>, pgsql-hackers <pgsql-hackers(at)postgresql(dot)org> |
| Subject: | 041_checkpoint_at_promote.pl might fail due to race condition on child kill |
| Date: | 2026-10-07 04:00:00 |
| Message-ID: | e7abd282-655d-495e-94c9-e38a58917ebf@gmail.com |
| Views: | Whole Thread | Raw Message | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-hackers |
Hello hackers,
Please look at a new failure of 041_checkpoint_at_promote.pl produced by
bushmaster, [1]:
[23:56:13.841](0.002s) ok 4 - psql query died successfully after SIGKILL
[23:56:13.902](0.061s) not ok 5 - psql connect success
[23:56:13.902](0.000s)
[23:56:13.902](0.000s) # Failed test 'psql connect success'
# at t/041_checkpoint_at_promote.pl line 168.
[23:56:13.902](0.000s) # got: '2'
# expected: '0'
[23:56:13.902](0.000s) not ok 6 - psql select 1
[23:56:13.902](0.000s)
[23:56:13.902](0.000s) # Failed test 'psql select 1'
# at t/041_checkpoint_at_promote.pl line 169.
[23:56:13.902](0.000s) # got: ''
# expected: '1'
[23:56:13.902](0.000s) 1..6
pgsql.build/src/test/recovery/tmp_check/log/041_checkpoint_at_promote_standby1.log
2026-10-03 23:56:13.852 CEST [4159149][postmaster][:0] LOG: client backend (PID 4159398) was terminated by signal 9: Killed
2026-10-03 23:56:13.852 CEST [4159149][postmaster][:0] DETAIL: Failed process was running: SELECT pg_backend_pid();
2026-10-03 23:56:13.852 CEST [4159149][postmaster][:0] LOG: terminating any other active server processes
2026-10-03 23:56:13.855 CEST [4159149][postmaster][:0] LOG: all server processes terminated; reinitializing
2026-10-03 23:56:13.899 CEST [4159414][startup][:0] LOG: database system was interrupted; last known up at 2026-10-03
23:56:13 CEST
2026-10-03 23:56:13.899 CEST [4159414][startup][:0] LOG: database system was not properly shut down; automatic recovery
in progress
2026-10-03 23:56:13.899 CEST [4159414][startup][:0] LOG: crash recovery starts in timeline 1 and has target timeline 2
2026-10-03 23:56:13.900 CEST [4159414][startup][:0] LOG: redo starts at 0/3000028
2026-10-03 23:56:13.900 CEST [4159417][not initialized][:0] LOG: connection received: host=[local]
2026-10-03 23:56:13.900 CEST [4159417][client backend][:0] FATAL: the database system is in recovery mode
I've reproduced this failure locally, running multiple tests concurrently inside a 4-core VM, in a loop:
for i in {1..50}; do echo "Iteration $i"; parallel -j40 --linebuffer --tag PROVE_TESTS="t/041*" NO_TEMP_INSTALL=1
TEMP_CONFIG=~/extra.config make -s check -s -C src/test/recovery_{} PROVE_FLAGS="--timer" ::: `seq 25` || break; done;
(with bushmaster's parameters put in ~/extra.config)
This failed for me on iterations 14, 30, 10:
...
Iteration 10
...
10
10 # Failed test 'psql connect success'
10 # at t/041_checkpoint_at_promote.pl line 168.
10 # got: '2'
10 # expected: '0'
10
10 # Failed test 'psql select 1'
10 # at t/041_checkpoint_at_promote.pl line 169.
10 # got: ''
10 # expected: '1'
10 # Looks like you failed 2 tests of 6.
10 [03:51:18] t/041_checkpoint_at_promote.pl ..
10 Dubious, test returned 2 (wstat 512, 0x200)
10 Failed 2/6 subtests
10 [03:51:18]
10
10 Test Summary Report
10 -------------------
10 t/041_checkpoint_at_promote.pl (Wstat: 512 (exited 2) Tests: 6 Failed: 2)
10 Failed tests: 5-6
10 Non-zero exit status: 2
It looks like the same race condition was fixed in 022_crash_temp_files.pl
by e37ad5fa4 two years before 041_checkpoint_at_promote.pl appeared: [2].
[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=bushmaster&dt=2026-10-03%2021%3A37%3A08
[2] https://postgr.es/m/1801850.1649047827@sss.pgh.pa.us
Best regards,
Alexander
| From | Date | Subject | |
|---|---|---|---|
| Next Message | shveta malik | 2026-10-07 04:03:24 | Re: Persist slot invalidations before publishing them |
| Previous Message | shihao zhong | 2026-10-07 03:59:59 | Re: Parallel autovacuum: DROP DATABASE WITH (FORCE) fails on the parallel workers |