public inbox for [email protected]
help / color / mirror / Atom feedodd buildfarm failure - "pg_ctl: control file appears to be corrupt"
8+ messages / 5 participants
[nested] [flat]
* odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
@ 2022-11-23 01:42 Andres Freund <[email protected]>
2022-11-23 06:12 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Michael Paquier <[email protected]>
2022-11-23 09:02 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Alvaro Herrera <[email protected]>
2022-11-23 10:03 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
0 siblings, 3 replies; 8+ messages in thread
From: Andres Freund @ 2022-11-23 01:42 UTC (permalink / raw)
To: pgsql-hackers
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
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
@ 2022-11-23 06:12 ` Michael Paquier <[email protected]>
2 siblings, 0 replies; 8+ messages in thread
From: Michael Paquier @ 2022-11-23 06:12 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers
On Tue, Nov 22, 2022 at 05:42:24PM -0800, Andres Freund wrote:
> The failure has to be happening in wait_for_postmaster_promote(), because the
> 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
Attachments:
[application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
download
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
@ 2022-11-23 09:02 ` Alvaro Herrera <[email protected]>
2 siblings, 0 replies; 8+ messages in thread
From: Alvaro Herrera @ 2022-11-23 09:02 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers
On 2022-Nov-22, Andres Freund wrote:
> 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.
This triggered me on this proposal I saw yesterday
https://postgr.es/m/[email protected]
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/
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
@ 2022-11-23 10:03 ` Thomas Munro <[email protected]>
2022-11-23 21:59 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
2 siblings, 1 reply; 8+ messages in thread
From: Thomas Munro @ 2022-11-23 10:03 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers
On Wed, Nov 23, 2022 at 2:42 PM Andres Freund <[email protected]> wrote:
> The failure has to be happening in wait_for_postmaster_promote(), because the
> 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.
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
2022-11-23 10:03 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
@ 2022-11-23 21:59 ` Thomas Munro <[email protected]>
2022-11-23 22:05 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Tom Lane <[email protected]>
0 siblings, 1 reply; 8+ messages in thread
From: Thomas Munro @ 2022-11-23 21:59 UTC (permalink / raw)
To: Andres Freund <[email protected]>; +Cc: pgsql-hackers
On Wed, Nov 23, 2022 at 11:03 PM Thomas Munro <[email protected]> wrote:
> On Wed, Nov 23, 2022 at 2:42 PM Andres Freund <[email protected]> wrote:
> > The failure has to be happening in wait_for_postmaster_promote(), because the
> > 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.
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.
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
2022-11-23 10:03 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
2022-11-23 21:59 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
@ 2022-11-23 22:05 ` Tom Lane <[email protected]>
2022-11-24 01:02 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
0 siblings, 1 reply; 8+ messages in thread
From: Tom Lane @ 2022-11-23 22:05 UTC (permalink / raw)
To: Thomas Munro <[email protected]>; +Cc: Andres Freund <[email protected]>; pgsql-hackers
Thomas Munro <[email protected]> writes:
> On Wed, Nov 23, 2022 at 11:03 PM Thomas Munro <[email protected]> wrote:
>> 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.
Ugh.
> As for what to do about it, some ideas:
> 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.
> First thought is that 2 is appropriate level of complexity for this
> rare and stupid problem.
Yeah, I was thinking the same. A variant could be "repeat until
we see the same calculated checksum twice".
regards, tom lane
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
2022-11-23 10:03 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
2022-11-23 21:59 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
2022-11-23 22:05 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Tom Lane <[email protected]>
@ 2022-11-24 01:02 ` Thomas Munro <[email protected]>
2022-11-24 01:59 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
0 siblings, 1 reply; 8+ messages in thread
From: Thomas Munro @ 2022-11-24 01:02 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Andres Freund <[email protected]>; pgsql-hackers
On Thu, Nov 24, 2022 at 11:05 AM Tom Lane <[email protected]> wrote:
> Thomas Munro <[email protected]> writes:
> > On Wed, Nov 23, 2022 at 11:03 PM Thomas Munro <[email protected]> wrote:
> > As for what to do about it, some ideas:
> > 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.
>
> > First thought is that 2 is appropriate level of complexity for this
> > rare and stupid problem.
>
> Yeah, I was thinking the same. A variant could be "repeat until
> 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.
Attachments:
[text/x-patch] 0001-XXX-Dirty-hack-to-clobber-control-file-for-testing.patch (1.8K, ../../CA+hUKGK-BEe38aKNqHJDQ86LUW-CMwF5F9bo1JtJVg71FoDv_w@mail.gmail.com/2-0001-XXX-Dirty-hack-to-clobber-control-file-for-testing.patch)
download | inline diff:
From 9f1856aeb56be888123702fe471d8388da66439f Mon Sep 17 00:00:00 2001
From: Thomas Munro <[email protected]>
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
[text/x-patch] 0002-Try-to-tolerate-concurrent-reads-and-writes-of-contr.patch (2.3K, ../../CA+hUKGK-BEe38aKNqHJDQ86LUW-CMwF5F9bo1JtJVg71FoDv_w@mail.gmail.com/3-0002-Try-to-tolerate-concurrent-reads-and-writes-of-contr.patch)
download | inline diff:
From a63818a32d661dba563cedfdb85731e522b3c6a9 Mon Sep 17 00:00:00 2001
From: Thomas Munro <[email protected]>
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 protected]>
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
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt"
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
2022-11-23 10:03 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
2022-11-23 21:59 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
2022-11-23 22:05 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Tom Lane <[email protected]>
2022-11-24 01:02 ` Re: odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Thomas Munro <[email protected]>
@ 2022-11-24 01:59 ` Thomas Munro <[email protected]>
0 siblings, 0 replies; 8+ messages in thread
From: Thomas Munro @ 2022-11-24 01:59 UTC (permalink / raw)
To: Tom Lane <[email protected]>; +Cc: Andres Freund <[email protected]>; pgsql-hackers
On Thu, Nov 24, 2022 at 2:02 PM Thomas Munro <[email protected]> wrote:
> ... and you'll soon see:
>
> 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.
^ permalink raw reply [nested|flat] 8+ messages in thread
end of thread, other threads:[~2022-11-24 01:59 UTC | newest]
Thread overview: 8+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2022-11-23 01:42 odd buildfarm failure - "pg_ctl: control file appears to be corrupt" Andres Freund <[email protected]>
2022-11-23 06:12 ` Michael Paquier <[email protected]>
2022-11-23 09:02 ` Alvaro Herrera <[email protected]>
2022-11-23 10:03 ` Thomas Munro <[email protected]>
2022-11-23 21:59 ` Thomas Munro <[email protected]>
2022-11-23 22:05 ` Tom Lane <[email protected]>
2022-11-24 01:02 ` Thomas Munro <[email protected]>
2022-11-24 01:59 ` Thomas Munro <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox