Subject: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"

From: Andres Freund <[email-masked]>
Date: Tue, 22 Nov 2022 17:42:24 -0800

Hi,

My buildfarm animal grassquit just showed an odd failure [1] in REL_11_STABLE:

ok 10 - standby is in recovery
# Running: pg_ctl -D /mnt/resource/bf/build/grassquit/REL_11_STABLE/pgsql.build/src/bin/pg_ctl/tmp_check/t_003_promote_standby2_data/pgdata promote
waiting for server to promote....pg_ctl: control file appears to be corrupt
not ok 11 - pg_ctl promote of standby runs

#   Failed test 'pg_ctl promote of standby runs'
#   at /mnt/resource/bf/build/grassquit/REL_11_STABLE/pgsql.build/../pgsql/src/test/perl/TestLib.pm line 474.

I didn't find other references to this kind of failure. Nor has the error
re-occurred on grassquit.

I don't immediately see a way for this message to be hit that's not indicating
a bug somewhere. We should be updating the control file in an atomic way and
read it in an atomic way.

The failure has to be happening in wait_for_postmaster_promote(), because the
standby2 is actually successfully promoted.

Greetings,

Andres Freund

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=grassquit&dt=2022-11-22%2016%3A33%3A57

---

From: Michael Paquier <[email-masked]>
Date: Wed, 23 Nov 2022 15:12:41 +0900

> standby2 is actually successfully promoted.

That's the one under -fsanitize=address.  It really smells to me like
a bug with a race condition all over it.
--
Michael

---

From: Alvaro Herrera <[email-masked]>
Date: Wed, 23 Nov 2022 10:02:04 +0100

> #   at /mnt/resource/bf/build/grassquit/REL_11_STABLE/pgsql.build/../pgsql/src/test/perl/TestLib.pm line 474.

This triggered me on this proposal I saw yesterday
https://postgr.es/m/[email-masked]
I think trying to store more stuff in pg_control is dangerous and we
should resist it.

-- 
Álvaro Herrera         PostgreSQL Developer  —  https://www.EnterpriseDB.com/

---

From: Thomas Munro <[email-masked]>
Date: Wed, 23 Nov 2022 23:03:45 +1300

> standby2 is actually successfully promoted.

I assume this is ext4.  Presumably anything that reads the
controlfile, like pg_ctl, pg_checksums, pg_resetwal,
pg_control_system(), ... by reading without interlocking against
writes could see garbage.  I have lost track of the versions and the
thread, but I worked out at some point by experimentation that this
only started relatively recently for concurrent read() and write(),
but always happened with concurrent pread() and pwrite().  The control
file uses the non-p variants which didn't mash old/new data like
grated cheese under concurrency due to some implementation detail, but
now does.

---

From: Thomas Munro <[email-masked]>
Date: Thu, 24 Nov 2022 10:59:26 +1300

> grated cheese under concurrency due to some implementation detail, but

As for what to do about it, some ideas:

1.  Use advisory range locking.  (This would be an advisory version of
what many other filesystems do automatically, AFAIK.  Does Windows
have a thing like POSIX file locking, or need it here?)
2.  Retry after a short time on checksum failure.  The probability is
already miniscule, and becomes pretty close to 0 if we read thrice
100ms apart.
3.  Some scheme that involves renaming the file into place.  (That
might be a pain on Windows; it only works for the relmap thing because
all readers and writers are in the backend and use an LWLock to avoid
silly handle semantics.)
4.  ???

First thought is that 2 is appropriate level of complexity for this
rare and stupid problem.

---

From: Tom Lane <[email-masked]>
Date: Wed, 23 Nov 2022 17:05:03 -0500

>> grated cheese under concurrency due to some implementation detail, but

Ugh.

> First thought is that 2 is appropriate level of complexity for this

Yeah, I was thinking the same.  A variant could be "repeat until
we see the same calculated checksum twice".

			regards, tom lane

---

From: Thomas Munro <[email-masked]>
Date: Thu, 24 Nov 2022 14:02:54 +1300

> we see the same calculated checksum twice".

Hmm.  While writing a comment to explain why that's good enough, I
realised it's not really true for a standby that control file writes
are always expected to be far apart in time.  XLogFlush->
UpdateMinRecoveryPoint() could coincide badly with our N attempts for
any small N and for any nap time, which I think makes your idea better
than mine.

With some cartoon-level understanding of what's going on (to wit: I
think the kernel just pins the page but doesn't use a page-level
content lock or range lock, so what you're seeing is raw racing memcpy
calls and unsynchronised cache line effects), I guess you'd be fairly
likely to make "progress" in seeing more new data even if you didn't
sleep in between, but who knows.  So I have a 10ms sleep to make
progress very likely; given your algorithm it doesn't matter if you
didn't make all the progress, just some.  Since this is reachable from
SQL, I think we also need a CFI call so you can't get uninterruptibly
stuck here?

I wrote a stupid throw-away function to force a write.  If you have an
ext4 system to hand (xfs, zfs, apfs, ufs, others don't suffer from
this) you can do:

 do $$ begin for i in 1..100000000 do loop perform
pg_update_control_file(); end loop; end; $$;

... while you also do:

 select pg_control_system();
 \watch 0.001

... and you'll soon see:

ERROR:  calculated CRC checksum does not match value stored in file

The attached draft patch fixes it.
From 9f1856aeb56be888123702fe471d8388da66439f Mon Sep 17 00:00:00 2001
From: Thomas Munro <[email-masked]>
Date: Thu, 24 Nov 2022 00:55:03 +0000
Subject: [PATCH 1/2] XXX Dirty hack to clobber control file for testing

---
 src/backend/access/transam/xlog.c | 10 ++++++++++
 src/include/catalog/pg_proc.dat   |  8 ++++++++
 2 files changed, 18 insertions(+)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index a31fbbff78..88de05ab35 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -2502,6 +2502,16 @@ UpdateMinRecoveryPoint(XLogRecPtr lsn, bool force)
 	LWLockRelease(ControlFileLock);
 }
 
+Datum
+pg_update_control_file()
+{
+	LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
+	ControlFile->minRecoveryPoint++;		/* XXX change something to affect CRC! */
+	UpdateControlFile();
+	LWLockRelease(ControlFileLock);
+	PG_RETURN_VOID();
+}
+
 /*
  * Ensure that all XLOG data through the given position is flushed to disk.
  *
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index f15aa2dbb1..8177c1657c 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -11679,6 +11679,14 @@
   proargnames => '{pg_control_version,catalog_version_no,system_identifier,pg_control_last_modified}',
   prosrc => 'pg_control_system' },
 
+{ oid => '8888',
+  descr => 'update control file',
+  proname => 'pg_update_control_file', provolatile => 'v', prorettype => 'void',
+  proargtypes => '', proallargtypes => '',
+  proargmodes => '{}',
+  proargnames => '{}',
+  prosrc => 'pg_update_control_file' },
+
 { oid => '3442',
   descr => 'pg_controldata checkpoint state information as a function',
   proname => 'pg_control_checkpoint', provolatile => 'v',
-- 
2.35.1

From a63818a32d661dba563cedfdb85731e522b3c6a9 Mon Sep 17 00:00:00 2001
From: Thomas Munro <[email-masked]>
Date: Thu, 24 Nov 2022 13:28:22 +1300
Subject: [PATCH 2/2] Try to tolerate concurrent reads and writes of control
 file.

Various frontend programs and SQL-callable backend functions read the
control file without any kind of interlocking against concurrent writes.
Linux ext4 doesn't implement the atomicity required by POSIX here, so a
concurrent reader can see only partial effects of an in-progress write.

Tolerate this by retrying until we get two reads in a row with the same
checksum, after an idea from Tom Lane.

Reported-by: Andres Freund <[email-masked]>
Discussion: https://postgr.es/m/20221123014224.xisi44byq3cf5psi%40awork3.anarazel.de
---
 src/common/controldata_utils.c | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)

diff --git a/src/common/controldata_utils.c b/src/common/controldata_utils.c
index 2d1f35bbd1..200d24df02 100644
--- a/src/common/controldata_utils.c
+++ b/src/common/controldata_utils.c
@@ -56,12 +56,19 @@ get_controlfile(const char *DataDir, bool *crc_ok_p)
 	char		ControlFilePath[MAXPGPATH];
 	pg_crc32c	crc;
 	int			r;
+	bool		first_try;
+	pg_crc32c	last_crc;
 
 	Assert(crc_ok_p);
 
 	ControlFile = palloc_object(ControlFileData);
 	snprintf(ControlFilePath, MAXPGPATH, "%s/global/pg_control", DataDir);
 
+	first_try = true;
+	INIT_CRC32C(last_crc);
+
+retry:
+
 #ifndef FRONTEND
 	if ((fd = OpenTransientFile(ControlFilePath, O_RDONLY | PG_BINARY)) == -1)
 		ereport(ERROR,
@@ -117,6 +124,24 @@ get_controlfile(const char *DataDir, bool *crc_ok_p)
 
 	*crc_ok_p = EQ_CRC32C(crc, ControlFile->crc);
 
+	/*
+	 * With unlucky timing on filesystems that don't implement atomicity of
+	 * concurrent reads and writes (such as Linux ext4), we might have seen
+	 * garbage if the server was writing to the file at the same time.  Keep
+	 * retrying until we see the same CRC twice.
+	 */
+	if (!*crc_ok_p && (first_try || !EQ_CRC32C(crc, last_crc)))
+	{
+		first_try = false;
+		last_crc = crc;
+		pg_usleep(10000);
+
+#ifndef FRONTEND
+		CHECK_FOR_INTERRUPTS();
+#endif
+		goto retry;
+	}
+
 	/* Make sure the control file is valid byte order. */
 	if (ControlFile->pg_control_version % 65536 == 0 &&
 		ControlFile->pg_control_version / 65536 != 0)
-- 
2.35.1

---

From: Thomas Munro <[email-masked]>
Date: Thu, 24 Nov 2022 14:59:04 +1300

> ERROR:  calculated CRC checksum does not match value stored in file

I forgot to mention: this reproducer only seems to work if fsync =
off.  I don't know why, but I recall that was true also for bug
#17064.