Streaming replication - invalid resource manager ID

I’m a bit stuck with a few LOG messages. The one in the subject disturbs me
the most.

(FreeBSD 11.2, PostgreSQL 10.6)

When I restart the hot standby, sometimes I see

2019-02-13 21:17:31 CET LOG: redo starts at 0/488A2748
2019-02-13 21:17:31 CET LOG: invalid record length at 0/488A2780: wanted
24, got 0
2019-02-13 21:17:31 CET LOG: database system is ready to accept read only
connections
2019-02-13 21:17:31 CET LOG: started streaming WAL from primary at
0/48000000 on timeline 1

I try to believe it is harmless. I found two emails in the archive telling
that this is harmless, but they were from many years ago. Is it really
harmless? (Without PANIC, etc). The main reason I believe it’s harmless is
that I often see it.

The one I see less often is: "invalid resource manager ID"

The last time I encountered it when I made the standby the new master, and
the original master the new standby. Steps:

1. Stop the master (service postgresql stop)

Log from the original master:
2019-02-13 20:19:12 CET LOG: received fast shutdown request
2019-02-13 20:19:12 CET LOG: aborting any active transactions
2019-02-13 20:19:12 CET LOG: worker process: logical replication launcher
(PID 17828) exited with exit code 1
2019-02-13 20:19:12 CET LOG: shutting down
2019-02-13 20:19:16 CET LOG: database system is shut down

Log from the new master (it was the standby):
2019-02-13 20:19:16 CET LOG: replication terminated by primary server
2019-02-13 20:19:16 CET DETAIL: End of WAL reached on timeline 3 at
8F42/645FBD00.
2019-02-13 20:19:16 CET FATAL: could not send end-of-streaming message to
primary: no COPY in progress
2019-02-13 20:19:16 CET LOG: invalid record length at 8F42/645FBD00:
wanted 24, got 0
2019-02-13 20:19:16 CET FATAL: could not connect to the primary server:
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.

2. pg_ctl -D the_whole_galaxy promote

Log from the new master (was slave):
2019-02-13 20:19:31 CET LOG: received promote request
2019-02-13 20:19:31 CET FATAL: terminating walreceiver process due to
administrator command
2019-02-13 20:19:31 CET LOG: redo done at 8F42/645FBC90
2019-02-13 20:19:31 CET LOG: last completed transaction was at log time
2019-02-13 20:19:12.354569+01
2019-02-13 20:19:31 CET LOG: selected new timeline ID: 4
2019-02-13 20:19:31 CET LOG: archive recovery complete
2019-02-13 20:19:31 CET LOG: database system is ready to accept
connections

3. Start the old master after putting there a recovery.conf to make it the
new standby

Log from the original master:
2019-02-13 20:23:22 CET LOG: database system was shut down at 2019-02-13
20:19:16 CET
2019-02-13 20:23:22 CET LOG: entering standby mode
2019-02-13 20:23:22 CET LOG: consistent recovery state reached at
8F42/645FBD00
2019-02-13 20:23:22 CET LOG: invalid record length at 8F42/645FBD00:
wanted 24, got 0
2019-02-13 20:23:22 CET LOG: database system is ready to accept read only
connections
2019-02-13 20:23:22 CET LOG: fetching timeline history file for timeline
4 from primary server
2019-02-13 20:23:22 CET LOG: started streaming WAL from primary at
8F42/64000000 on timeline 3
2019-02-13 20:23:22 CET LOG: replication terminated by primary server
2019-02-13 20:23:22 CET DETAIL: End of WAL reached on timeline 3 at
8F42/645FBD00.
2019-02-13 20:23:22 CET LOG: new target timeline is 4
2019-02-13 20:23:22 CET LOG: restarted WAL streaming at 8F42/64000000 on
timeline 4
2019-02-13 20:23:22 CET LOG: redo starts at 8F42/645FBD00

So far so good (except for the invalid record length, but it’s only LOG).

4. A bit later I shutdown the original master server itself (which runs the
now-standby PG cluster) due to VM configuration. It takes a few minutes. I
start the server.

Log from the original master:
2019-02-13 20:33:39 CET LOG: received fast shutdown request
2019-02-13 20:33:39 CET LOG: aborting any active transactions
2019-02-13 20:33:39 CET FATAL: terminating walreceiver process due to
administrator command
2019-02-13 20:33:39 CET LOG: shutting down
2019-02-13 20:33:40 CET LOG: database system is shut down
2019-02-13 20:38:45 CET LOG: database system was shut down in recovery at
2019-02-13 20:33:39 CET
2019-02-13 20:38:45 CET LOG: entering standby mode
2019-02-13 20:38:45 CET LOG: redo starts at 8F42/E7DC51B8
2019-02-13 20:38:47 CET WARNING: could not open directory
"base/26083437": No such file or directory
2019-02-13 20:38:47 CET CONTEXT: WAL redo at 8F42/EDE3E720 for
Database/DROP: dir 26083437/1663
2019-02-13 20:38:47 CET WARNING: some useless files may be left behind in
old database directory "base/26083437"
2019-02-13 20:38:47 CET CONTEXT: WAL redo at 8F42/EDE3E720 for
Database/DROP: dir 26083437/1663

I don’t like these because they are WARNINGS. I believe they might be there
because sometimes I check the replication with a createdb something (on
master); psql -l (on standby); dropdb something (on master). Although I do
it when they both are running.

2019-02-13 20:39:06 CET LOG: consistent recovery state reached at
8F43/38B80FB0
2019-02-13 20:39:06 CET LOG: database system is ready to accept read only
connections
2019-02-13 20:39:06 CET LOG: started streaming WAL from primary at
8F43/38000000 on timeline 4

Except for the let’s-hope-not-harmful WARNING, it looks okay. There was no
new log on the new master.

5. A bit later I restart the new master cluster as I set up things.

Log from the new master (was slave):
2019-02-13 20:42:04 CET LOG: received fast shutdown request
2019-02-13 20:42:04 CET LOG: aborting any active transactions
2019-02-13 20:42:04 CET FATAL: terminating autovacuum process due to
administrator command
2019-02-13 20:42:04 CET LOG: worker process: logical replication launcher
(PID 2455) exited with exit code 1
2019-02-13 20:42:05 CET LOG: shutting down
2019-02-13 20:42:08 CET LOG: database system is shut down
2019-02-13 20:42:08 CET LOG: database system was shut down at 2019-02-13
20:42:08 CET
2019-02-13 20:42:08 CET LOG: database system is ready to accept
connections

Here it comes:

Log from the original master:
2019-02-13 20:42:08 CET LOG: replication terminated by primary server
2019-02-13 20:42:08 CET DETAIL: End of WAL reached on timeline 4 at
8F43/AB4E6438.
2019-02-13 20:42:08 CET FATAL: could not send end-of-streaming message to
primary: no COPY in progress
2019-02-13 20:42:08 CET LOG: invalid resource manager ID 118 at
8F43/AB4E6438
2019-02-13 20:42:08 CET FATAL: could not connect to the primary server:
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
2019-02-13 20:42:13 CET LOG: started streaming WAL from primary at
8F43/AB000000 on timeline 4

Although it’s also only a LOG, I find it scary because when I googled for
it, I found it only in terrible context usually followed by a PANIC.

For example:
https://www.postgresql.org/message-id/0A3270AA-31DC-4BA7-BC74-11BCAF38F80E%40gmail.com

Also, I could reproduce the "invalid record length at ..." messages on a
local machine (vacuum + update + restarting the master and the standby),
but I could not reproduce the "invalid resource manager ID" message no
matter how hard I tried.

(Although the local machine has PostgreSQL 11.1)

Besides, it doesn’t go away. Late, I restarted the master one more time.

Log from the new master (was slave):
2019-02-13 21:35:55 CET LOG: database system was shut down at 2019-02-13
21:35:54 CET
2019-02-13 21:35:55 CET LOG: database system is ready to accept
connections

Log from the original master:
2019-02-13 21:35:54 CET LOG: replication terminated by primary server
2019-02-13 21:35:54 CET DETAIL: End of WAL reached on timeline 4 at
8F46/93705AF0.
2019-02-13 21:35:54 CET FATAL: could not send end-of-streaming message to
primary: no COPY in progress
2019-02-13 21:35:54 CET LOG: invalid resource manager ID 31 at
8F46/93705AF0
2019-02-13 21:35:54 CET FATAL: could not connect to the primary server:
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
2019-02-13 21:35:59 CET LOG: started streaming WAL from primary at
8F46/93000000 on timeline 4

Since I’m not someone who says: "It’s okay, it works", I ended up running
pg_basebackups after each promote due to these messages. Which means, I
deleted the data directory on the old master after each promote. And the
fact that the basebackup make these log messages disappear tells me that it
might have been the right choice to do it. I mean, if there is no problem
at all, why do I see these messages after I connect the old master to the
new master, and why aren’t they there after a basebackup? What’s the
difference?

There are two master-standby pairs I am upgrading now. I had to re-create
the disks in each machine (for other reasons). Since I wanted the websites
to stay online, I went to the upgrade the standby => promote the standby =>
upgrade the oiriginal master => promote the original master line. I had
maybe 3 seconds downtime twice.

I believe I could have done it with zero pg_basebackup, but I already did
it four or five times due to these messages, and I am not yet finished.
During the long basebackup, I feel less safe, and my apps can’t read the
standby.

I have been using PostgreSQL for ages. I use and love almost every feature
of it.

The log messages, on the other hand, are more esoteric to me than the
original Maya calendar was which sank with Atlantis. Maybe I’m not the only
user, who, without reading the source code, would expect something like
this:

LOG: Everything is all right. I did what you asked, and I talk about it.
NOTICE: Please fix your pg_hba.conf
WARNING: If I weren’t rock solid ACID, you would be in a trouble now. Don’t
do this again.
ERROR: The query was wrong but your data is safe.
FATAL: Do you have a backup?
PANIC: Do you have a legal insurance?

But the reality in my understanding is something like this:

LOG: Your data is either corrupted or not.
WARNING: I think something is wrong. (But it’s not)
ERROR: Your data is either corrupted or not.
FATAL: I’m the least harmful kind of log message in PostgreSQL. Just give
me two seconds. Your data is safe.

I can see what the different kind of log messages communicate:
https://www.postgresql.org/docs/11/runtime-config-logging.html

However, when I look at the log, in 100 of 100 times, I am more interested
in whether my data is safe or not than whether only the current command was
aborted or the whole session.

If someone please explains it what the invalid resource manager ID message
means, they will have my eternal thanks.

M.