[BUG] False indication in pg_stat_replication.sync_state

Hello. My colleague found that pg_stat_replication.sync_state
shows false state for some condition.

This prevents Pacemaker from completing fail-over that could
safely be done.

The point is in walsender.c, pg_stat_get_wal_senders() below, (as
of REL9_2_1)

1555: if (walsnd->pid != 0)
1556: {
1557: /*
1558: * Treat a standby such as a pg_basebackup background process
1559: * which always returns an invalid flush location, as an
1560: * asynchronous standby.
1561: */
! 1562: sync_priority[i] = XLogRecPtrIsInvalid(walsnd->flush) ?
1563: 0 : walsnd->sync_standby_priority;

Here, XLogRecPtrIsInvalid(walsnd->flush) is defined as
(walsnd->flush.xrecoff == 0) which becomes true as usual at every
WAL 'file's (not segments) boundary. xrecoff == 0 is certainly
invalid for the start point of WAL *RECORD*, but should be
considered valid in replication stream. This check was introduced
at 9.2.0 and the version up between 9.1.4 and 9.1.5.

| DEBUG: write 4/0 flush 3/FEFFEC68 apply 3/FEFFEC68
| DEBUG: write 4/0 flush 4/0 apply 3/FEFFEC68
| DEBUG: HOGE: flush = 3/FEFFEC68 sync_priority[0] = 1
| DEBUG: write 4/111C0 flush 4/0 apply 3/FEFFECC0
!| DEBUG: HOGE: flush = 4/0 sync_priority[0] = 0

This value zero of sync_priority[0] makes sync_status 'async'
errorneously and confuses Pacemaker.

# The log line marked with 'HOGE' above printed by applying the
# patch at the bottom of this message and invoking 'select
# sync_state from pg_stat_replication' periodically. To increase
# the chance to see the symptom, sleep 1 second for 'file'
# boundaries :-)

The Heikki's recent(?) commit
0ab9d1c4b31622e9176472b4276f3e9831e3d6ba which changes the format
of XLogRecPtr from logid:xrecoff struct to 64 bit linear address
would fix the false indication. But I suppose this patch won't be
applied to existing 9.1.x and 9.2.x because of the modification
onto streaming protocol.

As far as I see the patch, it would'nt change the meaning of
XLogRecPtr to change XLogRecPtrIsInvalid from (xrecoff == 0) to
(xrecoff == 0 && xlogid == 0). But this change affects rather
wide portion where handling WAL nevertheless what is needed here
is only to stop the false indication.

On the other hand, pg_basebackup seems return 0/0 as flush and
apply positions so it seems enough only to add xlogid == 0 into
the condition. The patch attached for REL9_2_1 does this and
yields the result following.

| DEBUG: write 2/FEFFFD48 flush 2/FEFFFD48 apply 2/FEFF7AB0
| DEBUG: write 3/0 flush 2/FEFFFD48 apply 2/FEFF7E88
| DEBUG: write 3/0 flush 3/0 apply 2/FEFFFD48
| DEBUG: HOGE: flush = 2/FEFFFD48 sync_priority[0] = 1
| DEBUG: write 3/E338 flush 3/0 apply 2/FEFFFF80
!| DEBUG: HOGE: flush = 3/0 sync_priority[0] = 1

I think this patch should be applied for 9.2.2 and 9.1.7.

regards,

--
Kyotaro Horiguchi
NTT Open Source Software Center

============================================================
===== The patch for this test.
============================================================
diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 064ddd5..19f79d1 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -618,6 +618,10 @@ ProcessStandbyReplyMessage(void)
reply.flush.xlogid, reply.flush.xrecoff,
reply.apply.xlogid, reply.apply.xrecoff);

+ if (reply.write.xrecoff == 0 ||
+ reply.flush.xrecoff == 0)
+ sleep(1);
+
/*
* Update shared state for this WalSender process based on reply data from
* standby.
@@ -1561,7 +1565,10 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
*/
sync_priority[i] = XLogRecPtrIsInvalid(walsnd->flush) ?
0 : walsnd->sync_standby_priority;
-
+ elog(DEBUG1, "HOGE: flush = %X/%X sync_priority[%d] = %d",
+ walsnd->flush.xlogid, walsnd->flush.xrecoff,
+ i, sync_priority[i]);
+
if (walsnd->state == WALSNDSTATE_STREAMING &&
walsnd->sync_standby_priority > 0 &&
(priority == 0 ||