Dear Experts, Here is my latest issue with replication: I have 3 systems, X, Y and Z. Initially X is replicated to Y and Y is replicated to Z; in each case the replication involves log-shipping using archive_command and restore_command (via a 4th system called "backup") and then streaming. The plan is to shut down X and to promote Y to be the new master. I shut down X, and as expected Y complains that it con no longer connect to it: 2018-08-15 15:10:58.785 UTC [617] LOG: replication terminated by primary server 2018-08-15 15:10:58.785 UTC [617] DETAIL: End of WAL reached on timeline 1 at 7/E9000098. 2018-08-15 15:10:58.785 UTC [617] FATAL: could not send end-of-streaming message to primary: no COPY in progress scp: backup/postgresql/archivedir/0000000100000007000000E9: No such file or directory 2018-08-15 15:10:59.928 UTC [354] LOG: invalid resource manager ID 22 at 7/E9000098 2018-08-15 15:11:00.092 UTC [5856] FATAL: could not connect to the primary server: FATAL: the database system is shutting down Note that in the middle of that, after streaming has failed it tries to fetch the next WAL segment, E9, from the backup; this fails because this segment doesn't exist. Then I pg_ctl promote on Y: 2018-08-15 15:12:11.888 UTC [354] LOG: received promote request 2018-08-15 15:12:11.888 UTC [354] LOG: redo done at 7/E9000028 2018-08-15 15:12:11.888 UTC [354] LOG: last completed transaction was at log time 2018-08-15 14:45:05.961153+00 scp: backup/postgresql/archivedir/0000000100000007000000E9: No such file or directory scp: backup/postgresql/archivedir/00000002.history: No such file or directory 2018-08-15 15:12:13.316 UTC [354] LOG: selected new timeline ID: 2 2018-08-15 15:12:13.368 UTC [354] FATAL: could not open file "recovery.conf": Permission denied So in the process of exiting recovery mode it tries to rename recovery.conf to recovery.done, but it fails to do so because my recovery.conf was owned by root, not user postgres. Oooops. Perhaps it would be appropriate to check for that when it initially reads recovery.conf? Anyway, I fix the permissions and restart it. It starts in recovery mode and cannot connect to the master, as expected. 2018-08-15 15:16:58.061 UTC [6036] LOG: restored log file "0000000100000007000000E8" from archive 2018-08-15 15:16:58.108 UTC [6036] LOG: redo starts at 7/E8678300 2018-08-15 15:16:58.731 UTC [6087] LOG: archive command failed with exit code 1 2018-08-15 15:16:58.731 UTC [6087] DETAIL: The failed archive command was: ssh backup test ! -f backup/postgresql/Y/0000000100000007000000E8 && scp pg_xlog/0000000100000007000000E8 backup:backup/postgresql/Y/0000000100000007000000E8 scp: backup/postgresql/archivedir/0000000100000007000000E9: No such file or directory 2018-08-15 15:16:58.823 UTC [6036] LOG: consistent recovery state reached at 7/E9000098 2018-08-15 15:16:58.823 UTC [6036] LOG: invalid resource manager ID 22 at 7/E9000098 2018-08-15 15:16:58.824 UTC [6035] LOG: database system is ready to accept read only connections 2018-08-15 15:16:58.855 UTC [6094] FATAL: could not connect to the primary server: could not connect to server: Connection refused But note that in the middle of that log fragment it has tried to write WAL segment E8 to its (output) WAL archive, which is used to replicate to the downstream system Z, and it has found that that segment already exists there. The file that's already there has the same checksum as the E8 file in the pg_xlog directory. Somehow it has forgotten that it has already archived that segment. It keeps retrying this archive command. I try again to promote it: 2018-08-15 15:17:14.424 UTC [6036] LOG: received promote request 2018-08-15 15:17:14.424 UTC [6036] LOG: redo done at 7/E9000028 scp: backup/postgresql/archivedir/0000000100000007000000E9: No such file or directory scp: backup/postgresql/archivedir/00000002.history: No such file or directory 2018-08-15 15:17:15.832 UTC [6036] LOG: selected new timeline ID: 2 2018-08-15 15:17:15.884 UTC [6036] LOG: archive recovery complete scp: backup/postgresql/archivedir/00000001.history: No such file or directory 2018-08-15 15:17:16.612 UTC [6036] LOG: MultiXact member wraparound protections are now enabled 2018-08-15 15:17:16.614 UTC [6035] LOG: database system is ready to accept connections I can now connect to the db and do read/write operations, but it continues to try and fail to re-write segment E8 to its archive. Eventually I manually delete E8 from the archive; it then succeeds at writing it with the same content as before and seems to continue to function normally. Questions: - Can all of this be blamed on the failure of the first attempt to promote due to the wrong permissions on recovery.conf? - Should my archive_command detect the case where it is asked to write the same file again with the same contents, and report success in that case? - Is this a bug? Thanks, Phil.
