Re: recovery test failure on morepork with timestamp mystery

On Fri, May 13, 2022 at 11:43 AM Melanie Plageman
<melanieplageman(at)gmail(dot)com> wrote:
>
> 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'
>

I don't know if this is related, but I noticed that the log timestamp
(19:59:58.342) is reporting the $reset1 value (19:59:58.402808).

I did not understand how a timestamp saved from the past could be
ahead of the timestamp of the log.

------
Kind Regards,
Peter Smith.
Fujitsu Australia