BUG #16788: Postmaster started then shmem_exit(1) is called. database system is starting up

The following bug has been logged on the website:

Bug reference: 16788
Logged by: Lily Zhang
Email address: bjzhangl(at)cn(dot)ibm(dot)com
PostgreSQL version: 10.9
Operating system: Ubuntu 18.04
Description:

We have a postgresql database cluster with 3 node, one is primary, the other
2 are secondary. The cluster is managed by patroni. The 3 databases are in
respective containers. When we update one secondary container image, the
database in this container can not start. It reports "database system is
starting up". We tried to delete the container and recover it from primary,
the same error is reported.
This is the db log. The log contains operations to delete the container and
recover it from primary and then update the container with an image that
using "-d 5" to start db server.
"
Dec 15 07:33:36 postgresql-28137 postgres[210]: [1] 2020-12-15 07:33:36.732
UTC [210-1] LOG: pgaudit extension initialized
Dec 15 07:33:36 postgresql-28137 postgres[210]: [2] 2020-12-15 07:33:36.737
UTC [210-2] LOG: listening on IPv4 address "0.0.0.0", port 5432
Dec 15 07:33:36 postgresql-28137 postgres[210]: [3] 2020-12-15 07:33:36.738
UTC [210-3] LOG: listening on Unix socket "./.s.PGSQL.5432"
Dec 15 07:33:36 postgresql-28137 postgres[210]: [4] 2020-12-15 07:33:36.757
UTC [210-4] LOG: ending log output to stderr#0122020-12-15 07:33:36.757 UTC
[210-5] HINT: Future log output will go to log destination "syslog".
Dec 15 07:33:36 postgresql-28137 postgres[212]: [5] 2020-12-15 07:33:36.767
UTC [212-1] LOG: database system was interrupted; last known up at
2020-12-15 07:33:07 UTC
Dec 15 07:33:36 postgresql-28137 postgres[212]: [6] 2020-12-15 07:33:36.878
UTC [212-2] LOG: entering standby mode
Dec 15 07:33:36 postgresql-28137 postgres[212]: [7] 2020-12-15 07:33:36.896
UTC [212-3] LOG: redo starts at 3/EC000028
Dec 15 07:33:36 postgresql-28137 postgres[212]: [8] 2020-12-15 07:33:36.901
UTC [212-4] LOG: consistent recovery state reached at 3/EC0431E8
Dec 15 07:33:36 postgresql-28137 postgres[215]: [5] 2020-12-15 07:33:36.937
UTC [215-1] LOG: started streaming WAL from primary at 3/ED000000 on
timeline 9
Dec 15 07:33:37 postgresql-28137 postgres[219]: [5] 2020-12-15 07:33:37.656
UTC [219-1] [unknown](at)[unknown] LOG: connection received: host=127.0.0.1
port=52526
Dec 15 07:33:37 postgresql-28137 postgres[219]: [6] 2020-12-15 07:33:37.670
UTC [219-2] postgres(at)postgres FATAL: the database system is starting up
(repeated connection messages here)
Dec 15 07:37:46 postgresql-28137 postgres[1261]: [5] 2020-12-15 07:37:46.589
UTC [1261-1] [unknown](at)[unknown] LOG: connection received: host=127.0.0.1
port=53754
Dec 15 07:37:46 postgresql-28137 postgres[1261]: [6] 2020-12-15 07:37:46.600
UTC [1261-2] postgres(at)postgres FATAL: the database system is starting up
Dec 15 07:37:46 postgresql-28137 postgres[1262]: [5] 2020-12-15 07:37:46.601
UTC [1262-1] [unknown](at)[unknown] LOG: connection received: host=127.0.0.1
port=53756
Dec 15 07:37:46 postgresql-28137 postgres[1262]: [6] 2020-12-15 07:37:46.601
UTC [1262-2] postgres(at)postgres FATAL: the database system is starting up
Dec 15 07:38:11 postgresql-28137 postgres[144]: [1] 2020-12-15 07:38:11.532
UTC [144-1] DEBUG: postgres: PostmasterMain: initial environment dump:
Dec 15 07:38:11 postgresql-28137 postgres[144]: [2] 2020-12-15 07:38:11.534
UTC [144-2] DEBUG: -----------------------------------------
Dec 15 07:38:11 postgresql-28137 postgres[144]: [3] 2020-12-15 07:38:11.534
UTC [144-3] DEBUG:
#011PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
Dec 15 07:38:11 postgresql-28137 postgres[144]: [4] 2020-12-15 07:38:11.534
UTC [144-4] DEBUG: #011PGLOCALEDIR=/usr/share/locale
Dec 15 07:38:11 postgresql-28137 postgres[144]: [5] 2020-12-15 07:38:11.534
UTC [144-5] DEBUG: #011PGSYSCONFDIR=/etc/postgresql-common
Dec 15 07:38:11 postgresql-28137 postgres[144]: [6] 2020-12-15 07:38:11.534
UTC [144-6] DEBUG: #011LC_COLLATE=C
Dec 15 07:38:11 postgresql-28137 postgres[144]: [7] 2020-12-15 07:38:11.534
UTC [144-7] DEBUG: #011LC_CTYPE=C
Dec 15 07:38:11 postgresql-28137 postgres[144]: [8] 2020-12-15 07:38:11.534
UTC [144-8] DEBUG: #011LC_MESSAGES=C
Dec 15 07:38:11 postgresql-28137 postgres[144]: [9] 2020-12-15 07:38:11.534
UTC [144-9] DEBUG: #011LC_MONETARY=C
Dec 15 07:38:11 postgresql-28137 postgres[144]: [10] 2020-12-15 07:38:11.534
UTC [144-10] DEBUG: #011LC_NUMERIC=C
Dec 15 07:38:11 postgresql-28137 postgres[144]: [11] 2020-12-15 07:38:11.534
UTC [144-11] DEBUG: #011LC_TIME=C
Dec 15 07:38:11 postgresql-28137 postgres[144]: [12] 2020-12-15 07:38:11.534
UTC [144-12] DEBUG: -----------------------------------------
Dec 15 07:38:11 postgresql-28137 postgres[144]: [13] 2020-12-15 07:38:11.552
UTC [144-13] DEBUG: registering background worker "logical replication
launcher"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [14] 2020-12-15 07:38:11.552
UTC [144-14] DEBUG: find_in_dynamic_libpath: trying
"/usr/lib/postgresql/10/lib/pgaudit"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [15] 2020-12-15 07:38:11.554
UTC [144-15] DEBUG: find_in_dynamic_libpath: trying
"/usr/lib/postgresql/10/lib/pgaudit.so"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [16] 2020-12-15 07:38:11.557
UTC [144-16] LOG: pgaudit extension initialized
Dec 15 07:38:11 postgresql-28137 postgres[144]: [17] 2020-12-15 07:38:11.557
UTC [144-17] DEBUG: loaded library "pgaudit"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [18] 2020-12-15 07:38:11.557
UTC [144-18] DEBUG: find_in_dynamic_libpath: trying
"/usr/lib/postgresql/10/lib/pg_stat_statements"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [19] 2020-12-15 07:38:11.557
UTC [144-19] DEBUG: find_in_dynamic_libpath: trying
"/usr/lib/postgresql/10/lib/pg_stat_statements.so"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [20] 2020-12-15 07:38:11.560
UTC [144-20] DEBUG: loaded library "pg_stat_statements"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [21] 2020-12-15 07:38:11.560
UTC [144-21] LOG: listening on IPv4 address "0.0.0.0", port 5432
Dec 15 07:38:11 postgresql-28137 postgres[144]: [22] 2020-12-15 07:38:11.561
UTC [144-22] LOG: listening on Unix socket "./.s.PGSQL.5432"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [23] 2020-12-15 07:38:11.566
UTC [144-23] DEBUG: invoking IpcMemoryCreate(size=150364160)
Dec 15 07:38:11 postgresql-28137 postgres[144]: [24] 2020-12-15 07:38:11.566
UTC [144-24] DEBUG: mmap(150994944) with MAP_HUGETLB failed, huge pages
disabled: Cannot allocate memory
Dec 15 07:38:11 postgresql-28137 postgres[144]: [25] 2020-12-15 07:38:11.575
UTC [144-25] DEBUG: SlruScanDirectory invoking callback on pg_notify/0000
Dec 15 07:38:11 postgresql-28137 postgres[144]: [26] 2020-12-15 07:38:11.575
UTC [144-26] DEBUG: removing file "pg_notify/0000"
Dec 15 07:38:11 postgresql-28137 postgres[144]: [27] 2020-12-15 07:38:11.576
UTC [144-27] DEBUG: dynamic shared memory system will support 318
segments
Dec 15 07:38:11 postgresql-28137 postgres[144]: [28] 2020-12-15 07:38:11.576
UTC [144-28] DEBUG: created dynamic shared memory control segment
1716390047 (7648 bytes)
Dec 15 07:38:11 postgresql-28137 postgres[144]: [29] 2020-12-15 07:38:11.578
UTC [144-29] DEBUG: max_safe_fds = 982, usable_fds = 1000, already_open =
8
Dec 15 07:38:11 postgresql-28137 postgres[144]: [30] 2020-12-15 07:38:11.579
UTC [144-30] LOG: ending log output to stderr#0122020-12-15 07:38:11.579
UTC [144-31] HINT: Future log output will go to log destination "syslog".
Dec 15 07:38:11 postgresql-28137 postgres[146]: [31] 2020-12-15 07:38:11.590
UTC [146-1] LOG: database system was shut down in recovery at 2020-12-15
07:37:51 UTC
Dec 15 07:38:11 postgresql-28137 postgres[146]: [32] 2020-12-15 07:38:11.590
UTC [146-2] DEBUG: standby_mode = 'on'
Dec 15 07:38:11 postgresql-28137 postgres[146]: [33] 2020-12-15 07:38:11.590
UTC [146-3] DEBUG: recovery_target_timeline = latest
Dec 15 07:38:11 postgresql-28137 postgres[146]: [34] 2020-12-15 07:38:11.590
UTC [146-4] DEBUG: primary_conninfo = 'user=replicator password 'xxxxxx'
Dec 15 07:38:11 postgresql-28137 postgres[146]: [35] 2020-12-15 07:38:11.590
UTC [146-5] DEBUG: primary_slot_name =
'308b271b_d04a_428c_a695_465ffbb2ed02_v7w0m9ey'
Dec 15 07:38:11 postgresql-28137 postgres[146]: [36] 2020-12-15 07:38:11.590
UTC [146-6] LOG: entering standby mode
Dec 15 07:38:11 postgresql-28137 postgres[146]: [37] 2020-12-15 07:38:11.590
UTC [146-7] DEBUG: checkpoint record is at 3/EC0000A0
Dec 15 07:38:11 postgresql-28137 postgres[146]: [38] 2020-12-15 07:38:11.590
UTC [146-8] DEBUG: redo record is at 3/EC000028; shutdown FALSE
Dec 15 07:38:11 postgresql-28137 postgres[146]: [39] 2020-12-15 07:38:11.590
UTC [146-9] DEBUG: next transaction ID: 0:4739127; next OID: 88543
Dec 15 07:38:11 postgresql-28137 postgres[146]: [40] 2020-12-15 07:38:11.590
UTC [146-10] DEBUG: next MultiXactId: 19; next MultiXactOffset: 37
Dec 15 07:38:11 postgresql-28137 postgres[146]: [41] 2020-12-15 07:38:11.590
UTC [146-11] DEBUG: oldest unfrozen transaction ID: 549, in database 1
Dec 15 07:38:11 postgresql-28137 postgres[146]: [42] 2020-12-15 07:38:11.590
UTC [146-12] DEBUG: oldest MultiXactId: 1, in database 1
Dec 15 07:38:11 postgresql-28137 postgres[146]: [43] 2020-12-15 07:38:11.590
UTC [146-13] DEBUG: commit timestamp Xid oldest/newest: 0/0
Dec 15 07:38:11 postgresql-28137 postgres[146]: [44] 2020-12-15 07:38:11.590
UTC [146-14] DEBUG: transaction ID wrap limit is 2147484196, limited by
database with OID 1
Dec 15 07:38:11 postgresql-28137 postgres[146]: [45] 2020-12-15 07:38:11.590
UTC [146-15] DEBUG: MultiXactId wrap limit is 2147483648, limited by
database with OID 1
Dec 15 07:38:11 postgresql-28137 postgres[146]: [46] 2020-12-15 07:38:11.590
UTC [146-16] DEBUG: starting up replication slots
Dec 15 07:38:11 postgresql-28137 postgres[146]: [47] 2020-12-15 07:38:11.590
UTC [146-17] DEBUG: starting up replication origin progress state
Dec 15 07:38:11 postgresql-28137 postgres[146]: [48] 2020-12-15 07:38:11.591
UTC [146-18] DEBUG: resetting unlogged relations: cleanup 1 init 0
Dec 15 07:38:11 postgresql-28137 postgres[146]: [49] 2020-12-15 07:38:11.592
UTC [146-19] DEBUG: initializing for hot standby
Dec 15 07:38:11 postgresql-28137 postgres[146]: [50] 2020-12-15 07:38:11.592
UTC [146-20] DEBUG: my backend ID is 1
Dec 15 07:38:11 postgresql-28137 postgres[146]: [51] 2020-12-15 07:38:11.606
UTC [146-21] LOG: redo starts at 3/EC000028
Dec 15 07:38:11 postgresql-28137 postgres[146]: [52] 2020-12-15 07:38:11.606
UTC [146-22] DEBUG: prune KnownAssignedXids to 1422751#0122020-12-15
07:38:11.606 UTC [146-23] CONTEXT: WAL redo at 3/EC000028 for
Standby/RUNNING_XACTS: nextXid 4739127 latestCompletedXid 4739125
oldestRunningXid 1422751; 16 xacts: 2716862 2721890 4665244 2495592 2289138
2288820 2287653 1422751 4280517 2288510 2287620 3297674 1757103 4739023
3320989 2259670; subxid ovf
Dec 15 07:38:11 postgresql-28137 postgres[147]: [31] 2020-12-15 07:38:11.606
UTC [147-1] DEBUG: checkpointer updated shared memory configuration
values
Dec 15 07:38:11 postgresql-28137 postgres[146]: [53] 2020-12-15 07:38:11.608
UTC [146-24] DEBUG: 15 KnownAssignedXids (num=15 tail=0 head=15)
[0]=1422751 [1]=1757103 [2]=2259670 [3]=2287620 [4]=2287653 [5]=2288510
[6]=2288820 [7]=2289138 [8]=2495592 [9]=2716862 [10]=2721890 [11]=3297674
[12]=3320989 [13]=4280517 [14]=4665244 #0122020-12-15 07:38:11.608 UTC
[146-25] CONTEXT: WAL redo at 3/EC000028 for Standby/RUNNING_XACTS: nextXid
4739127 latestCompletedXid 4739125 oldestRunningXid 1422751; 16 xacts:
2716862 2721890 4665244 2495592 2289138 2288820 2287653 1422751 4280517
2288510 2287620 3297674 1757103 4739023 3320989 2259670; subxid ovf
Dec 15 07:38:11 postgresql-28137 postgres[146]: [54] 2020-12-15 07:38:11.608
UTC [146-26] DEBUG: 15 KnownAssignedXids (num=15 tail=0 head=15)
[0]=1422751 [1]=1757103 [2]=2259670 [3]=2287620 [4]=2287653 [5]=2288510
[6]=2288820 [7]=2289138 [8]=2495592 [9]=2716862 [10]=2721890 [11]=3297674
[12]=3320989 [13]=4280517 [14]=4665244 #0122020-12-15 07:38:11.608 UTC
[146-27] CONTEXT: WAL redo at 3/EC000028 for Standby/RUNNING_XACTS: nextXid
4739127 latestCompletedXid 4739125 oldestRunningXid 1422751; 16 xacts:
2716862 2721890 4665244 2495592 2289138 2288820 2287653 1422751 4280517
2288510 2287620 3297674 1757103 4739023 3320989 2259670; subxid ovf
Dec 15 07:38:11 postgresql-28137 postgres[146]: [55] 2020-12-15 07:38:11.608
UTC [146-28] DEBUG: recovery snapshot waiting for non-overflowed snapshot
or until oldest active xid on standby is at least 4739126 (now
1422751)#0122020-12-15 07:38:11.608 UTC [146-29] CONTEXT: WAL redo at
3/EC000028 for Standby/RUNNING_XACTS: nextXid 4739127 latestCompletedXid
4739125 oldestRunningXid 1422751; 16 xacts: 2716862 2721890 4665244 2495592
2289138 2288820 2287653 1422751 4280517 2288510 2287620 3297674 1757103
4739023 3320989 2259670; subxid ovf
Dec 15 07:38:11 postgresql-28137 postgres[146]: [56] 2020-12-15 07:38:11.610
UTC [146-30] DEBUG: record known xact 4739127 latestObservedXid
4739126#0122020-12-15 07:38:11.610 UTC [146-31] CONTEXT: WAL redo at
3/EC000178 for Heap/INSERT: off 6
Dec 15 07:38:11 postgresql-28137 postgres[146]: [57] 2020-12-15 07:38:11.610
UTC [146-32] DEBUG: record known xact 4739127 latestObservedXid
4739127#0122020-12-15 07
(repeated wal redo messages here)
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1083] 2020-12-15
07:38:11.626 UTC [146-2084] DEBUG: remove KnownAssignedXid
4739226#0122020-12-15 07:38:11.626 UTC [146-2085] CONTEXT: WAL redo at
3/ED05DDD8 for Transaction/ASSIGNMENT: xtop 1422751: subxacts: 4739188
4739189 4739190 4739191 4739193 4739194 4739195 4739196 4739197 4739198
4739200 4739201 4739202 4739203 4739204 4739207 4739209 4739210 4739211
4739212 4739213 4739214 4739215 4739217 4739218 4739219 4739220 4739221
4739222 4739224 4739225 4739226 4739227 4739228 4739230 4739233 4739234
4739235 4739236 4739237 4739239 4739240 4739241 4739242 4739243 4739244
4739246 4739247 4739248 4739249 4739250 4739251 4739253 4739254 4739255
4739258 4739259 4739260 4739262 4739263 4739264 4739265 4739266 4739267
(repeated such messages here)
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1811] 2020-12-15
07:38:11.641 UTC [146-3540] DEBUG: record known xact 4739367
latestObservedXid 4739367#0122020-12-15 07:38:11.641 UTC [146-3541] CONTEXT:
WAL redo at 3/ED081EA0 for Heap/HOT_UPDATE: off 32 xmax 4739367 ; new off
33 xmax 0
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1812] 2020-12-15
07:38:11.641 UTC [146-3542] DEBUG: record known xact 4739361
latestObservedXid 4739367#0122020-12-15 07:38:11.641 UTC [146-3543] CONTEXT:
WAL redo at 3/ED081EF0 for Heap/LOCK: off 5: xid 4739361: flags 0 LOCK_ONLY
EXCL_LOCK
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1813] 2020-12-15
07:38:11.641 UTC [146-3544] DEBUG: record known xact 4739361
latestObservedXid 4739367#0122020-12-15 07:38:11.641 UTC [146-3545] CONTEXT:
WAL redo at 3/ED081F28 for Heap/UPDATE: off 5 xmax 4739361 ; new off 11
xmax 0
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1814] 2020-12-15
07:38:11.641 UTC [146-3546] LOG: consistent recovery state reached at
3/ED082088
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1815] 2020-12-15
07:38:11.641 UTC [146-3547] LOG: invalid record length at 3/ED082088:
wanted 24, got 0
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1816] 2020-12-15
07:38:11.641 UTC [146-3548] DEBUG: switched WAL source from archive to
stream after failure
Dec 15 07:38:11 postgresql-28137 postgres[149]: [31] 2020-12-15 07:38:11.641
UTC [149-1] DEBUG: find_in_dynamic_libpath: trying
"/usr/lib/postgresql/10/lib/libpqwalreceiver"
Dec 15 07:38:11 postgresql-28137 postgres[149]: [32] 2020-12-15 07:38:11.641
UTC [149-2] DEBUG: find_in_dynamic_libpath: trying
"/usr/lib/postgresql/10/lib/libpqwalreceiver.so"
Dec 15 07:38:11 postgresql-28137 postgres[149]: [33] 2020-12-15 07:38:11.675
UTC [149-3] LOG: started streaming WAL from primary at 3/ED000000 on
timeline 9
Dec 15 07:38:11 postgresql-28137 postgres[149]: [34] 2020-12-15 07:38:11.680
UTC [149-4] DEBUG: sendtime 2020-12-15 07:38:11.671141+00 receipttime
2020-12-15 07:38:11.680126+00 replication apply delay (N/A) transfer latency
8 ms
Dec 15 07:38:11 postgresql-28137 postgres[149]: [35] 2020-12-15 07:38:11.680
UTC [149-5] DEBUG: sending write 3/ED020000 flush 3/ED082088 apply
3/ED082088
Dec 15 07:38:11 postgresql-28137 postgres[149]: [36] 2020-12-15 07:38:11.683
UTC [149-6] DEBUG: sendtime 2020-12-15 07:38:11.673223+00 receipttime
2020-12-15 07:38:11.683943+00 replication apply delay (N/A) transfer latency
10 ms
Dec 15 07:38:11 postgresql-28137 postgres[149]: [37] 2020-12-15 07:38:11.683
UTC [149-7] DEBUG: sending write 3/ED040000 flush 3/ED082088 apply
3/ED082088
Dec 15 07:38:11 postgresql-28137 postgres[149]: [38] 2020-12-15 07:38:11.687
UTC [149-8] DEBUG: sendtime 2020-12-15 07:38:11.676085+00 receipttime
2020-12-15 07:38:11.687108+00 replication apply delay (N/A) transfer latency
11 ms
Dec 15 07:38:11 postgresql-28137 postgres[149]: [39] 2020-12-15 07:38:11.687
UTC [149-9] DEBUG: sending write 3/ED060000 flush 3/ED082088 apply
3/ED082088
Dec 15 07:38:11 postgresql-28137 postgres[149]: [40] 2020-12-15 07:38:11.690
UTC [149-10] DEBUG: sendtime 2020-12-15 07:38:11.678189+00 receipttime
2020-12-15 07:38:11.69011+00 replication apply delay (N/A) transfer latency
11 ms
Dec 15 07:38:11 postgresql-28137 postgres[149]: [41] 2020-12-15 07:38:11.690
UTC [149-11] DEBUG: sending write 3/ED080000 flush 3/ED082088 apply
3/ED082088
Dec 15 07:38:11 postgresql-28137 postgres[149]: [42] 2020-12-15 07:38:11.691
UTC [149-12] DEBUG: sendtime 2020-12-15 07:38:11.680332+00 receipttime
2020-12-15 07:38:11.691337+00 replication apply delay (N/A) transfer latency
11 ms
Dec 15 07:38:11 postgresql-28137 postgres[149]: [43] 2020-12-15 07:38:11.691
UTC [149-13] DEBUG: sending write 3/ED08F8F8 flush 3/ED082088 apply
3/ED082088
Dec 15 07:38:11 postgresql-28137 postgres[149]: [44] 2020-12-15 07:38:11.693
UTC [149-14] DEBUG: sending write 3/ED08F8F8 flush 3/ED08F8F8 apply
3/ED082088
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1817] 2020-12-15
07:38:11.693 UTC [146-3549] DEBUG: record known xact 4739361
latestObservedXid 4739367#0122020-12-15 07:38:11.693 UTC [146-3550] CONTEXT:
WAL redo at 3/ED082088 for Btree/INSERT_LEAF: off 41
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1818] 2020-12-15
07:38:11.693 UTC [146-3551] DEBUG: record known xact 4739361
latestObservedXid 4739367#0122020-12-15 07:38:11.693 UTC [146-3552] CONTEXT:
WAL redo at 3/ED0820E0 for Heap/LOCK: off 6: xid 4739361: flags 0 LOCK_ONLY
EXCL_LOCK
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1935] 2020-12-15
07:38:11.695 UTC [146-3785] DEBUG: record known xact 4739382
latestObservedXid 4739382#0122020-12-15 07:38:11.695 UTC [146-3786] CONTEXT:
WAL redo at 3/ED08F868 for Btree/INSERT_LEAF: off 125
Dec 15 07:38:11 postgresql-28137 postgres[146]: [1936] 2020-12-15
07:38:11.695 UTC [146-3787] DEBUG: record known xact 4739382
latestObservedXid 4739382#0122020-12-15 07:38:11.695 UTC [146-3788] CONTEXT:
WAL redo at 3/ED08F8A8 for Heap/HOT_UPDATE: off 4 xmax 4739382 ; new off 5
xmax 0
Dec 15 07:38:11 postgresql-28137 postgres[149]: [45] 2020-12-15 07:38:11.695
UTC [149-15] DEBUG: sending write 3/ED08F8F8 flush 3/ED08F8F8 apply
3/ED08F8F8
Dec 15 07:38:12 postgresql-28137 postgres[149]: [46] 2020-12-15 07:38:12.332
UTC [149-16] DEBUG: sendtime 2020-12-15 07:38:12.327462+00 receipttime
2020-12-15 07:38:12.332214+00 replication apply delay 0 ms transfer latency
4 ms
Dec 15 07:38:12 postgresql-28137 postgres[149]: [47] 2020-12-15 07:38:12.332
UTC [149-17] DEBUG: sending write 3/ED091A10 flush 3/ED08F8F8 apply
3/ED08F8F8
Dec 15 07:38:12 postgresql-28137 postgres[149]: [48] 2020-12-15 07:38:12.332
UTC [149-18] DEBUG: sending write 3/ED091A10 flush 3/ED091A10 apply
3/ED08F8F8
Dec 15 07:38:12 postgresql-28137 postgres[146]: [1937] 2020-12-15
07:38:12.332 UTC [146-3789] DEBUG: record known xact 4739383
latestObservedXid 4739382#0122020-12-15 07:38:12.332 UTC [146-3790] CONTEXT:
WAL redo at 3/ED08F9E8 for Heap/HOT_UPDATE: off 1 xmax 4739383 ; new off 2
xmax 0
Dec 15 07:38:12 postgresql-28137 postgres[146]: [1938] 2020-12-15
07:38:12.332 UTC [146-3791] DEBUG: record known xact 4739383
latestObservedXid 4739383#0122020-12-15 07:38:12.332 UTC [146-3792] CONTEXT:
WAL redo at 3/ED08FA38 for XLOG/FPI_FOR_HINT:
Dec 15 07:38:12 postgresql-28137 postgres[149]: [49] 2020-12-15 07:38:12.332
UTC [149-19] DEBUG: sending write 3/ED091A10 flush 3/ED091A10 apply
3/ED091A10
Dec 15 07:38:12 postgresql-28137 postgres[144]: [31] 2020-12-15 07:38:12.414
UTC [144-32] DEBUG: forked new backend, pid=152 socket=11
Dec 15 07:38:12 postgresql-28137 postgres[152]: [31] 2020-12-15 07:38:12.414
UTC [152-1] [unknown](at)[unknown] LOG: connection received: host=127.0.0.1
port=33092
Dec 15 07:38:12 postgresql-28137 postgres[152]: [32] 2020-12-15 07:38:12.427
UTC [152-2] [unknown](at)[unknown] DEBUG: SSL connection from "(anonymous)"
Dec 15 07:38:12 postgresql-28137 postgres[152]: [33] 2020-12-15 07:38:12.427
UTC [152-3] root(at)root FATAL: the database system is starting up
Dec 15 07:38:12 postgresql-28137 postgres[152]: [34] 2020-12-15 07:38:12.427
UTC [152-4] root(at)root DEBUG: shmem_exit(1): 0 before_shmem_exit callbacks
to make
Dec 15 07:38:12 postgresql-28137 postgres[152]: [35] 2020-12-15 07:38:12.427
UTC [152-5] root(at)root DEBUG: shmem_exit(1): 0 on_shmem_exit callbacks to
make
Dec 15 07:38:12 postgresql-28137 postgres[152]: [36] 2020-12-15 07:38:12.427
UTC [152-6] root(at)root DEBUG: proc_exit(1): 1 callbacks to make
Dec 15 07:38:12 postgresql-28137 postgres[152]: [37] 2020-12-15 07:38:12.427
UTC [152-7] root(at)root DEBUG: SSL: write alert (0x0100)
Dec 15 07:38:12 postgresql-28137 postgres[152]: [38] 2020-12-15 07:38:12.427
UTC [152-8] root(at)root DEBUG: exit(1)
Dec 15 07:38:12 postgresql-28137 postgres[152]: [39] 2020-12-15 07:38:12.428
UTC [152-9] root(at)root DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks
to make
Dec 15 07:38:12 postgresql-28137 postgres[152]: [40] 2020-12-15 07:38:12.428
UTC [152-10] root(at)root DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to
make
Dec 15 07:38:12 postgresql-28137 postgres[152]: [41] 2020-12-15 07:38:12.428
UTC [152-11] root(at)root DEBUG: proc_exit(-1): 0 callbacks to make
Dec 15 07:38:12 postgresql-28137 postgres[144]: [32] 2020-12-15 07:38:12.428
UTC [144-33] DEBUG: forked new backend, pid=154 socket=11
Dec 15 07:38:12 postgresql-28137 postgres[154]: [32] 2020-12-15 07:38:12.428
UTC [154-1] [unknown](at)[unknown] LOG: connection received: host=127.0.0.1
port=33094
Dec 15 07:38:12 postgresql-28137 postgres[154]: [33] 2020-12-15 07:38:12.428
UTC [154-2] root(at)root FATAL: the database system is starting up
Dec 15 07:38:12 postgresql-28137 postgres[154]: [34] 2020-12-15 07:38:12.428
UTC [154-3] root(at)root DEBUG: shmem_exit(1): 0 before_shmem_exit callbacks
to make
Dec 15 07:38:12 postgresql-28137 postgres[154]: [35] 2020-12-15 07:38:12.428
UTC [154-4] root(at)root DEBUG: shmem_exit(1): 0 on_shmem_exit callbacks to
make
Dec 15 07:38:12 postgresql-28137 postgres[154]: [36] 2020-12-15 07:38:12.428
UTC [154-5] root(at)root DEBUG: proc_exit(1): 1 callbacks to make
Dec 15 07:38:12 postgresql-28137 postgres[154]: [37] 2020-12-15 07:38:12.428
UTC [154-6] root(at)root DEBUG: exit(1)
Dec 15 07:38:12 postgresql-28137 postgres[154]: [38] 2020-12-15 07:38:12.429
UTC [154-7] root(at)root DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks
to make
Dec 15 07:38:12 postgresql-28137 postgres[154]: [39] 2020-12-15 07:38:12.429
UTC [154-8] root(at)root DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to
make
Dec 15 07:38:12 postgresql-28137 postgres[154]: [40] 2020-12-15 07:38:12.429
UTC [154-9] root(at)root DEBUG: proc_exit(-1): 0 callbacks to make
Dec 15 07:38:12 postgresql-28137 postgres[144]: [33] 2020-12-15 07:38:12.432
UTC [144-34] DEBUG: reaping dead processes
Dec 15 07:38:12 postgresql-28137 postgres[144]: [34] 2020-12-15 07:38:12.432
UTC [144-35] DEBUG: server process (PID 152) exited with exit code 1
Dec 15 07:38:12 postgresql-28137 postgres[144]: [35] 2020-12-15 07:38:12.432
UTC [144-36] DEBUG: server process (PID 154) exited with exit code 1
Dec 15 07:38:12 postgresql-28137 postgres[144]: [36] 2020-12-15 07:38:12.432
UTC [144-37] DEBUG: reaping dead processes
Dec 15 07:38:12 postgresql-28137 postgres[144]: [37] 2020-12-15 07:38:12.476
UTC [144-38] DEBUG: forked new backend, pid=155 socket=11
Dec 15 07:38:12 postgresql-28137 postgres[155]: [37] 2020-12-15 07:38:12.476
UTC [155-1] [unknown](at)[unknown] LOG: connection received: host=127.0.0.1
port=33096
Dec 15 07:38:12 postgresql-28137 postgres[155]: [38] 2020-12-15 07:38:12.491
UTC [155-2] [unknown](at)[unknown] DEBUG: SSL connection from "(anonymous)"
Dec 15 07:38:12 postgresql-28137 postgres[155]: [39] 2020-12-15 07:38:12.491
UTC [155-3] postgres(at)postgres FATAL: the database system is starting up
Dec 15 07:38:12 postgresql-28137 postgres[155]: [40] 2020-12-15 07:38:12.491
UTC [155-4] postgres(at)postgres DEBUG: shmem_exit(1): 0 before_shmem_exit
callbacks to make
Dec 15 07:38:12 postgresql-28137 postgres[155]: [41] 2020-12-15 07:38:12.491
UTC [155-5] postgres(at)postgres DEBUG: shmem_exit(1): 0 on_shmem_exit
callbacks to make
Dec 15 07:38:12 postgresql-28137 postgres[155]: [42] 2020-12-15 07:38:12.491
UTC [155-6] postgres(at)postgres DEBUG: proc_exit(1): 1 callbacks to make
Dec 15 07:38:12 postgresql-28137 postgres[155]: [43] 2020-12-15 07:38:12.491
UTC [155-7] postgres(at)postgres DEBUG: SSL: write alert (0x0100)
Dec 15 07:38:12 postgresql-28137 postgres[155]: [44] 2020-12-15 07:38:12.491
UTC [155-8] postgres(at)postgres DEBUG: exit(1)
"