Обсуждение: BUG #16788: Postmaster started then shmem_exit(1) is called. database system is starting up
BUG #16788: Postmaster started then shmem_exit(1) is called. database system is starting up
От
PG Bug reporting form
Дата:
The following bug has been logged on the website: Bug reference: 16788 Logged by: Lily Zhang Email address: bjzhangl@cn.ibm.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]@[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@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]@[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@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]@[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@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]@[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]@[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@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@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@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@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@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@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@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@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@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]@[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@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@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@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@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@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@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@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@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]@[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]@[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@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@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@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@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@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@postgres DEBUG: exit(1) "