During promotion, new master tries to archive same segment twice

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
shuttingdown
 

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:
Connectionrefused
 

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.