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

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

Responses

Browse pgsql-hackers by date

  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