Date: Sun, 4 Sep 2022 19:23:20 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Michael Paquier <michael@paquier.xyz>
Cc: Andrey Borodin <x4mmm@yandex-team.ru>, pgsql-hackers@postgresql.org,
	Thomas Munro <thomas.munro@gmail.com>, Peter Geoghegan <pg@bowt.ie>,
	Andres Freund <andres@anarazel.de>
Subject: Re: Different compression methods for FPI
Message-ID: <20220905002320.GD31833@telsasoft.com>
References: <20210321193004.GA4203@telsasoft.com>
 <YKIelANwse+k2JxT@paquier.xyz>
 <20210519030618.GS373@telsasoft.com>
 <YKTa4+kTFkb3EIBs@paquier.xyz>
 <20210525044444.GV3676@telsasoft.com>
 <YKymshLnYZeD0cue@paquier.xyz>
 <3252174C-C21D-4711-A038-5230DE465BAE@yandex-team.ru>
 <YLWWPaq/KnVS24J4@paquier.xyz>
 <20210614012412.GA31772@telsasoft.com>
 <20220902115511.GY31833@telsasoft.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20220902115511.GY31833@telsasoft.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20220905002320.GD31833%40telsasoft.com>
Precedence: bulk

On Fri, Sep 02, 2022 at 06:55:11AM -0500, Justin Pryzby wrote:
> On Sun, Jun 13, 2021 at 08:24:12PM -0500, Justin Pryzby wrote:
> > In this patch series, I added compression information to the errcontext from
> > xlog_block_info(), and allow specifying compression levels like zlib-2.  I'll
> > rearrange that commit earlier if we decide that's desirable to include.
> 
> 4035cd5d4 added wal_compress=lz4 and
> e9537321a added wal_compress=zstd
> 
> Since 4035cd5d4, pg_waldump has shown compression info (and walinspect
> shows the same since 2258e76f9).
> 
> But if you try to replay WAL on a server which wasn't compiled with
> support for the requisite compression methods, it's a bit crummy that it
> doesn't include in the error message the reason *why* it failed to
> restore the image, if that's caused by the missing compression method.

That's also hitting an elog().

2022-09-04 15:56:29.916 CDT startup[2625] FATAL:  XX000: failed to restore block image
2022-09-04 15:56:29.916 CDT startup[2625] DETAIL:  image at 0/1D11CB8 compressed with zstd not supported by build, block 0
2022-09-04 15:56:29.916 CDT startup[2625] CONTEXT:  WAL redo at 0/1D11CB8 for Heap/DELETE: off 50 flags 0x00 KEYS_UPDATED ; blkref #0: rel 1663/16384/2610, blk 4 FPW
2022-09-04 15:56:29.916 CDT startup[2625] LOCATION:  XLogReadBufferForRedoExtended, xlogutils.c:396

(gdb) bt
#0  report_invalid_record (state=0x555555e33ff0, fmt=0x555555b1c1a8 "image at %X/%X compressed with %s not supported by build, block %d") at xlogreader.c:74
#1  0x00005555556beeec in RestoreBlockImage (record=record@entry=0x555555e33ff0, block_id=block_id@entry=0 '\000', page=page@entry=0x7fffee9bdc00 "") at xlogreader.c:2078
#2  0x00005555556c5d39 in XLogReadBufferForRedoExtended (record=record@entry=0x555555e33ff0, block_id=block_id@entry=0 '\000', mode=mode@entry=RBM_NORMAL, get_cleanup_lock=get_cleanup_lock@entry=false, 
    buf=buf@entry=0x7fffffffd760) at xlogutils.c:395
#3  0x00005555556c5e4a in XLogReadBufferForRedo (record=record@entry=0x555555e33ff0, block_id=block_id@entry=0 '\000', buf=buf@entry=0x7fffffffd760) at xlogutils.c:320
#4  0x000055555565bd5b in heap_xlog_delete (record=0x555555e33ff0) at heapam.c:9032
#5  0x00005555556622b7 in heap_redo (record=<optimized out>) at heapam.c:9836
#6  0x00005555556c15ed in ApplyWalRecord (xlogreader=0x555555e33ff0, record=record@entry=0x7fffee2b6820, replayTLI=replayTLI@entry=0x7fffffffd870) at ../../../../src/include/access/xlog_internal.h:379
#7  0x00005555556c4c30 in PerformWalRecovery () at xlogrecovery.c:1725
#8  0x00005555556b7f23 in StartupXLOG () at xlog.c:5291
#9  0x0000555555ac4491 in InitPostgres (in_dbname=in_dbname@entry=0x555555e09390 "postgres", dboid=dboid@entry=0, username=username@entry=0x555555dedda0 "pryzbyj", useroid=useroid@entry=0, 
    load_session_libraries=<optimized out>, override_allow_connections=override_allow_connections@entry=false, out_dbname=0x0) at postinit.c:731
#10 0x000055555598471f in PostgresMain (dbname=0x555555e09390 "postgres", username=username@entry=0x555555dedda0 "pryzbyj") at postgres.c:4085
#11 0x00005555559851b0 in PostgresSingleUserMain (argc=5, argv=0x555555de7530, username=0x555555dedda0 "pryzbyj") at postgres.c:3986
#12 0x0000555555840533 in main (argc=5, argv=0x555555de7530) at main.c:194

I guess it should be promoted to an ereport(), since it's now a
user-facing error rathere than an internal one.

$ ./tmp_install.without-zstd/usr/local/pgsql/bin/postgres -D ./src/test/regress/tmp_check/data
2022-09-04 15:28:37.446 CDT postmaster[29964] LOG:  starting PostgreSQL 16devel on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit
2022-09-04 15:28:37.446 CDT postmaster[29964] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2022-09-04 15:28:37.528 CDT postmaster[29964] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2022-09-04 15:28:37.587 CDT startup[29972] LOG:  database system was interrupted while in recovery at 2022-09-04 15:27:44 CDT
2022-09-04 15:28:37.587 CDT startup[29972] HINT:  This probably means that some data is corrupted and you will have to use the last backup for recovery.
2022-09-04 15:28:38.010 CDT startup[29972] LOG:  database system was not properly shut down; automatic recovery in progress
2022-09-04 15:28:38.038 CDT startup[29972] LOG:  redo starts at 0/1D118C0
2022-09-04 15:28:38.039 CDT startup[29972] LOG:  could not stat file "pg_tblspc/16502": No such file or directory
2022-09-04 15:28:38.039 CDT startup[29972] CONTEXT:  WAL redo at 0/1D11970 for Tablespace/DROP: 16502
2022-09-04 15:28:38.039 CDT startup[29972] FATAL:  failed to restore block image
2022-09-04 15:28:38.039 CDT startup[29972] DETAIL:  image at 0/1D11CB8 compressed with zstd not supported by build, block 0
2022-09-04 15:28:38.039 CDT startup[29972] CONTEXT:  WAL redo at 0/1D11CB8 for Heap/DELETE: off 50 flags 0x00 KEYS_UPDATED ; blkref #0: rel 1663/16384/2610, blk 4 FPW

diff --git a/src/backend/access/transam/xlogutils.c b/src/backend/access/transam/xlogutils.c
index 0cda22597fe..01c7454bcc7 100644
--- a/src/backend/access/transam/xlogutils.c
+++ b/src/backend/access/transam/xlogutils.c
@@ -393,7 +393,11 @@ XLogReadBufferForRedoExtended(XLogReaderState *record,
 									  prefetch_buffer);
 		page = BufferGetPage(*buf);
 		if (!RestoreBlockImage(record, block_id, page))
-			elog(ERROR, "failed to restore block image");
+			ereport(ERROR,
+					errcode(ERRCODE_FEATURE_NOT_SUPPORTED),
+					errmsg("failed to restore block image"),
+					errdetail("%s", record->errormsg_buf));
+
 
 		/*
 		 * The page may be uninitialized. If so, we can't set the LSN because