025_stuck_on_old_timeline_standby.log

application/octet-stream

Filename: 025_stuck_on_old_timeline_standby.log
Type: application/octet-stream
Part: 4
Message: Re: Race condition in recovery?
2021-06-03 16:16:51.950 EDT [47753] LOG:  starting PostgreSQL 14beta1 on x86_64-apple-darwin19.6.0, compiled by clang version 5.0.2 (tags/RELEASE_502/final), 64-bit
2021-06-03 16:16:51.951 EDT [47753] LOG:  listening on Unix socket "/var/folders/jh/925hn4t97mb_sby_1s37k7dc0000gs/T/sdk3QMgbuK/.s.PGSQL.50637"
2021-06-03 16:16:51.956 EDT [47754] LOG:  database system was interrupted; last known up at 2021-06-03 16:16:51 EDT
2021-06-03 16:16:51.956 EDT [47754] LOG:  entering standby mode
2021-06-03 16:16:51.960 EDT [47754] LOG:  redo starts at 0/2000028
2021-06-03 16:16:51.960 EDT [47754] LOG:  consistent recovery state reached at 0/2000100
2021-06-03 16:16:51.960 EDT [47753] LOG:  database system is ready to accept read only connections
2021-06-03 16:16:51.967 EDT [47758] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl LOG:  received replication command: SHOW data_directory_mode
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl STATEMENT:  SHOW data_directory_mode
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl LOG:  received replication command: SHOW wal_segment_size
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl STATEMENT:  SHOW wal_segment_size
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl LOG:  received replication command: IDENTIFY_SYSTEM
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl STATEMENT:  IDENTIFY_SYSTEM
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl LOG:  received replication command: BASE_BACKUP LABEL 'pg_basebackup base backup' PROGRESS  FAST     MANIFEST 'yes' 
2021-06-03 16:16:52.042 EDT [47761] 025_stuck_on_old_timeline.pl STATEMENT:  BASE_BACKUP LABEL 'pg_basebackup base backup' PROGRESS  FAST     MANIFEST 'yes' 
2021-06-03 16:16:52.876 EDT [47764] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT pg_promote()
2021-06-03 16:16:52.878 EDT [47754] LOG:  received promote request
2021-06-03 16:16:52.879 EDT [47758] FATAL:  terminating walreceiver process due to administrator command
2021-06-03 16:16:52.879 EDT [47754] LOG:  redo done at 0/2000100 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.91 s
2021-06-03 16:16:52.881 EDT [47754] LOG:  selected new timeline ID: 2
2021-06-03 16:16:52.961 EDT [47754] LOG:  archive recovery complete
2021-06-03 16:16:52.968 EDT [47753] LOG:  database system is ready to accept connections
2021-06-03 16:16:53.127 EDT [47772] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT pg_walfile_name(pg_current_wal_lsn());
2021-06-03 16:16:53.144 EDT [47774] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT pg_switch_wal()
2021-06-03 16:16:53.171 EDT [47777] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT '000000020000000000000003' <= last_archived_wal FROM pg_stat_archiver;
2021-06-03 16:16:53.310 EDT [47781] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT '000000020000000000000003' <= last_archived_wal FROM pg_stat_archiver;
2021-06-03 16:16:53.434 EDT [47783] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT '000000020000000000000003' <= last_archived_wal FROM pg_stat_archiver;
2021-06-03 16:16:53.558 EDT [47785] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT '000000020000000000000003' <= last_archived_wal FROM pg_stat_archiver;
2021-06-03 16:16:53.682 EDT [47787] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT '000000020000000000000003' <= last_archived_wal FROM pg_stat_archiver;
2021-06-03 16:16:53.816 EDT [47797] cascade LOG:  received replication command: IDENTIFY_SYSTEM
2021-06-03 16:16:53.816 EDT [47797] cascade STATEMENT:  IDENTIFY_SYSTEM
2021-06-03 16:16:53.816 EDT [47797] cascade LOG:  received replication command: START_REPLICATION 0/2000000 TIMELINE 1
2021-06-03 16:16:53.816 EDT [47797] cascade STATEMENT:  START_REPLICATION 0/2000000 TIMELINE 1
2021-06-03 16:16:53.983 EDT [47797] cascade LOG:  received replication command: IDENTIFY_SYSTEM
2021-06-03 16:16:53.983 EDT [47797] cascade STATEMENT:  IDENTIFY_SYSTEM
2021-06-03 16:16:53.983 EDT [47797] cascade LOG:  received replication command: START_REPLICATION 0/3000000 TIMELINE 2
2021-06-03 16:16:53.983 EDT [47797] cascade STATEMENT:  START_REPLICATION 0/3000000 TIMELINE 2
2021-06-03 16:16:54.042 EDT [47807] 025_stuck_on_old_timeline.pl LOG:  statement: CREATE TABLE tab_int AS SELECT 1 AS a
2021-06-03 16:16:54.135 EDT [47809] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT pg_last_wal_replay_lsn()
2021-06-03 16:16:54.154 EDT [47811] 025_stuck_on_old_timeline.pl LOG:  statement: SELECT '0/3000000' <= replay_lsn AND state = 'streaming' FROM pg_catalog.pg_stat_replication WHERE application_name = 'cascade';
2021-06-03 16:16:54.313 EDT [47753] LOG:  received immediate shutdown request
2021-06-03 16:16:54.319 EDT [47753] LOG:  database system is shut down