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