one of my PostgreSQL 11 servers was throwing a strange error and refused to correctly initiate streaming replication after a basebackup:
FATAL: terminating walreceiver process due to administrator command
I tried enabling the highest log verbosity (Debug5), but that didn't provide more insight as to why it kept dying:
2021-07-29 15:33:30.862 UTC [39315] DEBUG: postgres: PostmasterMain: initial environment dump:
2021-07-29 15:33:30.862 UTC [39315] DEBUG: -----------------------------------------
2021-07-29 15:33:30.862 UTC [39315] DEBUG: PG_OOM_ADJUST_FILE=/proc/self/oom_score_adj
2021-07-29 15:33:30.862 UTC [39315] DEBUG: PG_GRANDPARENT_PID=39310
2021-07-29 15:33:30.862 UTC [39315] DEBUG: PGLOCALEDIR=/usr/share/locale
2021-07-29 15:33:30.862 UTC [39315] DEBUG: PGSYSCONFDIR=/etc/postgresql-common
2021-07-29 15:33:30.862 UTC [39315] DEBUG: LANG=en_US.UTF-8
2021-07-29 15:33:30.862 UTC [39315] DEBUG: PWD=/
2021-07-29 15:33:30.863 UTC [39315] DEBUG: PGDATA=/var/lib/postgresql/11/replica
2021-07-29 15:33:30.863 UTC [39315] DEBUG: LC_COLLATE=en_US.UTF-8
2021-07-29 15:33:30.863 UTC [39315] DEBUG: LC_CTYPE=en_US.UTF-8
2021-07-29 15:33:30.863 UTC [39315] DEBUG: LC_MESSAGES=en_US.UTF-8
2021-07-29 15:33:30.863 UTC [39315] DEBUG: LC_MONETARY=C
2021-07-29 15:33:30.863 UTC [39315] DEBUG: LC_NUMERIC=C
2021-07-29 15:33:30.863 UTC [39315] DEBUG: LC_TIME=C
2021-07-29 15:33:30.863 UTC [39315] DEBUG: -----------------------------------------
2021-07-29 15:33:30.867 UTC [39315] DEBUG: registering background worker "logical replication launcher"
2021-07-29 15:33:30.868 UTC [39315] LOG: listening on IPv6 address "::1", port 5433
2021-07-29 15:33:30.868 UTC [39315] LOG: listening on IPv4 address "127.0.0.1", port 5433
2021-07-29 15:33:30.868 UTC [39315] LOG: listening on IPv4 address "*snip*", port 5433
2021-07-29 15:33:30.868 UTC [39315] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433"
2021-07-29 15:33:30.869 UTC [39315] DEBUG: invoking IpcMemoryCreate(size=156459008)
2021-07-29 15:33:30.869 UTC [39315] DEBUG: mmap(157286400) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
2021-07-29 15:33:30.885 UTC [39315] DEBUG: SlruScanDirectory invoking callback on pg_notify/0000
2021-07-29 15:33:30.885 UTC [39315] DEBUG: removing file "pg_notify/0000"
2021-07-29 15:33:30.885 UTC [39315] DEBUG: dynamic shared memory system will support 588 segments
2021-07-29 15:33:30.885 UTC [39315] DEBUG: created dynamic shared memory control segment 1597797971 (14128 bytes)
2021-07-29 15:33:30.887 UTC [39315] DEBUG: max_safe_fds = 982, usable_fds = 1000, already_open = 8
2021-07-29 15:33:30.889 UTC [39316] LOG: database system was shut down in recovery at 2021-07-29 15:31:23 UTC
2021-07-29 15:33:30.890 UTC [39316] DEBUG: standby_mode = 'on'
2021-07-29 15:33:30.890 UTC [39316] DEBUG: primary_conninfo = '*snip*'
2021-07-29 15:33:30.890 UTC [39316] DEBUG: recovery_target_timeline = latest
2021-07-29 15:33:30.890 UTC [39316] LOG: entering standby mode
2021-07-29 15:33:30.890 UTC [39316] LOG: invalid resource manager ID 172 at 235/450000D0
2021-07-29 15:33:30.890 UTC [39316] DEBUG: switched WAL source from archive to stream after failure
2021-07-29 15:33:30.891 UTC [39317] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/11/lib/libpqwalreceiver"
2021-07-29 15:33:30.905 UTC [39317] DEBUG: find_in_dynamic_libpath: trying "/usr/lib/postgresql/11/lib/libpqwalreceiver.so"
2021-07-29 15:33:30.918 UTC [39317] LOG: started streaming WAL from primary at 235/45000000 on timeline 1
2021-07-29 15:33:30.920 UTC [39317] DEBUG: sendtime 2021-07-29 15:33:30.917704+00 receipttime 2021-07-29 15:33:30.920718+00 replication apply delay (N/A) transfer latency 3 ms
2021-07-29 15:33:30.920 UTC [39317] DEBUG: sending write 235/45020000 flush 0/0 apply 0/0
2021-07-29 15:33:30.921 UTC [39317] DEBUG: sending write 235/45020000 flush 235/45020000 apply 0/0
2021-07-29 15:33:30.921 UTC [39316] LOG: invalid resource manager ID 172 at 235/450000D0
2021-07-29 15:33:30.921 UTC [39317] FATAL: terminating walreceiver process due to administrator command
2021-07-29 15:33:30.921 UTC [39317] DEBUG: shmem_exit(1): 1 before_shmem_exit callbacks to make
2021-07-29 15:33:30.921 UTC [39317] DEBUG: shmem_exit(1): 5 on_shmem_exit callbacks to make
2021-07-29 15:33:30.921 UTC [39317] DEBUG: proc_exit(1): 2 callbacks to make
2021-07-29 15:33:30.921 UTC [39317] DEBUG: exit(1)
2021-07-29 15:33:30.921 UTC [39316] DEBUG: switched WAL source from stream to archive after failure
The only concerning were the LOG level messages like
LOG: invalid resource manager ID 172 at 235/450000D0
It turned out, however, that these are just Postgres' way of saying "Reached an end of valid WAL structures" and LOG level messages can be safely ignored.
I tried removing existing WAL logs (from datadir/pg_wal/
), thinking maybe a file corruption was at play, the server still would not initiate replication. The only solution was to make a completely new basebackup.
My question - Is the terminating xyz process due to administrator command
a default message Postgres gives when one of its processes dies in a non-standard way?
Would there be further debugging options in cases like this? Not even the highest logging verbosity provided much useful information.