Read only compute pinned to an lsn requests page at a future lsn

[LizardWizzard]

Steps to reproduce

Run pgdump on pinned node while primary is active (or not all the time active, but is active rather frequently)

Expected result

No errors

Actual result

page server returned error: Timed out while waiting for WAL record at LSN F/464B4A48 to arrive,

Environment

prod

Details

While migrating projects into different aws account I've found an issue thats quite puzzling. I spin up compute node in docker locally to check that it works. Compare dump output, etc.
I follow this instruction from @kelvich with slightly modified script:

#!/bin/sh
set -e

cd /var/db/postgres
rm -rf bb_export
mkdir bb_export
chmod 0700 bb_export
cd bb_export

psql -h$PSHOST -p$PSPORT -c "basebackup $TNT $TLI" > backup.tar
tar xvf backup.tar

LSN=`pg_controldata . | grep 'REDO location' | awk '{print $5}'`

echo "Basebackup LSN: $LSN"
echo "zenith.signal: `cat zenith.signal`"

touch standby.signal

cat << EOF > postgresql.conf
neon.pageserver_connstring = 'host=$PSHOST port=$PSPORT'
neon.tenant_id = '$TNT' neon.timeline_id = '$TLI'
shared_preload_libraries = 'neon'
listen_addresses = '127.0.0.1'
port = 5555
recovery_target_lsn = '$LSN'
EOF

cd ..
mkdir -p $BATCH
pg_ctl -D bb_export -l logfile start
pg_dumpall -h127.0.0.1 -p5555 -U cloud_admin > $BATCH/dump-$TNT-$TLI-$PSHOST-$SUFFIX
pg_ctl -D bb_export -l logfile stop
rm -rf bb_export

The problem is that pg_dump fails with:

pg_dump: error: Dumping the contents of table "x" failed: PQgetResult() failed.
pg_dump: detail: Error message from server: ERROR: could not read block 62753 in rel 1663/32768/41055.0 from page server at lsn F/464B4A48
DETAIL: page server returned error: Timed out while waiting for WAL record at LSN F/464B4A48 to arrive, last\_record\_lsn F/4613EF28 disk consistent LSN=F/4610FF58
pg_dump: detail: Command was: COPY ... stdout;
pg\_dumpall: error: pg\_dump failed on database "y", exiting

Prior to the error script outputs this:

Basebackup LSN: F/4610D030
zenith.signal: PREV LSN: F/4610D008

The error looks strange to me, because basebackup lsn (and thus recovery_target_lsn) in this case are both equal to F/4610D030. And F/464B4A48 - the lsn at which the page was requested is greater. In my understanding in order to reconstruct the state at some lsn it shouldnt require future changes.
Additional info, this setup worked well for many projects before this one, the error happened for a project that is bigger in size and is quite active.

Full Postgres log:

2023-01-31 19:23:25.820 GMT [24] LOG:  starting PostgreSQL 15.1 on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2023-01-31 19:23:25.820 GMT [24] LOG:  listening on IPv4 address "127.0.0.1", port 5555
2023-01-31 19:23:25.825 GMT [24] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5555"
2023-01-31 19:23:25.830 GMT [27] LOG:  [ZENITH] found 'zenith.signal' file. setting prev LSN to F/4610D008
2023-01-31 19:23:25.830 GMT [27] LOG:  database system was shut down at 2022-11-25 01:24:05 GMT
2023-01-31 19:23:25.830 GMT [27] LOG:  starting with zenith basebackup at LSN F/4610D030, prev F/4610D008
2023-01-31 19:23:25.830 GMT [27] LOG:  Continue writing WAL at F/4610D030
2023-01-31 19:23:25.838 GMT [24] LOG:  database system is ready to accept connections
2023-01-31 19:23:25.843 GMT [30] LOG:  [NEON_SMGR] libpagestore: connected to 'host=zenith-1-ps-4.local port=6400'
2023-01-31 19:23:25.843 GMT [29] LOG:  [NEON_SMGR] libpagestore: connected to 'host=zenith-1-ps-4.local port=6400'
2023-01-31 19:23:25.922 GMT [34] LOG:  [NEON_SMGR] libpagestore: connected to 'host=zenith-1-ps-4.local port=6400'
2023-01-31 19:23:26.004 GMT [37] LOG:  [NEON_SMGR] libpagestore: connected to 'host=zenith-1-ps-4.local port=6400'
2023-01-31 19:23:26.250 GMT [40] LOG:  [NEON_SMGR] libpagestore: connected to 'host=zenith-1-ps-4.local port=6400'
2023-01-31 19:23:26.493 GMT [43] LOG:  [NEON_SMGR] libpagestore: connected to 'host=zenith-1-ps-4.local port=6400'
2023-01-31 19:24:25.909 GMT [44] LOG:  [NEON_SMGR] libpagestore: connected to 'host=zenith-1-ps-4.local port=6400'
2023-01-31 19:24:36.369 GMT [43] ERROR:  could not read block 62753 in rel 1663/32768/41055.0 from page server at lsn F/464B4A48
2023-01-31 19:24:36.369 GMT [43] DETAIL:  page server returned error: Timed out while waiting for WAL record at LSN F/464B4A48 to arrive, last_record_lsn F/4613EF28 disk consistent LSN=F/4610FF58
2023-01-31 19:24:36.369 GMT [43] STATEMENT:  COPY ... TO stdout;

The correct log during startup should be:

2023-01-26 15:01:25.514 GMT [24] LOG:  entering standby mode
2023-01-26 15:01:25.514 GMT [24] LOG:  starting with zenith basebackup at LSN 0/172D680, prev 0/172D658
2023-01-26 15:01:25.515 GMT [24] LOG:  database system was not properly shut down; automatic recovery in progress
2023-01-26 15:01:25.519 GMT [24] LOG:  consistent recovery state reached at 0/172D680

But for some reason postgres doesnt go into standby mode despite having standby.signal. See https://github.com/neondatabase/postgres/blob/REL_15_STABLE_neon/src/backend/access/transam/xlogrecovery.c#L524

This reproduces only for certain projects. Bigger and active ones. I've managed to run this sequence earlier and later for other projects without errors. On project I faced this error it reproduced every time

This might be relevant for read replica efforts cc @lubennikovaav

Originally posted in slack here

[lubennikovaav]

https://github.com/neondatabase/postgres/blob/REL_15_STABLE_neon/src/backend/access/transam/xlogrecovery.c#L1059

if (standby_signal_file_found)
{
StandbyModeRequested = true;
ArchiveRecoveryRequested = XLogRecPtrIsInvalid(zenithLastRec); /* no need to perform WAL recovery in Neon */
}

where zenithLastRec is PREV LSN from zenith.signal file
https://github.com/neondatabase/postgres/blob/REL_15_STABLE_neon/src/backend/access/transam/xlog.c#L5016

If it is valid, we won't enter standby mode.

PREV LSN can be sent as "none" or "invalid", if prev_record_lsn is unknown in pageserver
https://github.com/neondatabase/neon/blob/main/pageserver/src/basebackup.rs#L422

This explains, why script worked in other cases. Though, I would expect that this is an exception, rather than norm.
Will dig a bit more into this.

@LizardWizzard , can you please confirm that zenith.signal contains PREV LSN "none" or PREV LSN "invalid" for working cases?

[LizardWizzard]

See the attached thread in slack:

Prior to the error script outputs this:
Basebackup LSN: F/4610D030
zenith.signal: PREV LSN: F/4610D008

[lubennikovaav]

See the attached thread in slack:

Prior to the error script outputs this:
Basebackup LSN: F/4610D030
zenith.signal: PREV LSN: F/4610D008

Yep, I've read the thread. These are values for error case, right?

Is it the same for projects that pass this pg_dump check without failure?

[LizardWizzard]

These are values for error case, right?

Yes

Is it the same for projects that pass this pg_dump check without failure?

I believe so, but cannot say for sure, because unfortunately I no longer have access to the setup that was used when the error occurred (we've discontinued these hosts).

The error should be reproducible. The script can be tried in any environment (even when compute is running).