Op 19-04-2022 om 19:36 schreef Andres Freund:
Hi,
On 2022-04-19 13:50:25 +0200, Erik Rijkers wrote:
The 12th run of statbug.sh crashed and gave a corefile.
I ran through quite a few iterations by now, without reproducing :(
I guess there's some timing issue and you're hitting on your system
due to the slower disks.
Program terminated with signal 6, Aborted.
#0 0x000000357d6324f5 in raise () from /lib64/libc.so.6
(gdb) bt
#0 0x000000357d6324f5 in raise () from /lib64/libc.so.6
#1 0x000000357d633cd5 in abort () from /lib64/libc.so.6
#2 0x0000000000b3bada in ExceptionalCondition (conditionName=0xd389a1
"tabstat->trans == trans", errorType=0xd388b2 "FailedAssertion",
fileName=0xd388a0 "pgstat_relation.c", lineNumber=508) at assert.c:69
#3 0x00000000009bf5dc in AtEOXact_PgStat_Relations (xact_state=0x31b1b50,
isCommit=true) at pgstat_relation.c:508
#4 0x00000000009c4107 in AtEOXact_PgStat (isCommit=true, parallel=false) at
pgstat_xact.c:54
#5 0x0000000000583764 in CommitTransaction () at xact.c:2360
#6 0x0000000000584354 in CommitTransactionCommand () at xact.c:3048
#7 0x000000000090b34e in apply_handle_commit_internal
(commit_data=0x7ffd024b5940) at worker.c:1532
#8 0x000000000090a287 in apply_handle_commit (s=0x7ffd024b59b0) at
worker.c:845
#9 0x000000000090ce3a in apply_dispatch (s=0x7ffd024b59b0) at worker.c:2473
#10 0x000000000090d41c in LogicalRepApplyLoop (last_received=74680880) at
worker.c:2757
#11 0x000000000090e974 in start_apply (origin_startpos=0) at worker.c:3526
#12 0x000000000090f156 in ApplyWorkerMain (main_arg=0) at worker.c:3782
#13 0x00000000008c7623 in StartBackgroundWorker () at bgworker.c:858
#14 0x00000000008d1557 in do_start_bgworker (rw=0x30ff0a0) at
postmaster.c:5802
#15 0x00000000008d1903 in maybe_start_bgworkers () at postmaster.c:6026
#16 0x00000000008d09ba in sigusr1_handler (postgres_signal_arg=10) at
postmaster.c:5191
#17 <signal handler called>
#18 0x000000357d6e1683 in __select_nocancel () from /lib64/libc.so.6
#19 0x00000000008cc6c1 in ServerLoop () at postmaster.c:1757
#20 0x00000000008cc0aa in PostmasterMain (argc=11, argv=0x30d6590) at
postmaster.c:1465
#21 0x00000000007c9256 in main (argc=11, argv=0x30d6590) at main.c:202
(gdb) f 3
#3 0x00000000009bf5dc in AtEOXact_PgStat_Relations (xact_state=0x31b1b50,
isCommit=true) at pgstat_relation.c:508
508 Assert(tabstat->trans == trans);
(gdb) p tabstat
$1 = (PgStat_TableStatus *) 0x319e630
(gdb) p *tabstat
$2 = {t_id = 2139062143, t_shared = 127, trans = 0x7f7f7f7f7f7f7f7f,
t_counts = {t_numscans = 9187201950435737471, t_tuples_returned =
9187201950435737471, t_tuples_fetched = 9187201950435737471,
t_tuples_inserted = 9187201950435737471, t_tuples_updated =
9187201950435737471, t_tuples_deleted = 9187201950435737471,
t_tuples_hot_updated = 9187201950435737471, t_truncdropped = 127,
t_delta_live_tuples = 9187201950435737471, t_delta_dead_tuples =
9187201950435737471, t_changed_tuples = 9187201950435737471,
t_blocks_fetched = 9187201950435737471, t_blocks_hit = 9187201950435737471},
relation = 0x7f7f7f7f7f7f7f7f}
(gdb) p trans
$3 = (PgStat_TableXactStatus *) 0x31b1ba8
(gdb) p *trans
$4 = {tuples_inserted = 1, tuples_updated = 0, tuples_deleted = 0,
truncdropped = false, inserted_pre_truncdrop = 0, updated_pre_truncdrop = 0,
deleted_pre_truncdrop = 0, nest_level = 1, upper = 0x0,
parent = 0x319e630, next = 0x31b1ab8}
(gdb)
Could you print out
p xact_state
p *xact_state
p xact_state->first
p *xact_state->first
Do you have the server log file for the failed run / instance?
(gdb) p xact_state
$5 = (PgStat_SubXactStatus *) 0x31b1b50
(gdb) p *xact_state
$6 = {nest_level = 1, prev = 0x0, pending_drops = {head = {prev =
0x31b1b60, next = 0x31b1b60}}, pending_drops_count = 0, first = 0x31b1ba8}
(gdb) p xact_state->first
$7 = (PgStat_TableXactStatus *) 0x31b1ba8
(gdb) p *xact_state->first
$8 = {tuples_inserted = 1, tuples_updated = 0, tuples_deleted = 0,
truncdropped = false, inserted_pre_truncdrop = 0, updated_pre_truncdrop
= 0, deleted_pre_truncdrop = 0, nest_level = 1, upper = 0x0,
parent = 0x319e630, next = 0x31b1ab8}
(gdb)
The logfile is attached.
Erik
Greetings,
Andres Freund
2022-04-19 13:33:42.944 CEST [24981] LOG: starting PostgreSQL
15devel_HEAD_20220419_1308_a62bff74b135 on x86_64-pc-linux-gnu, compiled by gcc
(GCC) 8.2.0, 64-bit
2022-04-19 13:33:42.945 CEST [24981] LOG: listening on IPv4 address
"127.0.0.1", port 6526
2022-04-19 13:33:43.010 CEST [24981] LOG: listening on Unix socket
"/tmp/.s.PGSQL.6526"
2022-04-19 13:33:43.085 CEST [24991] LOG: database system was shut down at
2022-04-19 13:33:41 CEST
2022-04-19 13:33:43.181 CEST [24981] LOG: database system is ready to accept
connections
2022-04-19 13:33:51.040 CEST [25047] LOG: received replication command:
CREATE_REPLICATION_SLOT "pub_6527_from_6526" LOGICAL pgoutput (SNAPSHOT
'nothing')
2022-04-19 13:33:51.040 CEST [25047] STATEMENT: CREATE_REPLICATION_SLOT
"pub_6527_from_6526" LOGICAL pgoutput (SNAPSHOT 'nothing')
2022-04-19 13:33:51.306 CEST [25047] LOG: logical decoding found consistent
point at 0/1518C10
2022-04-19 13:33:51.306 CEST [25047] DETAIL: There are no running transactions.
2022-04-19 13:33:51.306 CEST [25047] STATEMENT: CREATE_REPLICATION_SLOT
"pub_6527_from_6526" LOGICAL pgoutput (SNAPSHOT 'nothing')
2022-04-19 13:33:51.444 CEST [25052] LOG: received replication command:
IDENTIFY_SYSTEM
2022-04-19 13:33:51.444 CEST [25052] STATEMENT: IDENTIFY_SYSTEM
2022-04-19 13:33:51.444 CEST [25052] LOG: received replication command:
START_REPLICATION SLOT "pub_6527_from_6526" LOGICAL 0/0 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:51.444 CEST [25052] STATEMENT: START_REPLICATION SLOT
"pub_6527_from_6526" LOGICAL 0/0 (proto_version '3', publication_names
'"pub_6526_to_6527"')
2022-04-19 13:33:51.445 CEST [25052] LOG: starting logical decoding for slot
"pub_6527_from_6526"
2022-04-19 13:33:51.445 CEST [25052] DETAIL: Streaming transactions committing
after 0/1518C48, reading WAL from 0/1518C10.
2022-04-19 13:33:51.445 CEST [25052] STATEMENT: START_REPLICATION SLOT
"pub_6527_from_6526" LOGICAL 0/0 (proto_version '3', publication_names
'"pub_6526_to_6527"')
2022-04-19 13:33:51.445 CEST [25052] LOG: logical decoding found consistent
point at 0/1518C10
2022-04-19 13:33:51.445 CEST [25052] DETAIL: There are no running transactions.
2022-04-19 13:33:51.445 CEST [25052] STATEMENT: START_REPLICATION SLOT
"pub_6527_from_6526" LOGICAL 0/0 (proto_version '3', publication_names
'"pub_6526_to_6527"')
2022-04-19 13:33:51.455 CEST [25054] LOG: received replication command:
CREATE_REPLICATION_SLOT "pg_16406_sync_16390_7088276686057484707" LOGICAL
pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:51.455 CEST [25054] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16390_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:51.467 CEST [25057] LOG: received replication command:
CREATE_REPLICATION_SLOT "pg_16406_sync_16384_7088276686057484707" LOGICAL
pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:51.467 CEST [25057] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16384_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:52.034 CEST [25054] LOG: logical decoding found initial
starting point at 0/1519488
2022-04-19 13:33:52.034 CEST [25054] DETAIL: Waiting for transactions
(approximately 1) older than 732 to end.
2022-04-19 13:33:52.034 CEST [25054] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16390_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:52.363 CEST [25054] LOG: logical decoding found consistent
point at 0/1519610
2022-04-19 13:33:52.363 CEST [25054] DETAIL: There are no running transactions.
2022-04-19 13:33:52.363 CEST [25054] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16390_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:52.365 CEST [25057] LOG: logical decoding found initial
starting point at 0/15194C0
2022-04-19 13:33:52.365 CEST [25057] DETAIL: Waiting for transactions
(approximately 1) older than 732 to end.
2022-04-19 13:33:52.365 CEST [25057] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16384_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:52.365 CEST [25057] LOG: logical decoding found consistent
point at 0/1519610
2022-04-19 13:33:52.365 CEST [25057] DETAIL: There are no running transactions.
2022-04-19 13:33:52.365 CEST [25057] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16384_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:52.370 CEST [25058] LOG: logical replication apply worker for
subscription "pub_6526_from_6525" has started
2022-04-19 13:33:52.386 CEST [25062] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_history" has started
2022-04-19 13:33:52.398 CEST [25068] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_accounts" has started
2022-04-19 13:33:52.743 CEST [25054] LOG: received replication command:
START_REPLICATION SLOT "pg_16406_sync_16390_7088276686057484707" LOGICAL
0/1519648 (proto_version '3', publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:52.743 CEST [25054] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16390_7088276686057484707" LOGICAL 0/1519648 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:52.743 CEST [25054] LOG: starting logical decoding for slot
"pg_16406_sync_16390_7088276686057484707"
2022-04-19 13:33:52.743 CEST [25054] DETAIL: Streaming transactions committing
after 0/1519648, reading WAL from 0/1519488.
2022-04-19 13:33:52.743 CEST [25054] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16390_7088276686057484707" LOGICAL 0/1519648 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:52.844 CEST [25054] LOG: logical decoding found consistent
point at 0/1519488
2022-04-19 13:33:52.844 CEST [25054] DETAIL: Logical decoding will begin using
saved snapshot.
2022-04-19 13:33:52.844 CEST [25054] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16390_7088276686057484707" LOGICAL 0/1519648 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:52.845 CEST [25054] LOG: received replication command:
DROP_REPLICATION_SLOT pg_16406_sync_16390_7088276686057484707 WAIT
2022-04-19 13:33:52.845 CEST [25054] STATEMENT: DROP_REPLICATION_SLOT
pg_16406_sync_16390_7088276686057484707 WAIT
2022-04-19 13:33:53.065 CEST [25057] LOG: received replication command:
START_REPLICATION SLOT "pg_16406_sync_16384_7088276686057484707" LOGICAL
0/1519648 (proto_version '3', publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:53.065 CEST [25057] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16384_7088276686057484707" LOGICAL 0/1519648 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:53.065 CEST [25057] LOG: starting logical decoding for slot
"pg_16406_sync_16384_7088276686057484707"
2022-04-19 13:33:53.065 CEST [25057] DETAIL: Streaming transactions committing
after 0/1519648, reading WAL from 0/15194C0.
2022-04-19 13:33:53.065 CEST [25057] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16384_7088276686057484707" LOGICAL 0/1519648 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:53.074 CEST [25142] LOG: received replication command:
CREATE_REPLICATION_SLOT "pg_16406_sync_16394_7088276686057484707" LOGICAL
pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:53.074 CEST [25142] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16394_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:53.272 CEST [25057] LOG: logical decoding found consistent
point at 0/15194C0
2022-04-19 13:33:53.272 CEST [25057] DETAIL: Logical decoding will begin using
saved snapshot.
2022-04-19 13:33:53.272 CEST [25057] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16384_7088276686057484707" LOGICAL 0/1519648 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:53.273 CEST [25057] LOG: received replication command:
DROP_REPLICATION_SLOT pg_16406_sync_16384_7088276686057484707 WAIT
2022-04-19 13:33:53.273 CEST [25057] STATEMENT: DROP_REPLICATION_SLOT
pg_16406_sync_16384_7088276686057484707 WAIT
2022-04-19 13:33:54.040 CEST [25144] LOG: received replication command:
CREATE_REPLICATION_SLOT "pg_16406_sync_16387_7088276686057484707" LOGICAL
pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:54.040 CEST [25144] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16387_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:54.225 CEST [25142] LOG: logical decoding found consistent
point at 0/1519A60
2022-04-19 13:33:54.225 CEST [25142] DETAIL: There are no running transactions.
2022-04-19 13:33:54.225 CEST [25142] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16394_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:54.635 CEST [25142] LOG: received replication command:
START_REPLICATION SLOT "pg_16406_sync_16394_7088276686057484707" LOGICAL
0/1519A98 (proto_version '3', publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:54.635 CEST [25142] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16394_7088276686057484707" LOGICAL 0/1519A98 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:54.635 CEST [25142] LOG: starting logical decoding for slot
"pg_16406_sync_16394_7088276686057484707"
2022-04-19 13:33:54.635 CEST [25142] DETAIL: Streaming transactions committing
after 0/1519A98, reading WAL from 0/1519A60.
2022-04-19 13:33:54.635 CEST [25142] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16394_7088276686057484707" LOGICAL 0/1519A98 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:54.635 CEST [25142] LOG: logical decoding found consistent
point at 0/1519A60
2022-04-19 13:33:54.635 CEST [25142] DETAIL: There are no running transactions.
2022-04-19 13:33:54.635 CEST [25142] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16394_7088276686057484707" LOGICAL 0/1519A98 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:54.635 CEST [25142] LOG: received replication command:
DROP_REPLICATION_SLOT pg_16406_sync_16394_7088276686057484707 WAIT
2022-04-19 13:33:54.635 CEST [25142] STATEMENT: DROP_REPLICATION_SLOT
pg_16406_sync_16394_7088276686057484707 WAIT
2022-04-19 13:33:55.113 CEST [25144] LOG: logical decoding found consistent
point at 0/1519A98
2022-04-19 13:33:55.113 CEST [25144] DETAIL: There are no running transactions.
2022-04-19 13:33:55.113 CEST [25144] STATEMENT: CREATE_REPLICATION_SLOT
"pg_16406_sync_16387_7088276686057484707" LOGICAL pgoutput (SNAPSHOT 'use')
2022-04-19 13:33:55.536 CEST [25144] LOG: received replication command:
START_REPLICATION SLOT "pg_16406_sync_16387_7088276686057484707" LOGICAL
0/1519AD0 (proto_version '3', publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:55.536 CEST [25144] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16387_7088276686057484707" LOGICAL 0/1519AD0 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:55.537 CEST [25144] LOG: starting logical decoding for slot
"pg_16406_sync_16387_7088276686057484707"
2022-04-19 13:33:55.537 CEST [25144] DETAIL: Streaming transactions committing
after 0/1519AD0, reading WAL from 0/1519A98.
2022-04-19 13:33:55.537 CEST [25144] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16387_7088276686057484707" LOGICAL 0/1519AD0 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:55.537 CEST [25144] LOG: logical decoding found consistent
point at 0/1519A98
2022-04-19 13:33:55.537 CEST [25144] DETAIL: There are no running transactions.
2022-04-19 13:33:55.537 CEST [25144] STATEMENT: START_REPLICATION SLOT
"pg_16406_sync_16387_7088276686057484707" LOGICAL 0/1519AD0 (proto_version '3',
publication_names '"pub_6526_to_6527"')
2022-04-19 13:33:55.537 CEST [25144] LOG: received replication command:
DROP_REPLICATION_SLOT pg_16406_sync_16387_7088276686057484707 WAIT
2022-04-19 13:33:55.537 CEST [25144] STATEMENT: DROP_REPLICATION_SLOT
pg_16406_sync_16387_7088276686057484707 WAIT
2022-04-19 13:34:03.123 CEST [25062] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_history" has finished
2022-04-19 13:34:03.123 CEST [25062] CONTEXT: processing remote data for
replication origin "pg_16411_16390" during "COMMIT" in transaction 1467
finished at 0/46E87F8
2022-04-19 13:34:03.138 CEST [25154] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_tellers" has started
2022-04-19 13:34:08.705 CEST [25068] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_accounts" has finished
2022-04-19 13:34:08.705 CEST [25068] CONTEXT: processing remote data for
replication origin "pg_16411_16384" during "COMMIT" in transaction 1868
finished at 0/472DB30
2022-04-19 13:34:08.720 CEST [25161] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_branches" has started
TRAP: FailedAssertion("tabstat->trans == trans", File: "pgstat_relation.c",
Line: 508, PID: 25058)
postgres: logical replication worker for subscription 16411
(ExceptionalCondition+0xb9)[0xb3baad]
postgres: logical replication worker for subscription 16411
(AtEOXact_PgStat_Relations+0xa0)[0x9bf5dc]
postgres: logical replication worker for subscription 16411
(AtEOXact_PgStat+0x93)[0x9c4107]
postgres: logical replication worker for subscription 16411 [0x583764]
postgres: logical replication worker for subscription 16411
(CommitTransactionCommand+0x8c)[0x584354]
postgres: logical replication worker for subscription 16411 [0x90b34e]
postgres: logical replication worker for subscription 16411 [0x90a287]
postgres: logical replication worker for subscription 16411 [0x90ce3a]
postgres: logical replication worker for subscription 16411 [0x90d41c]
postgres: logical replication worker for subscription 16411 [0x90e974]
postgres: logical replication worker for subscription 16411
(ApplyWorkerMain+0x75b)[0x90f156]
postgres: logical replication worker for subscription 16411
(StartBackgroundWorker+0x1f3)[0x8c7623]
postgres: logical replication worker for subscription 16411 [0x8d1557]
postgres: logical replication worker for subscription 16411 [0x8d1903]
postgres: logical replication worker for subscription 16411 [0x8d09ba]
/lib64/libc.so.6[0x357d632570]
/lib64/libc.so.6(__select+0x13)[0x357d6e1683]
postgres: logical replication worker for subscription 16411 [0x8cc6c1]
postgres: logical replication worker for subscription 16411
(PostmasterMain+0x122e)[0x8cc0aa]
postgres: logical replication worker for subscription 16411 [0x7c9256]
/lib64/libc.so.6(__libc_start_main+0x100)[0x357d61ed20]
postgres: logical replication worker for subscription 16411 [0x48a109]
2022-04-19 13:34:18.834 CEST [24981] LOG: background worker "logical
replication worker" (PID 25058) was terminated by signal 6: Aborted
2022-04-19 13:34:18.834 CEST [24981] LOG: terminating any other active server
processes
2022-04-19 13:34:18.839 CEST [24981] LOG: all server processes terminated;
reinitializing
2022-04-19 13:34:19.032 CEST [25203] FATAL: the database system is in recovery
mode
2022-04-19 13:34:19.032 CEST [25200] LOG: database system was interrupted;
last known up at 2022-04-19 13:33:43 CEST
2022-04-19 13:34:19.717 CEST [25200] LOG: database system was not properly
shut down; automatic recovery in progress
2022-04-19 13:34:19.845 CEST [25200] LOG: redo starts at 0/14E7F00
2022-04-19 13:34:19.903 CEST [25249] FATAL: the database system is not yet
accepting connections
2022-04-19 13:34:19.903 CEST [25249] DETAIL: Consistent recovery state has not
been yet reached.
2022-04-19 13:34:19.910 CEST [25255] FATAL: the database system is not yet
accepting connections
2022-04-19 13:34:19.910 CEST [25255] DETAIL: Consistent recovery state has not
been yet reached.
2022-04-19 13:34:19.918 CEST [25261] FATAL: the database system is not yet
accepting connections
2022-04-19 13:34:19.918 CEST [25261] DETAIL: Consistent recovery state has not
been yet reached.
2022-04-19 13:34:19.928 CEST [25267] FATAL: the database system is not yet
accepting connections
2022-04-19 13:34:19.928 CEST [25267] DETAIL: Consistent recovery state has not
been yet reached.
2022-04-19 13:34:20.875 CEST [25200] LOG: invalid record length at 0/57ADEB8:
wanted 24, got 0
2022-04-19 13:34:20.875 CEST [25200] LOG: redo done at 0/57ADE80 system usage:
CPU: user: 0.90 s, system: 0.07 s, elapsed: 1.02 s
2022-04-19 13:34:20.967 CEST [25201] LOG: checkpoint starting: end-of-recovery
immediate wait
2022-04-19 13:34:22.183 CEST [25201] LOG: checkpoint complete: wrote 7759
buffers (47.4%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.181 s,
sync=0.874 s, total=1.252 s; sync files=61, longest=0.846 s, average=0.015 s;
distance=68376 kB, estimate=68376 kB
2022-04-19 13:34:22.228 CEST [24981] LOG: database system is ready to accept
connections
2022-04-19 13:34:22.287 CEST [25322] LOG: logical replication apply worker for
subscription "pub_6526_from_6525" has started
2022-04-19 13:34:22.297 CEST [25324] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_tellers" has started
2022-04-19 13:34:22.308 CEST [25326] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_branches" has started
2022-04-19 13:34:23.879 CEST [25324] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_tellers" has finished
2022-04-19 13:34:23.967 CEST [25326] LOG: logical replication table
synchronization worker for subscription "pub_6526_from_6525", table
"pgbench_branches" has finished
2022-04-19 13:34:24.053 CEST [25366] LOG: received replication command:
IDENTIFY_SYSTEM
2022-04-19 13:34:24.053 CEST [25366] STATEMENT: IDENTIFY_SYSTEM
2022-04-19 13:34:24.053 CEST [25366] LOG: received replication command:
START_REPLICATION SLOT "pub_6527_from_6526" LOGICAL 0/5607A50 (proto_version
'3', publication_names '"pub_6526_to_6527"')
2022-04-19 13:34:24.053 CEST [25366] STATEMENT: START_REPLICATION SLOT
"pub_6527_from_6526" LOGICAL 0/5607A50 (proto_version '3', publication_names
'"pub_6526_to_6527"')
2022-04-19 13:34:24.054 CEST [25366] LOG: starting logical decoding for slot
"pub_6527_from_6526"
2022-04-19 13:34:24.054 CEST [25366] DETAIL: Streaming transactions committing
after 0/1519AD0, reading WAL from 0/1519AD0.
2022-04-19 13:34:24.054 CEST [25366] STATEMENT: START_REPLICATION SLOT
"pub_6527_from_6526" LOGICAL 0/5607A50 (proto_version '3', publication_names
'"pub_6526_to_6527"')
2022-04-19 13:34:24.054 CEST [25366] LOG: logical decoding found consistent
point at 0/1519AD0
2022-04-19 13:34:24.054 CEST [25366] DETAIL: There are no running transactions.
2022-04-19 13:34:24.054 CEST [25366] STATEMENT: START_REPLICATION SLOT
"pub_6527_from_6526" LOGICAL 0/5607A50 (proto_version '3', publication_names
'"pub_6526_to_6527"')
2022-04-19 13:34:25.664 CEST [24981] LOG: received fast shutdown request
2022-04-19 13:34:25.719 CEST [24981] LOG: aborting any active transactions
2022-04-19 13:34:25.719 CEST [25322] FATAL: terminating logical replication
worker due to administrator command
2022-04-19 13:34:25.722 CEST [24981] LOG: background worker "logical
replication launcher" (PID 25321) exited with exit code 1
2022-04-19 13:34:25.724 CEST [25412] FATAL: terminating connection due to
administrator command
2022-04-19 13:34:25.724 CEST [25412] STATEMENT: select * from pgbench_accounts
order by aid;
2022-04-19 13:34:25.725 CEST [24981] LOG: background worker "logical
replication worker" (PID 25322) exited with exit code 1
2022-04-19 13:34:25.746 CEST [25201] LOG: shutting down
2022-04-19 13:34:25.827 CEST [25201] LOG: checkpoint starting: shutdown
immediate
2022-04-19 13:34:29.304 CEST [25201] LOG: checkpoint complete: wrote 4828
buffers (29.5%); 0 WAL file(s) added, 0 removed, 0 recycled; write=1.980 s,
sync=1.161 s, total=3.558 s; sync files=21, longest=0.306 s, average=0.056 s;
distance=4202 kB, estimate=61958 kB
2022-04-19 13:34:29.331 CEST [24981] LOG: database system is shut down
