Thread: BUG #16799: postgresql log issue(last completed transaction was at log time)

The following bug has been logged on the website:

Bug reference:      16799
Logged by:          oleg9301
Email address:      oleg9301@gmail.com
PostgreSQL version: 12.5
Operating system:   debian 10
Description:

OS:Linux hostname 4.19.0-12-amd64 #1 SMP Debian 4.19.152-1 (2020-10-18)
x86_64 GNU/Linux (debian 10)


After recovering postgresql from barman, in version 12.5 I don't have next
string
"last completed transaction was at log time %s"
In postgresql 11.9-1.pgdg100+1 everything fine.



2020-12-31 17:37:25.529 MSK [25753] LOG:  starting PostgreSQL 12.5 (Debian
12.5-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6)
8.3.0, 64-bit
2020-12-31 17:37:25.529 MSK [25753] LOG:  listening on IPv4 address
"127.0.0.1", port 5432
2020-12-31 17:37:25.530 MSK [25753] LOG:  listening on Unix socket
"/var/run/postgresql/.s.PGSQL.5432"
2020-12-31 17:37:25.575 MSK [25755] LOG:  database system was interrupted;
last known up at 2020-12-31 15:10:34 MSK
2020-12-31 17:37:25.600 MSK [25755] LOG:  redo starts at 11/E9000028
2020-12-31 17:37:25.608 MSK [25755] LOG:  consistent recovery state reached
at 11/E904C2D8
2020-12-31 17:37:26.342 MSK [25755] LOG:  redo done at 11/EFFFFF50
2020-12-31 17:37:26.656 MSK [25753] LOG:  database system is ready to accept
connections

PG Bug reporting form <noreply@postgresql.org> writes:
> After recovering postgresql from barman, in version 12.5 I don't have next
> string
> "last completed transaction was at log time %s"
> In postgresql 11.9-1.pgdg100+1 everything fine.

I don't see any reason to believe there's a bug here.  That message
would only appear if at least one transaction commit or abort record was
replayed from WAL, and it's quite possible there wouldn't have been.

            regards, tom lane

oleg9301 xz <oleg9301@gmail.com> writes:
> чт, 31 дек. 2020 г. в 18:21, Tom Lane <tgl@sss.pgh.pa.us>:
>> PG Bug reporting form <noreply@postgresql.org> writes:
>>> After recovering postgresql from barman, in version 12.5 I don't have
>>> next string
>>> "last completed transaction was at log time %s"
>>> In postgresql 11.9-1.pgdg100+1 everything fine.

>> I don't see any reason to believe there's a bug here.  That message
>> would only appear if at least one transaction commit or abort record was
>> replayed from WAL, and it's quite possible there wouldn't have been.

> There is always transations to commit, I(barman) do pg_basebackup once a
> day, and recieve wal with pg_receivewal(standby slot). And everything is
> fine, i have all data on OLAP DB(restore 6 times in day)
> (all WAL files playing correctly).

Hmm.  I poked a bit into the code, and I see what is different in v12:
commit 7acf8a876 ("Make crash recovery ignore recovery target settings")
caused all of recoveryStopsAfter() to be skipped when
!ArchiveRecoveryRequested ... including the part that updates
recoveryLastXTime.

Fujii-san, Peter, was that actually intended?  The commit message
doesn't mention it.  It's certainly arguable that this is cosmetic
and we don't care enough to contort the code to keep the old behavior
here.

            regards, tom lane