Recovery ignores failure to apply log to a new page

A gap in error handling within IORequest::fake_read_complete() was spotted during MDEV-42009 investigations, specifically in the hang part that is now MDEV-42035.
Below is reported the AI-assisted description of the issue, with a suggested fix.

Description

When the log contains an INIT_PAGE record for a page, buf_read_recover() does not read the page from the data file. It submits os_fake_read(), and IORequest::fake_read_complete() builds the page from the log alone (MDEV-29911). This path is used for each page that was initialized after the checkpoint: new tables, B-tree splits, BLOB pages and undo pages.

IORequest::fake_read_complete() ignores a failure of recv_recover_page():

  if (recv_recover_page(reinterpret_cast<buf_block_t*>(bpage),

                        mtr, recs, node->space, init_lsn))

  {

    ut_ad(bpage->oldest_modification() || bpage->is_freed());

    bpage->lock.x_unlock(true);

  }

  recs.being_processed= -1;

When log_phys_t::apply() returns APPLIED_CORRUPTED, recv_recover_page() calls buf_pool_t::corrupted_evict() and returns nullptr. Neither recv_sys.found_corrupt_fs nor recv_sys.found_corrupt_log is set, so srv_start() continues. A later checkpoint discards the log records of the evicted page, and the table stays corrupted. The error log shows Set innodb_force_recovery=1 to ignore corruption., but the server starts.

With innodb_force_recovery=0, APPLIED_CORRUPTED comes from an OPT_PAGE_CHECKSUM mismatch, or from a failure of undo_append(), page_apply_insert_dynamic(), page_apply_insert_redundant(), page_apply_delete_dynamic() or page_apply_delete_redundant(). For a page that the log initialized, this means that the log does not agree with itself, as in MDEV-42009.

The other paths stop the recovery: IORequest::read_complete() calls recv_sys.set_corrupt_fs(), and a malformed record sets found_corrupt_log.

How to repeat

A debug build with this instrumentation makes log_phys_t::apply() return APPLIED_CORRUPTED for pages of a user tablespace that the log initialized (page 0 excluded):

diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc

--- a/storage/innobase/log/log0recv.cc

+++ b/storage/innobase/log/log0recv.cc

@@ -3355,6 +3355,20 @@ static buf_block_t *recv_recover_page(buf_block_t *block, mtr_t &mtr,

 				      block->page.id().page_no()));

 		log_phys_t::apply_status a= l->apply(*block, recs.last_offset);

+#ifndef DBUG_OFF

+		if (a != log_phys_t::APPLIED_NO && init_lsn

+		    && block->page.id().space()

+		    && block->page.id().page_no()

+		    && !srv_is_undo_tablespace(block->page.id().space())

+		    && DBUG_IF("recv_corrupt_fake_read")) {

+			sql_print_error("InnoDB: Simulating corruption on"

+					" [page id: space=%" PRIu32

+					", page number=%" PRIu32 "]",

+					block->page.id().space(),

+					block->page.id().page_no());

+			a = log_phys_t::APPLIED_CORRUPTED;

+		}

+#endif

 		switch (a) {

 		case log_phys_t::APPLIED_NO:

--source include/have_innodb.inc

--source include/have_debug.inc

--source include/have_sequence.inc

--source include/not_embedded.inc

call mtr.add_suppression("InnoDB: Simulating corruption on \\[page id: space=");

call mtr.add_suppression("InnoDB: Plugin initialization aborted");

call mtr.add_suppression("Plugin 'InnoDB' (init function returned error|registration as a STORAGE ENGINE failed)");

SET GLOBAL innodb_log_checkpoint_now=ON;

CREATE TABLE t (a INT PRIMARY KEY) ENGINE=InnoDB;

INSERT INTO t SELECT seq FROM seq_1_to_100;

--source include/kill_mysqld.inc

--let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err

--let SEARCH_PATTERN= InnoDB: Plugin initialization aborted at srv0start\.cc\[\d+\] with error

--let $restart_parameters= --debug-dbug=+d,recv_corrupt_fake_read

--source include/start_mysqld.inc

--source include/search_pattern_in_file.inc

--let $restart_parameters=

--source include/restart_mysqld.inc

CHECK TABLE t;

SELECT COUNT(*) FROM t;

DROP TABLE t;

./mtr --mem innodb.recovery_fake_read_corrupted

Expected: the first restart aborts (FOUND 1 /InnoDB: Plugin initialization aborted.../). The second restart recovers the table: CHECK TABLE is OK and COUNT(*) is 100.

Actual: the first restart completes (NOT FOUND), and after the second restart:

test.t	check	Error	Table `test`.`t` is corrupted. Please drop the table and recreate.

test.t	check	error	Corrupt

An rr trace of the first restart shows corrupted_evict() called from fake_read_complete() for pages 9:1, 9:2 and 9:3 (init_lsn 156481 and 156735), found_corrupt_log=0 found_corrupt_fs=0 after recv_sys.apply(true), and then a checkpoint at LSN 166756. The result is the same with and without the fix of MDEV-42035.

Suggested fix

Flag the log as corrupted in IORequest::fake_read_complete(). The page was built from the log alone, so the failure is in the log, not in the data file. log_phys_t::apply() already calls log_set_corrupt() for a malformed record on the same call path:

  if (recv_recover_page(reinterpret_cast<buf_block_t*>(bpage),

                        mtr, recs, node->space, init_lsn))

  {

    ut_ad(bpage->oldest_modification() || bpage->is_freed());

    bpage->lock.x_unlock(true);

  }

  else

    /* The page was evicted. Prevent the completion of recovery,

    so that a checkpoint will not discard the log. */

    log_set_corrupt();

With innodb_force_recovery>0, log_phys_t::apply() does not return APPLIED_CORRUPTED, so the change has no effect there.