recovery test failure on morepork with timestamp mystery

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