Andres drew my attention to this [1] build farm failure.
Looks like a test I wrote resetting pg_stat_replication_slots is
failing:
# Failed test 'Check that reset timestamp is later after resetting
stats for slot 'test_slot' again.'
# at t/006_logical_decoding.pl line 261.
# got: 'f'
# expected: 't'
# Looks like you failed 1 test of 20.
[19:59:58] t/006_logical_decoding.pl ............
This is the test code itself:
is( $node_primary->safe_psql(
'postgres',
qq(SELECT stats_reset > '$reset1'::timestamptz FROM
pg_stat_replication_slots WHERE slot_name = '$stats_test_slot1')
),
qq(t),
qq(Check that reset timestamp is later after resetting stats for
slot '$stats_test_slot1' again.)
);
This is the relevant SQL statement:
SELECT stats_reset > '$reset1'::timestamptz FROM
pg_stat_replication_slots WHERE slot_name = '$stats_test_slot1'
When this statement is executed, reset1 is as shown:
2022-05-12 19:59:58.342 CEST [88829:3] 006_logical_decoding.pl LOG:
statement: SELECT stats_reset > '2022-05-12
19:59:58.402808+02'::timestamptz FROM pg_stat_replication_slots WHERE
slot_name = 'test_slot'
Note the timestamp of this execution. The stats reset occurred in the
past, and as such *must* have come before '2022-05-12
19:59:58.402808+02'::timestamptz.
The starred line is where `reset1` is fetched:
2022-05-12 19:59:58.305 CEST [86784:2] [unknown] LOG: connection
authorized: user=pgbf database=postgres
application_name=006_logical_decoding.pl
* 2022-05-12 19:59:58.306 CEST [86784:3] 006_logical_decoding.pl LOG:
statement: SELECT stats_reset FROM pg_stat_replication_slots WHERE
slot_name = 'test_slot'
2022-05-12 19:59:58.308 CEST [86784:4] 006_logical_decoding.pl LOG:
disconnection: session time: 0:00:00.003 user=pgbf database=postgres
host=[local]
2022-05-12 19:59:58.315 CEST [18214:1] [unknown] LOG: connection
received: host=[local]
2022-05-12 19:59:58.316 CEST [18214:2] [unknown] LOG: connection
authorized: user=pgbf database=postgres
application_name=006_logical_decoding.pl
2022-05-12 19:59:58.317 CEST [18214:3] 006_logical_decoding.pl LOG:
statement: SELECT pg_stat_reset_replication_slot(NULL)
2022-05-12 19:59:58.322 CEST [18214:4] 006_logical_decoding.pl LOG:
disconnection: session time: 0:00:00.007 user=pgbf database=postgres
host=[local]
2022-05-12 19:59:58.329 CEST [45967:1] [unknown] LOG: connection
received: host=[local]
2022-05-12 19:59:58.330 CEST [45967:2] [unknown] LOG: connection
authorized: user=pgbf database=postgres
application_name=006_logical_decoding.pl
2022-05-12 19:59:58.331 CEST [45967:3] 006_logical_decoding.pl LOG:
statement: SELECT stats_reset IS NOT NULL FROM
pg_stat_replication_slots WHERE slot_name = 'logical_slot'
2022-05-12 19:59:58.333 CEST [45967:4] 006_logical_decoding.pl LOG:
disconnection: session time: 0:00:00.003 user=pgbf database=postgres
host=[local]
2022-05-12 19:59:58.341 CEST [88829:1] [unknown] LOG: connection
received: host=[local]
2022-05-12 19:59:58.341 CEST [88829:2] [unknown] LOG: connection
authorized: user=pgbf database=postgres
application_name=006_logical_decoding.pl
2022-05-12 19:59:58.342 CEST [88829:3] 006_logical_decoding.pl LOG:
statement: SELECT stats_reset > '2022-05-12
19:59:58.402808+02'::timestamptz FROM pg_stat_replication_slots WHERE
slot_name = 'test_slot'
2022-05-12 19:59:58.344 CEST [88829:4] 006_logical_decoding.pl LOG:
disconnection: session time: 0:00:00.003 user=pgbf database=postgres
host=[local]
2022-05-12 19:59:58.350 CEST [50055:4] LOG: received fast shutdown request
2022-05-12 19:59:58.350 CEST [50055:5] LOG: aborting any active transactions
2022-05-12 19:59:58.352 CEST [50055:6] LOG: background worker
"logical replication launcher" (PID 89924) exited with exit code 1
2022-05-12 19:59:58.352 CEST [56213:1] LOG: shutting down
2022-05-12 19:59:58.352 CEST [56213:2] LOG: checkpoint starting:
shutdown immediate
2022-05-12 19:59:58.353 CEST [56213:3] LOG: checkpoint complete:
wrote 4 buffers (3.1%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB
2022-05-12 19:59:58.355 CEST [50055:7] LOG: database system is shut down
stats_reset was set in the past, so `reset1` shouldn't be after
'2022-05-12 19:59:58.306 CEST'. It looks like the timestamp appearing in
the test query would correspond to a time after the database is shut
down.
- melanie
[1]
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=morepork&dt=2022-05-12%2017%3A50%3A47
