Test 031_recovery_conflict fails when a conflict counted twice - Mailing list pgsql-hackers

Hello hackers,

As a recent buildfarm test failure on olingo (which builds postgres with
-O1 and address sanitizer) [1] shows:
...
[23:12:02.127](0.166s) not ok 6 - snapshot conflict: stats show conflict on standby
[23:12:02.130](0.003s) #   Failed test 'snapshot conflict: stats show conflict on standby'
#   at /home/bf/bf-build/olingo/HEAD/pgsql/src/test/recovery/t/031_recovery_conflict.pl line 332.
[23:12:02.130](0.000s) #          got: '2'
#     expected: '1'
...
[23:12:06.848](1.291s) not ok 17 - 5 recovery conflicts shown in pg_stat_database
[23:12:06.887](0.040s) #   Failed test '5 recovery conflicts shown in pg_stat_database'
#   at /home/bf/bf-build/olingo/HEAD/pgsql/src/test/recovery/t/031_recovery_conflict.pl line 286.
[23:12:06.887](0.000s) #          got: '6'
#     expected: '5'
Waiting for replication conn standby's replay_lsn to pass 0/3459160 on primary
done
...

pgsql.build/testrun/recovery/031_recovery_conflict/log/031_recovery_conflict_standby.log:
2024-05-15 23:12:01.616 UTC [1299981][client backend][2/2:0] LOG: statement: FETCH FORWARD FROM 
test_recovery_conflict_cursor;
2024-05-15 23:12:01.617 UTC [1299981][client backend][2/2:0] LOG: statement: ;
2024-05-15 23:12:01.910 UTC [1297595][startup][34/0:0] LOG: recovery still waiting after 15.289 ms: recovery conflict
on
 
snapshot
2024-05-15 23:12:01.910 UTC [1297595][startup][34/0:0] DETAIL: Conflicting process: 1299981.
2024-05-15 23:12:01.910 UTC [1297595][startup][34/0:0] CONTEXT:  WAL redo at 0/344F468 for Heap2/PRUNE_VACUUM_SCAN: 
snapshotConflictHorizon: 746, isCatalogRel: F, nplans: 2, nredirected: 18, ndead: 0, nunused: 0, plans: [{ xmax: 0, 
infomask: 2816, infomask2: 2, ntuples: 2, offsets: [21, 22] }, { xmax: 0, infomask: 11008, infomask2: 32770, ntuples: 
18, offsets: [41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58] }], redirected: [23->41, 24->42,

25->43, 26->44, 27->45, 28->46, 29->47, 30->48, 31->49, 32->50, 33->51, 34->52, 35->53, 36->54, 37->55, 38->56, 39->57,

40->58]; blkref #0: rel 1663/16385/16386, blk 0
2024-05-15 23:12:01.959 UTC [1299981][client backend][2/2:0] FATAL: terminating connection due to conflict with
recovery
2024-05-15 23:12:01.959 UTC [1299981][client backend][2/2:0] DETAIL:  User query might have needed to see row versions

that must be removed.
2024-05-15 23:12:01.959 UTC [1299981][client backend][2/2:0] HINT: In a moment you should be able to reconnect to the 
database and repeat your command.
vvv an important difference from a successful test run
2024-05-15 23:12:01.966 UTC [1299981][client backend][2/2:0] LOG: could not send data to client: Broken pipe
2024-05-15 23:12:01.966 UTC [1299981][client backend][2/2:0] FATAL: terminating connection due to conflict with
recovery
2024-05-15 23:12:01.966 UTC [1299981][client backend][2/2:0] DETAIL:  User query might have needed to see row versions

that must be removed.
2024-05-15 23:12:01.966 UTC [1299981][client backend][2/2:0] HINT: In a moment you should be able to reconnect to the 
database and repeat your command.
^^^

test  031_recovery_conflict may fail in the following scenario:

031_recovery_conflict.pl:
     executes  a query, which produces a conflict:
     ## RECOVERY CONFLICT 2: Snapshot conflict
     ...
     $psql_standby->query_safe(...)

startup process:
         detects a snapshot conflict and sends
         PROCSIG_RECOVERY_CONFLICT_SNAPSHOT:
         (ResolveRecoveryConflictWithVirtualXIDs ->
         CancelVirtualTransaction) to the client backend

client backend:
             receives and processes the signal:
             HandleRecoveryConflictInterrupt; ProcessClientReadInterrupt ->
             ProcessInterrupts -> ProcessRecoveryConflictInterrupts ->
             ProcessRecoveryConflictInterrupt,

             reports the recovery conflict:
             pgstat_report_recovery_conflict(reason);

             and reports the error:
             ereport(FATAL, ... "terminating connection due to conflict with
             recovery" ...)
             sends the message to the server log:
             errfinish -> EmitErrorReport -> send_message_to_server_log

031_recovery_conflict.pl:
     # finds the message in the log and resets psql connection:
     check_conflict_log(
       "User query might have needed to see row versions that must
        be removed");
     $psql_standby->reconnect_and_clear();

startup process:
         keeps sending PROCSIG_RECOVERY_CONFLICT_SNAPSHOT to the client
         backend in a loop inside ResolveRecoveryConflictWithVirtualXIDs

client backend:
             tries to send the message to the client:
             send_message_to_frontend -> socket_flush ->
             internal_flush_buffer,
             gets an error (EPIPE) from secure_write, and calls
             ereport(COMMERROR,
               (errcode_for_socket_access(),
                errmsg("could not send data to client: %m")));

            receives the following PROCSIG_RECOVERY_CONFLICT_SNAPSHOT
            signal and processes it the same way:

            HandleRecoveryConflictInterrupt; ProcessClientReadInterrupt ->
            ProcessInterrupts -> ProcessRecoveryConflictInterrupts ->
            ProcessRecoveryConflictInterrupt,

            reports the recovery conflict:
            pgstat_report_recovery_conflict(reason);
            // now the conflict is counted twice

            and reports the error:
            ereport(FATAL, ... "terminating connection due to conflict with
            recovery" ...)
            sends the message to the server log:
            errfinish -> EmitErrorReport -> send_message_to_server_log

031_recovery_conflict.pl:
     calls
     check_conflict_stat("snapshot");
     and gets 2 instead of 1.

The patch adding delays to reproduce the issue is attached.

With the patch applied, I run the test (against an "-O0" build) in a loop:
for i in `seq 20`; do echo "I $i"; make check -s -C \
src/test/recovery/ PROVE_TESTS="t/031*"; grep ' not ok 6 ' \
src/test/recovery/tmp_check/log/regress_log_031_recovery_conflict && break;
done

and get exactly the same failure as on olingo:
I 1
# +++ tap check in src/test/recovery +++
t/031_recovery_conflict.pl .. 6/?
#   Failed test 'snapshot conflict: stats show conflict on standby'
#   at t/031_recovery_conflict.pl line 333.
#          got: '2'
#     expected: '1'
t/031_recovery_conflict.pl .. 13/?
#   Failed test '5 recovery conflicts shown in pg_stat_database'
#   at t/031_recovery_conflict.pl line 287.
#          got: '6'
#     expected: '5'
# Looks like you failed 2 tests of 18.
t/031_recovery_conflict.pl .. Dubious, test returned 2 (wstat 512, 0x200)
Failed 2/18 subtests

Test Summary Report
-------------------
t/031_recovery_conflict.pl (Wstat: 512 Tests: 18 Failed: 2)
   Failed tests:  6, 17
   Non-zero exit status: 2

(Similar failures can be seen with other sections of 031_recovery_conflict.)

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=olingo&dt=2024-05-15%2023%3A03%3A30

Best regards,
Alexander