Fix pg_rewind behavior with Postgres v16+ (#2944)

The error message format was changed in
https://github.com/postgres/postgres/commit/4ac30ba4f29d4b586b131404b0d514f16501272a, what caused `pg_rewind` being called by Patroni even when it was not necessary.

patroni/postgresql/rewind.py

@@ -101,12 +101,26 @@ class Rewind(object):
             return 'not accessible or not healty'
 
     def _get_checkpoint_end(self, timeline: int, lsn: int) -> int:
-        """The checkpoint record size in WAL depends on postgres major version and platform (memory alignment).
+        """Get the end of checkpoint record from WAL.
-        Hence, the only reliable way to figure out where it ends, read the record from file with the help of pg_waldump
-        and parse the output. We are trying to read two records, and expect that it will fail to read the second one:
-        `pg_waldump: fatal: error in WAL record at 0/182E220: invalid record length at 0/182E298: wanted 24, got 0`
-        The error message contains information about LSN of the next record, which is exactly where checkpoint ends."""
 
+        .. note::
+            The checkpoint record size in WAL depends on postgres major version and platform (memory alignment).
+            Hence, the only reliable way to figure out where it ends, is to read the record from file with the
+            help of ``pg_waldump`` and parse the output.
+
+            We are trying to read two records, and expect that it will fail to read the second record with message:
+
+                fatal: error in WAL record at 0/182E220: invalid record length at 0/182E298: wanted 24, got 0; or
+
+                fatal: error in WAL record at 0/182E220: invalid record length at 0/182E298: expected at least 24, got 0
+
+            The error message contains information about LSN of the next record, which is exactly where checkpoint ends.
+
+        :param timeline: the checkpoint *timeline* from ``pg_controldata``.
+        :param lsn: the checkpoint *location* as :class:`int` from ``pg_controldata``.
+
+        :returns: the end of checkpoint record as :class:`int` or ``0`` if failed to parse ``pg_waldump`` output.
+        """
         lsn8 = format_lsn(lsn, True)
         lsn_str = format_lsn(lsn)
         out, err = self._postgresql.waldump(timeline, lsn_str, 2)
@@ -117,12 +131,17 @@ class Rewind(object):
 
             if len(out) == 1 and len(err) == 1 and ', lsn: {0}, prev '.format(lsn8) in out[0] and pattern in err[0]:
                 i = err[0].find(pattern) + len(pattern)
-                j = err[0].find(": wanted ", i)
+                # Message format depends on the major version:
-                if j > -1:
+                # * expected at least -- starting from v16
-                    try:
+                # * wanted -- before v16
-                        return parse_lsn(err[0][i:j])
+                # We will simply check all possible combinations.
-                    except Exception as e:
+                for pattern in (': expected at least ', ': wanted '):
-                        logger.error('Failed to parse lsn %s: %r', err[0][i:j], e)
+                    j = err[0].find(pattern, i)
+                    if j > -1:
+                        try:
+                            return parse_lsn(err[0][i:j])
+                        except Exception as e:
+                            logger.error('Failed to parse lsn %s: %r', err[0][i:j], e)
             logger.error('Failed to parse pg_%sdump output', self._postgresql.wal_name)
             logger.error(' stdout=%s', '\n'.join(out))
             logger.error(' stderr=%s', '\n'.join(err))

tests/test_rewind.py

@@ -180,6 +180,16 @@ class TestRewind(BaseTestPostgresql):
             self.r.trigger_check_diverged_lsn()
             mock_get_local_timeline_lsn.return_value = (False, 2, 67197377)
             self.assertTrue(self.r.rewind_or_reinitialize_needed_and_possible(self.leader))
+
+            mock_popen.return_value.communicate.return_value = (
+                b'0, lsn: 0/040159C1, prev 0/\n',
+                b'pg_waldump: fatal: error in WAL record at 0/40159C1: invalid record '
+                b'length at 0/402DD98: expected at least 24, got 0\n'
+            )
+            self.r.reset_state()
+            self.r.trigger_check_diverged_lsn()
+            self.assertFalse(self.r.rewind_or_reinitialize_needed_and_possible(self.leader))
+
             self.r.reset_state()
             self.r.trigger_check_diverged_lsn()
             mock_popen.side_effect = Exception