Re: pg16: invalid page/page verification failed

On Thu, Oct 05, 2023 at 07:16:31PM +0200, Matthias van de Meent wrote:
> On Thu, 5 Oct 2023 at 18:48, Justin Pryzby <pryzby@telsasoft.com> wrote:
> >
> > On an instance running pg16.0:
> >
> > log_time         | 2023-10-05 10:03:00.014-05
> > backend_type     | autovacuum worker
> > left             | page verification failed, calculated checksum 5074 but expected 5050
> > context          | while scanning block 119 of relation "public.postgres_log_2023_10_05_0900"
> >
> > This is the only error I've seen so far, and for all I know there's a
> > issue on the storage behind the VM, or a cosmic ray hit.  But I moved
> > the table out of the way and saved a copy of get_raw_page() in case
> > someone wants to ask about it.
> >
> > postgres=# SELECT * FROM heap_page_item_attrs(get_raw_page(801594131::regclass::text, 119), 801594131);
> >  lp  | lp_off | lp_flags | lp_len | t_xmin | t_xmax | t_field3 | t_ctid | t_infomask2 | t_infomask | t_hoff |
t_bits| t_oid | t_attrs
 
> >    1 |   2304 |        1 |     16 |        |        |          |        |             |            |        |
|       |
 
> >    2 |   8160 |        1 |     16 |        |        |          |        |             |            |        |
|       |
 
> >    3 |   8144 |        1 |     16 |        |        |          |        |             |            |        |
|       |
 
> > ...all the same except for lp_off...
> >  365 |   2352 |        1 |     16 |        |        |          |        |             |            |        |
|       |
 
> >  366 |   2336 |        1 |     16 |        |        |          |        |             |            |        |
|       |
 
> >  367 |   2320 |        1 |     16 |        |        |          |        |             |            |        |
|       |
 
> 
> That's not a HEAP page; it looks more like a btree page: lp_len is too
> short for heap (which starts at lp_len = 24), and there are too many
> line pointers for an 8KiB heap page. btree often has lp_len of 16: 8
> bytes indextuple header, one maxalign of data (e.g. int or bigint).
> 
> So, assuming it's a block of a different relation kind, then it's also
> likely it was originally located elsewhere in that other relation,
> indeed causing the checksum failure. You can further validate this by
> looking at the page header's pd_special value - if it is 8176, that'd
> be another indicator for it being a btree.

Nice point.

postgres=# SET ignore_checksum_failure=on; SELECT * FROM generate_series(115,119) AS a,
page_header(get_raw_page(801594131::regclass::text,a)) AS b;
 
WARNING:  page verification failed, calculated checksum 5074 but expected 5050
  a  |     lsn      | checksum | flags | lower | upper | special | pagesize | version | prune_xid 
-----+--------------+----------+-------+-------+-------+---------+----------+---------+-----------
 115 | B61/A9436C8  |   -23759 |     4 |    92 |   336 |    8192 |     8192 |       4 |         0
 116 | B61/A944FA0  |     3907 |     4 |   104 |   224 |    8192 |     8192 |       4 |         0
 117 | B61/A946828  |   -24448 |     4 |    76 |   264 |    8192 |     8192 |       4 |         0
 118 | B61/A94CCE0  |    26915 |     4 |    28 |  6256 |    8192 |     8192 |       4 |         0
 119 | B5C/9F30D1C8 |     5050 |     0 |  1492 |  2304 |    8176 |     8192 |       4 |         0

The table itself has a few btree indexes on text columns and a brin
index on log_timestamp, but not on the integers.

It sounds like it's what's expected at this point, but after I
"SET ignore_checksum_failure=on", and read the page in, vacuum kicked
off and then crashed (in heap_page_prune() if that half of the stack
trace can be trusted).

*** stack smashing detected ***: postgres: autovacuum worker postgres terminated

< 2023-10-05 12:35:30.764 CDT  >LOG:  server process (PID 30692) was terminated by signal 11: Segmentation fault
< 2023-10-05 12:35:30.764 CDT  >DETAIL:  Failed process was running: autovacuum: VACUUM ANALYZE
public.BROKEN_postgres_log_2023_10_05_0900

I took the opportunity to fsck the FS, which showed no errors.

I was curious if the relfilenodes had gotten confused/corrupted/??
But this seems to indicate not; the problem is only one block.

postgres=# SELECT oid, relfilenode, oid=relfilenode, relname FROM pg_class WHERE oid BETWEEN 801550000 AND 801594199
ORDERBY 1;
 
    oid    | relfilenode | ?column? |                     relname                     
-----------+-------------+----------+-------------------------------------------------
 801564542 |   801564542 | t        | postgres_log_2023_10_05_0800
 801564545 |   801564545 | t        | pg_toast_801564542
 801564546 |   801564546 | t        | pg_toast_801564542_index
 801564547 |   801564547 | t        | postgres_log_2023_10_05_0800_log_time_idx
 801564548 |   801564548 | t        | postgres_log_2023_10_05_0800_error_severity_idx
 801564549 |   801564549 | t        | postgres_log_2023_10_05_0800_error_message_idx
 801564550 |   801564550 | t        | postgres_log_2023_10_05_0800_duration_idx
 801564551 |   801564551 | t        | postgres_log_2023_10_05_0800_tempfile_idx
 801594131 |   801594131 | t        | BROKEN_postgres_log_2023_10_05_0900
 801594134 |   801594134 | t        | pg_toast_801594131
 801594135 |   801594135 | t        | pg_toast_801594131_index
 801594136 |   801594136 | t        | postgres_log_2023_10_05_0900_log_time_idx
 801594137 |   801594137 | t        | postgres_log_2023_10_05_0900_error_severity_idx
 801594138 |   801594138 | t        | postgres_log_2023_10_05_0900_error_message_idx
 801594139 |   801594139 | t        | postgres_log_2023_10_05_0900_duration_idx
 801594140 |   801594140 | t        | postgres_log_2023_10_05_0900_tempfile_idx

Before anybody asks, we didn't retain WAL from this morning.

FYI, the storage is ext4/LVM/scsi (it looks like this didn't use
vmw_pvscsi but an emulated hardware driver).

/dev/mapper/data-postgres on /var/lib/pgsql type ext4 (rw,relatime,seclabel,data=ordered)
[    0.000000] Linux version 3.10.0-1160.el7.x86_64 (mockbuild@kbuilder.bsys.centos.org) (gcc version 4.8.5 20150623
(RedHat 4.8.5-44) (GCC) ) #1 SMP Mon Oct 19 16:18:59 UTC 2020
 
[    1.446380] scsi 2:0:1:0: Direct-Access     VMware   Virtual disk     1.0  PQ: 0 ANSI: 2
[    1.470764] scsi target2:0:1: Beginning Domain Validation
[    1.471077] scsi target2:0:1: Domain Validation skipping write tests
[    1.471079] scsi target2:0:1: Ending Domain Validation
[    1.471099] scsi target2:0:1: FAST-40 WIDE SCSI 80.0 MB/s ST (25 ns, offset 127)
[    1.484109] sd 2:0:1:0: [sdb] 1048576000 512-byte logical blocks: (536 GB/500 GiB)
[    1.484136] sd 2:0:1:0: [sdb] Write Protect is off
[    1.484139] sd 2:0:1:0: [sdb] Mode Sense: 45 00 00 00
[    1.484163] sd 2:0:1:0: [sdb] Write cache: disabled, read cache: disabled, doesn't support DPO or FUA
[    1.485808] sd 2:0:1:0: [sdb] Attached SCSI disk
[    4.271339] sd 2:0:1:0: Attached scsi generic sg1 type 0

-- 
Justin