Subject: Re: pgsql: Add contrib/pg_walinspect.

From: Tom Lane <[email-masked]>
Date: Tue, 26 Apr 2022 20:25:29 -0400

Thomas Munro <[email-masked]> writes:
> I think it's a bug in pg_walinspect, so I'll move the discussion back
> here.  Here's one rather simple way to fix it, that has survived
> running the test a thousand times (using a recipe that failed for me
> quite soon, after 20-100 attempts or so; I never figured out how to
> get the 50% failure rate reported by Tom).

Not sure what we're doing differently, but plain "make check" in
contrib/pg_walinspect fails pretty consistently for me on gcc23.
I tried it again just now and got five failures in five attempts.

I then installed your patch and got the same failure, three times
out of three, so I don't think we're there yet.

Again, since I do have this problem in captivity, I'm happy
to spend some time poking at it.  But I could use a little
guidance where to poke, because I've not looked at any of
the WAL prefetch stuff.

			regards, tom lane

---

From: Thomas Munro <[email-masked]>
Date: Wed, 27 Apr 2022 13:10:50 +1200

> I tried it again just now and got five failures in five attempts.

I tried on the /home filesystem (a slow NFS mount) and then inside a
directory on /tmp to get ext4 (I saw that Noah had somehow got onto a
local filesystem, based on the present of "ext4" in the pathname and I
was trying everything I could think of).  I used what I thought might
be some relevant starter configure options copied from the animal:

./configure --prefix=$HOME/install --enable-cassert --enable-debug
--enable-tap-tests CC="ccache gcc -mips32r2" CFLAGS="-O2
-funwind-tables" LDFLAGS="-rdynamic"

For me, make check always succeeds in contrib/pg_walinspect.  For me,
make installcheck fails if I do it enough times in a loop, somewhere
around the 20th loop or so, which I imagine has to do with WAL page
boundaries moving around.

for i in `seq 1 1000` ; do
  make -s installcheck || exit 1
done

> out of three, so I don't think we're there yet.

Hrmph...  Are you sure you rebuilt the contrib module?   Assuming so,
maybe it's failing in a different way for you and me.  For me, it
always fails after this break is reached in xlogutil.c:

            /* If asked, let's not wait for future WAL. */
            if (!wait_for_wal)
                break;

If you add a log message there, do you see that?  For me, the patch
fixes it, because it teaches pg_walinspect that messageless errors are
a way of detecting end-of-data (due to the code above, introduced by
the pg_walinspect commit).

---

From: Tom Lane <[email-masked]>
Date: Tue, 26 Apr 2022 21:47:53 -0400

>             /* If asked, let's not wait for future WAL. */

Hmm.  For me, that statement is not reached at all in successful
(make installcheck) runs.  In a failing run, it's reached with
wait_for_wal = false, after which we get the "could not read WAL"
failure.  Usually that happens twice, as per attached.

			regards, tom lane

diff --git a/contrib/pg_walinspect/Makefile b/contrib/pg_walinspect/Makefile
index 960530e..85dcb3a 100644
--- a/contrib/pg_walinspect/Makefile
+++ b/contrib/pg_walinspect/Makefile
@@ -15,7 +15,6 @@ REGRESS_OPTS = --temp-config $(top_srcdir)/contrib/pg_walinspect/walinspect.conf
 
 # Disabled because these tests require "wal_level=replica", which
 # some installcheck users do not have (e.g. buildfarm clients).
-NO_INSTALLCHECK = 1
 
 ifdef USE_PGXS
 PG_CONFIG = pg_config
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c
index cf5db23..33d2c73 100644
--- a/src/backend/access/transam/xlogreader.c
+++ b/src/backend/access/transam/xlogreader.c
@@ -373,6 +373,9 @@ XLogNextRecord(XLogReaderState *state, char **errormsg)
 		 */
 		Assert(!XLogRecPtrIsInvalid(state->EndRecPtr));
 
+		if(!*errormsg)
+		  *errormsg = "decode_queue_head is null";
+		
 		return NULL;
 	}
 
diff --git a/src/backend/access/transam/xlogutils.c b/src/backend/access/transam/xlogutils.c
index 4257026..4089efd 100644
--- a/src/backend/access/transam/xlogutils.c
+++ b/src/backend/access/transam/xlogutils.c
@@ -955,6 +955,8 @@ read_local_xlog_page_guts(XLogReaderState *state, XLogRecPtr targetPagePtr,
 			if (loc <= read_upto)
 				break;
 
+			elog(LOG, "let's wait for wal: %d", wait_for_wal);
+
 			/* If asked, let's not wait for future WAL. */
 			if (!wait_for_wal)
 				break;
2022-04-27 03:40:09.253 CEST postmaster[32569] LOG:  starting PostgreSQL 15devel on mipsel-unknown-linux-gnu, compiled by gcc (Debian 4.9.2-10+deb8u1) 4.9.2, 32-bit
2022-04-27 03:40:09.254 CEST postmaster[32569] LOG:  listening on Unix socket "/tmp/pg_regress-g0HWzi/.s.PGSQL.51696"
2022-04-27 03:40:09.284 CEST startup[32574] LOG:  database system was shut down at 2022-04-27 03:40:09 CEST
2022-04-27 03:40:09.314 CEST postmaster[32569] LOG:  database system is ready to accept connections
2022-04-27 03:40:12.073 CEST client backend[32598] pg_regress/pg_walinspect ERROR:  WAL start LSN must be less than end LSN
2022-04-27 03:40:12.073 CEST client backend[32598] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info('0/1903EE8', '0/1903E40');
2022-04-27 03:40:12.075 CEST client backend[32598] pg_regress/pg_walinspect ERROR:  WAL start LSN must be less than end LSN
2022-04-27 03:40:12.075 CEST client backend[32598] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats('0/1903EE8', '0/1903E40');
2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspect LOG:  let's wait for wal: 0
2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E40');
2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspect ERROR:  could not read WAL at 0/1903E40: decode_queue_head is null
2022-04-27 03:40:12.085 CEST client backend[32598] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E40');
2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspect LOG:  let's wait for wal: 0
2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E40');
2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspect ERROR:  could not read WAL at 0/1903E40: decode_queue_head is null
2022-04-27 03:40:12.091 CEST client backend[32598] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E40');
2022-04-27 03:40:12.198 CEST postmaster[32569] LOG:  received fast shutdown request
2022-04-27 03:40:12.299 CEST postmaster[32569] LOG:  aborting any active transactions
2022-04-27 03:40:12.304 CEST postmaster[32569] LOG:  background worker "logical replication launcher" (PID 32577) exited with exit code 1
2022-04-27 03:40:12.306 CEST checkpointer[32572] LOG:  shutting down
2022-04-27 03:40:12.310 CEST checkpointer[32572] LOG:  checkpoint starting: shutdown immediate
2022-04-27 03:40:12.524 CEST checkpointer[32572] LOG:  checkpoint complete: wrote 784 buffers (4.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.199 s, sync=0.001 s, total=0.218 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4197 kB, estimate=4197 kB
2022-04-27 03:40:12.838 CEST postmaster[32569] LOG:  database system is shut down

---

From: Thomas Munro <[email-masked]>
Date: Wed, 27 Apr 2022 13:54:34 +1200

> failure.  Usually that happens twice, as per attached.

Ok, that's the same for me.  Next question: why does the patch I
posted not help?  For me, the error "could not read WAL at %X/%X",
seen on the BF log, is raised by ReadNextXLogRecord() in
pg_walinspect.c.  The patch removes that ereport() entirely (and
handles NULL in a couple of places).

---

From: Tom Lane <[email-masked]>
Date: Tue, 26 Apr 2022 21:55:50 -0400

> -funwind-tables" LDFLAGS="-rdynamic"

Hmph.  I'm also running it on the /home filesystem, and I used
these settings:

export CC="ccache gcc -mips32r2"
export CFLAGS="-O2 -funwind-tables"
export LDFLAGS="-rdynamic"

./configure --enable-debug --enable-cassert --with-systemd --enable-nls --with-icu --enable-tap-tests --with-system-tzdata=/usr/share/zoneinfo

plus uninteresting stuff like --prefix.  Now maybe some of these
other options affect this, but I'd be pretty surprised if so.
So I'm at a loss why it behaves differently for you.

			regards, tom lane

---

From: Tom Lane <[email-masked]>
Date: Tue, 26 Apr 2022 22:14:25 -0400

Thomas Munro <[email-masked]> writes:
> posted not help?

I improved the instrumentation a bit, and it looks like what is
happening is that loc > read_upto, causing that code to "break"
independently of wait_for_wal.  success.log is from "make installcheck"
immediately after initdb; fail.log is from "make check".

			regards, tom lane

 
 ifdef USE_PGXS
 PG_CONFIG = pg_config
 
+		if(!*errormsg)
 
diff --git a/src/backend/access/transam/xlogutils.c b/src/backend/access/transam/xlogutils.c
index 4257026..5ea59a3 100644
--- a/src/backend/access/transam/xlogutils.c
+++ b/src/backend/access/transam/xlogutils.c
@@ -951,6 +951,9 @@ read_local_xlog_page_guts(XLogReaderState *state, XLogRecPtr targetPagePtr,
 
 		if (state->currTLI == currTLI)
 		{
+		  elog(LOG, "considering wait for wal: loc %X/%X read_upto %X/%X wait_for_wal %d",
+		       LSN_FORMAT_ARGS(loc), LSN_FORMAT_ARGS(read_upto),
+		       wait_for_wal);
 
 			if (loc <= read_upto)
 				break;
2022-04-27 04:06:21.995 CEST [4503] LOG:  starting PostgreSQL 15devel on mipsel-unknown-linux-gnu, compiled by gcc (Debian 4.9.2-10+deb8u1) 4.9.2, 32-bit
2022-04-27 04:06:21.997 CEST [4503] LOG:  listening on IPv6 address "::1", port 5440
2022-04-27 04:06:21.997 CEST [4503] LOG:  listening on IPv4 address "127.0.0.1", port 5440
2022-04-27 04:06:22.000 CEST [4503] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5440"
2022-04-27 04:06:22.021 CEST [4523] LOG:  database system was shut down at 2022-04-27 04:06:11 CEST
2022-04-27 04:06:22.048 CEST [4503] LOG:  database system is ready to accept connections
2022-04-27 04:06:30.619 CEST [4738] ERROR:  WAL start LSN must be less than end LSN
2022-04-27 04:06:30.619 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info('0/1903EB0', '0/1903E08');
2022-04-27 04:06:30.621 CEST [4738] ERROR:  WAL start LSN must be less than end LSN
2022-04-27 04:06:30.621 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats('0/1903EB0', '0/1903E08');
2022-04-27 04:06:30.623 CEST [4738] LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.623 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_record_info('0/1903E08');
2022-04-27 04:06:30.623 CEST [4738] LOG:  considering wait for wal: loc 0/1903E08 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.623 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_record_info('0/1903E08');
2022-04-27 04:06:30.626 CEST [4738] LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.626 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info('0/1903E08', '0/1903EB0');
2022-04-27 04:06:30.626 CEST [4738] LOG:  considering wait for wal: loc 0/1903E08 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.626 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info('0/1903E08', '0/1903EB0');
2022-04-27 04:06:30.630 CEST [4738] LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.630 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E08');
2022-04-27 04:06:30.630 CEST [4738] LOG:  considering wait for wal: loc 0/1903E08 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.630 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E08');
2022-04-27 04:06:30.633 CEST [4738] LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.633 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats('0/1903E08', '0/1903EB0');
2022-04-27 04:06:30.634 CEST [4738] LOG:  considering wait for wal: loc 0/1903E08 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.634 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats('0/1903E08', '0/1903EB0');
2022-04-27 04:06:30.638 CEST [4738] LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.638 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E08');
2022-04-27 04:06:30.639 CEST [4738] LOG:  considering wait for wal: loc 0/1903E08 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.639 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E08');
2022-04-27 04:06:30.653 CEST [4738] LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.653 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E08', '0/1903EB0')
				WHERE block_ref LIKE concat('%', '16391', '%') AND resource_manager = 'Heap';
2022-04-27 04:06:30.654 CEST [4738] LOG:  considering wait for wal: loc 0/1903E08 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.654 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E08', '0/1903EB0')
				WHERE block_ref LIKE concat('%', '16391', '%') AND resource_manager = 'Heap';
2022-04-27 04:06:30.657 CEST [4738] LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.657 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E08', '0/1903EB0')
				WHERE resource_manager = 'Heap' AND record_type = 'INSERT';
2022-04-27 04:06:30.658 CEST [4738] LOG:  considering wait for wal: loc 0/1903E08 read_upto 0/1903F58 wait_for_wal 0
2022-04-27 04:06:30.658 CEST [4738] STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E08', '0/1903EB0')
				WHERE resource_manager = 'Heap' AND record_type = 'INSERT';
2022-04-27 04:06:37.735 CEST [4503] LOG:  received fast shutdown request
2022-04-27 04:06:37.829 CEST [4503] LOG:  aborting any active transactions
2022-04-27 04:06:37.835 CEST [4503] LOG:  background worker "logical replication launcher" (PID 4526) exited with exit code 1
2022-04-27 04:06:40.402 CEST [4521] LOG:  shutting down
2022-04-27 04:06:40.406 CEST [4521] LOG:  checkpoint starting: shutdown immediate
2022-04-27 04:06:41.063 CEST [4521] LOG:  checkpoint complete: wrote 784 buffers (4.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.218 s, sync=0.001 s, total=0.661 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4197 kB, estimate=4197 kB
2022-04-27 04:06:43.573 CEST [4503] LOG:  database system is shut down
2022-04-27 04:04:08.677 CEST postmaster[3167] LOG:  starting PostgreSQL 15devel on mipsel-unknown-linux-gnu, compiled by gcc (Debian 4.9.2-10+deb8u1) 4.9.2, 32-bit
2022-04-27 04:04:08.677 CEST postmaster[3167] LOG:  listening on Unix socket "/tmp/pg_regress-S5YZoI/.s.PGSQL.51696"
2022-04-27 04:04:08.708 CEST startup[3172] LOG:  database system was shut down at 2022-04-27 04:04:08 CEST
2022-04-27 04:04:08.737 CEST postmaster[3167] LOG:  database system is ready to accept connections
2022-04-27 04:04:12.135 CEST client backend[3185] pg_regress/pg_walinspect ERROR:  WAL start LSN must be less than end LSN
2022-04-27 04:04:12.135 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info('0/1903EE8', '0/1903E40');
2022-04-27 04:04:12.137 CEST client backend[3185] pg_regress/pg_walinspect ERROR:  WAL start LSN must be less than end LSN
2022-04-27 04:04:12.137 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats('0/1903EE8', '0/1903E40');
2022-04-27 04:04:12.138 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1903F90 wait_for_wal 0
2022-04-27 04:04:12.138 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_record_info('0/1903E40');
2022-04-27 04:04:12.139 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1903E40 read_upto 0/1903F90 wait_for_wal 0
2022-04-27 04:04:12.139 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_record_info('0/1903E40');
2022-04-27 04:04:12.142 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.142 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info('0/1903E40', '0/1903EE8');
2022-04-27 04:04:12.143 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1903E40 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.143 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info('0/1903E40', '0/1903EE8');
2022-04-27 04:04:12.146 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.146 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.147 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1903E40 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.147 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.147 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1904034 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.147 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.147 CEST client backend[3185] pg_regress/pg_walinspect ERROR:  could not read WAL at 0/1903E40: decode_queue_head is null
2022-04-27 04:04:12.147 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_records_info_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.149 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.149 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats('0/1903E40', '0/1903EE8');
2022-04-27 04:04:12.149 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1903E40 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.149 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats('0/1903E40', '0/1903EE8');
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1903E40 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1904034 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect ERROR:  could not read WAL at 0/1903E40: decode_queue_head is null
2022-04-27 04:04:12.153 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 0 AS ok FROM pg_get_wal_stats_till_end_of_wal('0/1903E40');
2022-04-27 04:04:12.165 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.165 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E40', '0/1903EE8')
				WHERE block_ref LIKE concat('%', '16391', '%') AND resource_manager = 'Heap';
2022-04-27 04:04:12.165 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1903E40 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.165 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E40', '0/1903EE8')
				WHERE block_ref LIKE concat('%', '16391', '%') AND resource_manager = 'Heap';
2022-04-27 04:04:12.168 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1002000 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.168 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E40', '0/1903EE8')
				WHERE resource_manager = 'Heap' AND record_type = 'INSERT';
2022-04-27 04:04:12.168 CEST client backend[3185] pg_regress/pg_walinspect LOG:  considering wait for wal: loc 0/1903E40 read_upto 0/1904000 wait_for_wal 0
2022-04-27 04:04:12.168 CEST client backend[3185] pg_regress/pg_walinspect STATEMENT:  SELECT COUNT(*) >= 1 AS ok FROM pg_get_wal_records_info('0/1903E40', '0/1903EE8')
				WHERE resource_manager = 'Heap' AND record_type = 'INSERT';
2022-04-27 04:04:12.297 CEST postmaster[3167] LOG:  received fast shutdown request
2022-04-27 04:04:12.299 CEST postmaster[3167] LOG:  aborting any active transactions
2022-04-27 04:04:12.306 CEST postmaster[3167] LOG:  background worker "logical replication launcher" (PID 3175) exited with exit code 1
2022-04-27 04:04:12.307 CEST checkpointer[3170] LOG:  shutting down
2022-04-27 04:04:12.310 CEST checkpointer[3170] LOG:  checkpoint starting: shutdown immediate
2022-04-27 04:04:12.536 CEST checkpointer[3170] LOG:  checkpoint complete: wrote 784 buffers (4.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.212 s, sync=0.001 s, total=0.230 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4197 kB, estimate=4197 kB
2022-04-27 04:04:12.866 CEST postmaster[3167] LOG:  database system is shut down