Subject: DDL result is lost by CREATE DATABASE with WAL_LOG strategy

From: "Ryo Matsumura (Fujitsu)" <[email-masked]>
Date: Wed, 15 Feb 2023 04:49:38 +0000

Hi, hackers.

I found that CREATE DATABASE occurs lost of DDL result after crash server.
The direct cause is that the checkpoint skips sync for page of template1's main fork
because buffer status is not marked as BM_PERMANENT in BufferAlloc().

Have you any knowledge about it?

Reproduction:
1) Do initdb.
2) Start server.
3) Connect to 'postgres' database.
4) Execute CREATE DATABASE statement with WAL_LOG strategy.
5) Connect to 'template1' database.
6) Update pg_class by executing some DDL.
7) Do checkpoint.
8) Crash server.

[src/backend/storage/buffer/bufmgr.c]
1437     if (relpersistence == RELPERSISTENCE_PERMANENT || forkNum == INIT_FORKNUM)
1438         buf_state |= BM_TAG_VALID | BM_PERMANENT | BUF_USAGECOUNT_ONE;
1439     else
             !!! walk this route !!!
1440         buf_state |= BM_TAG_VALID | BUF_USAGECOUNT_ONE;

The above is occured by the following call.
The argument 'permanent' of ReadBufferWithoutRelcache() is passed to
BufferAlloc() as 'relpersistence'.

[src/backend/commands/]
 298         buf = ReadBufferWithoutRelcache(rnode, MAIN_FORKNUM, blkno,
 299                                         RBM_NORMAL, bstrategy, false);

Regards
Ryo Matsumura

---

From: Justin Pryzby <[email-masked]>
Date: Wed, 15 Feb 2023 10:24:08 -0600

> because buffer status is not marked as BM_PERMANENT in BufferAlloc().

I had some trouble reproducing this when running the commands by hand.

But it reproduces fine like this:

$ ./tmp_install/usr/local/pgsql/bin/postgres -D ./testrun/regress/regress/tmp_check/data& sleep 2; psql -h /tmp postgres -c "DROP DATABASE IF EXISTS j" -c "CREATE DATABASE j STRATEGY wal_log" && psql -h /tmp template1 -c "CREATE TABLE t(i int)" -c "INSERT INTO t SELECT generate_series(1,9)" -c CHECKPOINT; kill -9 %1; wait; ./tmp_install/usr/local/pgsql/bin/postgres -D ./testrun/regress/regress/tmp_check/data& sleep 9; psql -h /tmp template1 -c "table t"; kill %1
[1] 29069
2023-02-15 10:10:27.584 CST postmaster[29069] LOG:  starting PostgreSQL 16devel on x86_64-linux, compiled by gcc-9.4.0, 64-bit
2023-02-15 10:10:27.584 CST postmaster[29069] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2023-02-15 10:10:27.663 CST postmaster[29069] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-02-15 10:10:27.728 CST startup[29074] LOG:  database system was shut down at 2023-02-15 10:10:13 CST
2023-02-15 10:10:27.780 CST postmaster[29069] LOG:  database system is ready to accept connections
NOTICE:  database "j" does not exist, skipping
DROP DATABASE
CREATE DATABASE
CREATE TABLE
INSERT 0 9
2023-02-15 10:10:30.160 CST checkpointer[29072] LOG:  checkpoint starting: immediate force wait
2023-02-15 10:10:30.740 CST checkpointer[29072] LOG:  checkpoint complete: wrote 943 buffers (5.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.070 s, sync=0.369 s, total=0.581 s; sync files=268, longest=0.274 s, average=0.002 s; distance=4322 kB, estimate=4322 kB; lsn=0/BA9E8A0, redo lsn=0/BA9E868
CHECKPOINT
[1]+  Killed                  ./tmp_install/usr/local/pgsql/bin/postgres -D ./testrun/regress/regress/tmp_check/data
[1] 29088
2023-02-15 10:10:31.664 CST postmaster[29088] LOG:  starting PostgreSQL 16devel on x86_64-linux, compiled by gcc-9.4.0, 64-bit
2023-02-15 10:10:31.665 CST postmaster[29088] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2023-02-15 10:10:31.724 CST postmaster[29088] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-02-15 10:10:31.780 CST startup[29094] LOG:  database system was interrupted; last known up at 2023-02-15 10:10:30 CST
2023-02-15 10:10:33.888 CST startup[29094] LOG:  database system was not properly shut down; automatic recovery in progress
2023-02-15 10:10:33.934 CST startup[29094] LOG:  redo starts at 0/BA9E868
2023-02-15 10:10:33.934 CST startup[29094] LOG:  invalid record length at 0/BA9E918: wanted 24, got 0
2023-02-15 10:10:33.934 CST startup[29094] LOG:  redo done at 0/BA9E8A0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2023-02-15 10:10:34.073 CST checkpointer[29092] LOG:  checkpoint starting: end-of-recovery immediate wait
2023-02-15 10:10:34.275 CST checkpointer[29092] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.035 s, sync=0.026 s, total=0.257 s; sync files=2, longest=0.019 s, average=0.013 s; distance=0 kB, estimate=0 kB; lsn=0/BA9E918, redo lsn=0/BA9E918
2023-02-15 10:10:34.321 CST postmaster[29088] LOG:  database system is ready to accept connections
2023-02-15 10:10:39.893 CST client backend[29110] psql ERROR:  relation "t" does not exist at character 7
2023-02-15 10:10:39.893 CST client backend[29110] psql STATEMENT:  table t
ERROR:  relation "t" does not exist

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 15 Feb 2023 16:06:59 -0800

>  299                                         RBM_NORMAL, bstrategy, false);

Indeed, setting that to true (as per the attached patch) seems to fix this.
I don't see any reason this _shouldn't_ be true from what I've read so far.
We're reading pg_class, which will probably never be UNLOGGED.

-- 
Nathan Bossart
Amazon Web Services: https://aws.amazon.com
diff --git a/src/backend/commands/dbcommands.c b/src/backend/commands/dbcommands.c
index ef05633bb0..a0259cc593 100644
--- a/src/backend/commands/dbcommands.c
+++ b/src/backend/commands/dbcommands.c
@@ -296,7 +296,7 @@ ScanSourceDatabasePgClass(Oid tbid, Oid dbid, char *srcpath)
 		CHECK_FOR_INTERRUPTS();
 
 		buf = ReadBufferWithoutRelcache(rlocator, MAIN_FORKNUM, blkno,
-										RBM_NORMAL, bstrategy, false);
+										RBM_NORMAL, bstrategy, true);
 
 		LockBuffer(buf, BUFFER_LOCK_SHARE);
 		page = BufferGetPage(buf);

---

From: Dilip Kumar <[email-masked]>
Date: Thu, 16 Feb 2023 10:24:13 +0530

> We're reading pg_class, which will probably never be UNLOGGED.

Yes, there is no reason to pass this as false, seems like this is
passed false by mistake.  And your patch fixes the issue.

-- 
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

---

From: Michael Paquier <[email-masked]>
Date: Thu, 16 Feb 2023 14:26:55 +0900

> passed false by mistake.  And your patch fixes the issue.

So, if I am understanding this stuff right, this issue can create data
corruption once a DDL updates any pages of pg_class stored in a
template database that gets copied by this routine.  In this case, the
patch sent makes sure that any page copied will get written once a
checkpoint kicks in.  Shouldn't we have at least a regression test for
such a scenario?  The issue can happen when updating a template
database after creating a database from it, which is less worrying
than the initial impression I got, still I'd like to think that we
should have some coverage as of the special logic this code path
relies on for pg_class when reading its buffers.

I have not given much attention to this area, but I am a bit
suspicious that enforcing the default as WAL_LOG was a good idea for
15~, TBH.  We are usually much more conservative when it comes to
such choices, switching to the new behavior after a few years would
have been wiser..
--
Michael

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 15 Feb 2023 22:41:20 -0800

> relies on for pg_class when reading its buffers.

I was able to quickly hack together a TAP test that seems to reliably fail
before the fix and pass afterwards.  There's probably a better place for
it, though...

 
 		LockBuffer(buf, BUFFER_LOCK_SHARE);
 		page = BufferGetPage(buf);
diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.build
index 209118a639..6e9f8a7c7f 100644
--- a/src/test/recovery/meson.build
+++ b/src/test/recovery/meson.build
@@ -39,6 +39,7 @@ tests += {
       't/031_recovery_conflict.pl',
       't/032_relfilenode_reuse.pl',
       't/033_replay_tsp_drops.pl',
+      't/100_bugs.pl',
     ],
   },
 }
diff --git a/src/test/recovery/t/100_bugs.pl b/src/test/recovery/t/100_bugs.pl
new file mode 100644
index 0000000000..6429a352e9
--- /dev/null
+++ b/src/test/recovery/t/100_bugs.pl
@@ -0,0 +1,24 @@
+
+# Copyright (c) 2023, PostgreSQL Global Development Group
+
+# Tests for various bugs found over time
+use strict;
+use warnings;
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# DDL on template is persisted after creating database using WAL_LOG strategy
+my $node = PostgreSQL::Test::Cluster->new('node');
+$node->init;
+$node->start;
+$node->safe_psql("postgres", "CREATE DATABASE test STRATEGY WAL_LOG;");
+$node->safe_psql("template1", "CREATE TABLE test (a INT);");
+$node->safe_psql("postgres", "CHECKPOINT;");
+$node->stop('immediate');
+$node->start;
+my $result = $node->safe_psql("template1", "SELECT count(*) FROM test;");
+is($result, "0", "check table still exists");
+$node->stop;
+
+done_testing();

---

From: Dilip Kumar <[email-masked]>
Date: Thu, 16 Feb 2023 12:31:54 +0530

> before the fix and pass afterwards.  There's probably a better place for

I think the below change is not relevant to this bug right?

---

From: Robert Haas <[email-masked]>
Date: Thu, 16 Feb 2023 12:37:57 +0530

>        't/033_replay_tsp_drops.pl',

Why not? The patch creates 100_bugs.pl so it also adds it to meson.build.

-- 
Robert Haas
EDB: http://www.enterprisedb.com

---

From: Michael Paquier <[email-masked]>
Date: Thu, 16 Feb 2023 16:17:16 +0900

> Why not? The patch creates 100_bugs.pl so it also adds it to meson.build.

It would not matter for REL_15_STABLE, but on HEAD all the new TAP
test files have to be added in their respective meson.build.  If you
don't do that, the CFBot would not test it, neither would a local
build with meson.

Adding a test in src/test/recovery/ is OK by me.  This is a recovery
case, and that's a..  Bug.  Another possible name would be something
like 0XX_create_database.pl, now that's me being picky.
--
Michael

---

From: Andres Freund <[email-masked]>
Date: Thu, 16 Feb 2023 13:29:34 -0800

On 2023-02-16 12:37:57 +0530, Robert Haas wrote:
> The patch creates 100_bugs.pl

What's the story behind 100_bugs.pl? This name clearly is copied from
src/test/subscription/t/100_bugs.pl - but I've never understood why that is
outside of the normal numbering space.

---

From: Amit Kapila <[email-masked]>
Date: Fri, 17 Feb 2023 08:54:02 +0530

> outside of the normal numbering space.

Yeah, I have also previously wondered about this name for
src/test/subscription/t/100_bugs.pl. My guess is that it has been kept
to distinguish it from the other feature tests which have numbering
starting from 001.

-- 
With Regards,
Amit Kapila.

---

From: Peter Eisentraut <[email-masked]>
Date: Fri, 17 Feb 2023 15:13:32 +0100

> outside of the normal numbering space.

Mainly to avoid awkwardness for backpatching.  The number of tests in 
src/test/subscription/ varies quite a bit across branches.

---

From: Nathan Bossart <[email-masked]>
Date: Fri, 17 Feb 2023 14:35:30 -0800

> src/test/subscription/ varies quite a bit across branches.

I'm happy to move this new test to wherever folks think it should go.  I'll
look around to see if I can find a better place, too.

---

From: Michael Paquier <[email-masked]>
Date: Mon, 20 Feb 2023 17:02:01 +0900

> look around to see if I can find a better place, too.

I think that src/test/recovery/ is the best fit, because this stresses
a code path for WAL replay on pg_class for the template db.  The name
is not specific enough, though, why not just using something like
0NN_create_database.pl?
--
Michael

---

From: "Ryo Matsumura (Fujitsu)" <[email-masked]>
Date: Mon, 20 Feb 2023 08:22:02 +0000

On Thu, Feb 16, 2023 at 02:26:55PM +0900, Michael Paquier wrote:
> checkpoint kicks in.

Thank you for comment and patch.
I think that the patch for dbcommand.c is fixed.
So I apply to my environment.

> such choices, switching to the new behavior after a few years would

I think so too. I was surprised that new strategy is default.

Regards
Ryo Matsumura