[MDEV-30132] Crash after recovery, with InnoDB: Tried to read ... bytes at offset Created: 2022-11-30  Updated: 2023-02-14  Resolved: 2022-11-30

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Data Definition - Create Table, Storage Engine - InnoDB
Affects Version/s: 10.6, 10.7, 10.8, 10.9, 10.10, 10.11
Fix Version/s: 10.11.2, 10.6.12, 10.7.8, 10.8.7, 10.9.5, 10.10.3

Type: Bug Priority: Blocker
Reporter: Marko Mäkelä Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: affects-tests, corruption, crash, recovery, rr-profile-analyzed

Attachments: File data.tar.xz     Text File encryption_keys.txt    
Issue Links:
Duplicate
Relates
relates to MDEV-13542 Crashing on a corrupted page is unhel... Closed
relates to MDEV-24626 Remove synchronous write of page0 and... Closed
relates to MDEV-30069 InnoDB: Trying to write ... bytes at ... Closed

 Description   

We got a data directory and an rr trace of failed recovery:

2022-11-28 14:25:35 0 [Note] InnoDB: Starting a batch to recover 504 pages from redo log.
 
2022-11-28 14:25:36 0 [Note] InnoDB: Starting a batch to recover 578 pages from redo log.
 
2022-11-28 14:25:37 0 [Note] InnoDB: Starting final batch to recover 295 pages from redo log.
 
...
 
2022-11-28 14:25:37 0 [Note] InnoDB: log sequence number 31381348 (memory-mapped); transaction id 27971
 
...
 
2022-11-28 14:25:39 0 [Note] /data/Server_bin/bb-10.11-new-innodb-defaults_asan_Og/bin/mysqld: ready for connections.
 
...
 
2022-11-28 14:25:40 6 [Warning] InnoDB: 8192 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
 
...
 
2022-11-28 14:25:40 6 [Warning] InnoDB: Retry attempts for reading partial data failed.
 
2022-11-28 14:25:40 6 [ERROR] InnoDB: File (null) was not found
 
2022-11-28 14:25:40 6 [ERROR] [FATAL] InnoDB: Tried to read 8192 bytes at offset 335872, but was only able to read 512.Cannot read from file. OS error number 2.

The fix of MDEV-30069 turns out to be ineffective after all. Before recovery was attempted, there was a file cool_down/t7.ibd that consists of 0x58000 NUL bytes. Recovery would actually shrink the file here:

#0  0x00005643699d96ef in fil_space_extend_must_retry (space=..., node=..., 
    size=..., success=...)
 
    at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/fil/fil0fil.cc:550
 
#1  0x00005643699da7cb in fil_space_t::prepare_acquired (this=...)
 
    at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/fil/fil0fil.cc:667
 
#2  0x00005643699daae4 in fil_space_t::acquire_and_prepare (this=...)
 
    at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/fil/fil0fil.cc:707
 
#3  0x000056436935aba3 in fil_space_t::acquire (this=...)
 
    at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/log/log0recv.cc:956
 
#4  recv_sys_t::recover_deferred (this=..., p=..., name=..., free_block=...)
 
    at /data/Server/bb-10.11-new-innodb-defaults/storage/innobase/log/log0recv.cc:954

We must invoke a special form of fil_space_t::acquire(), or we must set fil_space_t::committed_size based on the actual file size, so that the file will not be shrunk.

Furthermore, the intentional crash during a file read is against the spirit of MDEV-13542. The read error must be propagated up the call stack.

I can reproduce the crash on MariaDB 10.9 (anything later than 10.8 will do) as follows:

tar xJf data.tar.xz
 
mariadbd --innodb-buffer-pool-size=4m --innodb-page-size=8k --innodb-log-file-size=100663296 --datadir "$(pwd)"/data --plugin-dir="$BUILDDIR"/plugin/file_key_management --plugin-load-add=file_key_management.so --file-key-management-filename="$(pwd)"/encryption_keys.txt --innodb-undo-tablespaces=3 &
 
echo 'check table cool_down.t7 extended;'|mariadb -uroot

10.9 9abd70e390bd8ef2e8347677a2aedd00151f0712

 
...
 
2022-11-30  9:08:29 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2106076
 
2022-11-30  9:08:29 0 [Note] InnoDB: Starting a batch to recover 159 pages from redo log.
 
2022-11-30  9:08:30 0 [Note] InnoDB: Starting a batch to recover 255 pages from redo log.
 
2022-11-30  9:08:30 0 [Note] InnoDB: Starting a batch to recover 348 pages from redo log.
 
2022-11-30  9:08:30 0 [Note] InnoDB: Starting a batch to recover 372 pages from redo log.
 
2022-11-30  9:08:30 0 [Note] InnoDB: Starting a batch to recover 429 pages from redo log.
 
2022-11-30  9:08:30 0 [Note] InnoDB: Starting a batch to recover 410 pages from redo log.
 
2022-11-30  9:08:30 0 [Note] InnoDB: Starting a batch to recover 478 pages from redo log.
 
2022-11-30  9:08:30 0 [Note] InnoDB: Opened 3 undo tablespaces
 
2022-11-30  9:08:30 0 [Note] InnoDB: Starting final batch to recover 146 pages from redo log.
 
...
 
Version: '10.9.5-MariaDB-debug'  socket: '/dev/shm/mariadb.sock'  port: 3306  Source distribution
 
2022-11-30  9:08:54 3 [Warning] InnoDB: 8192 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
 
...
 
2022-11-30  9:08:54 3 [Warning] InnoDB: Retry attempts for reading partial data failed.
 
2022-11-30  9:08:54 3 [ERROR] InnoDB: File (null) was not found
 
2022-11-30  9:08:54 3 [ERROR] [FATAL] InnoDB: Tried to read 8192 bytes at offset 335872, but was only able to read 512.Cannot read from file. OS error number 2.

If I use a larger innodb_buffer_pool_size so that everything will be recovered in a single batch, the database will not crash.

 Comments   
Comment by Marko Mäkelä [ 2022-11-30 ]

The following patch will improve upon the fix of MDEV-30069:

diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.cc
 
index 98024bd2769..c59e15da2c7 100644
 
--- a/storage/innobase/fil/fil0fil.cc
 
+++ b/storage/innobase/fil/fil0fil.cc
 
@@ -661,6 +661,7 @@ ATTRIBUTE_COLD bool fil_space_t::prepare_acquired()
 
 
   if (!is_open)
 
     release();
 
+  else if (node->deferred);
 
   else if (auto desired_size= recv_size)
 
   {
 
     bool success;

Comment by Marko Mäkelä [ 2022-11-30 ]

The recovery of the dataset is nondeterministic. After I fixed up something in the MDEV-30069 fix, data.tar.xz recovered each time when I tried it with rr record --chaos.

diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc
 
index 3dcc7e54ab0..b0651d8b8da 100644
 
--- a/storage/innobase/log/log0recv.cc
 
+++ b/storage/innobase/log/log0recv.cc
 
@@ -998,6 +998,7 @@ bool recv_sys_t::recover_deferred(recv_sys_t::map::iterator &p,
 
         {
 
           space->size= node->size= n_pages;
 
           space->set_committed_size();
 
+          goto size_set;
 
         }
 
       }
 
       if (!os_file_set_size(node->name, node->handle,
 
@@ -1007,6 +1008,7 @@ bool recv_sys_t::recover_deferred(recv_sys_t::map::iterator &p,
 
         space->release();
 
         goto release_and_fail;
 
       }
 
+    size_set:
 
       node->deferred= false;
 
       space->release();
 
       it->second.space= space;

Comment by Matthias Leich [ 2022-11-30 ] 

Some results of RQG testing.
 
A simplified RQG test (developed against bb-10.11-new-innodb-defaults) replayed
 
the error patterns
 
- [ 'TBR-1680', 'INFO: Reporter \'CrashRecovery.*\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+\[Warning\] InnoDB: .{1,10} bytes should have been read. Only .{1,10} bytes read. Retrying for the remaining bytes..+InnoDB: Assertion failure in file .{1,250}fil0fil.cc .+InnoDB: Failing assertion: type\.type == IORequest::DBLWR_RECOVER \|\| err == DB_SUCCESS.+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],
 
- [ 'TBR-1682', 'INFO: Reporter \'CrashRecovery.*\': Attempting database recovery using the server.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+\[Warning\] InnoDB: .{1,10} bytes should have been read. Only .{1,10} bytes read. Retrying for the remaining bytes..+\[ERROR\] InnoDB: File \(unknown\): \'read\' returned OS error 0.+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],
 
on origin/10.11 commit fc1403d3a9ef3230324396f621f72f02097c8a6a 2022-11-30T10:41:11+02:00
 
 
 
No replay on origin/10.11, 10.11 b81b1943932a383a92bcd22d053e112198507ae2 2022-11-30T12:59:57+02:00
 
which contains the fixes for
 
- MDEV-30132 Crash after recovery, with InnoDB: Tried to read ...
 
- MDEV-30069 fixup: Do not truncate files on recovery
 
 
 
There was also no replay on origin/10.6 ae6ebafd819d48c965d2615fc78f1f950e0fbf40 2022-11-14T15:44:55+02:00 even though I adjusted the server to the defaults used in 10.11.

Comment by Matthias Leich [ 2022-12-02 ] 

One  testing result which might belong to this MDEV.
 
origin/10.6 6d40274f65b8d145fbf496e9b1b1d46f258de227 2022-11-23T18:13:28+02:00
 
10.6.12
 
Szenario:
 
1. Start server + generate some initial data.
 
2. One session runs a DDL/DML mix
 
3. During 2. is ongoing kill the server intentional
 
4. Restart with success
 
5. As soon as the server is connectable the consistency of table data is checked.
 
    Some SELECT * FROM `cool_down`.`t6` FORCE INDEX (`PRIMARY`)  WHERE `col1` IS NULL OR `col1` IS NOT NULL
 
    leads to the crash of the server
 
Snip of server error log:
 
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61655]2022-12-02  2:09:38 6 [Warning] InnoDB: 16384 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
 
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61659]2022-12-02  2:09:38 6 [Warning] InnoDB: 16384 bytes should have been read. Only 512 bytes read. Retrying for the remaining bytes.
 
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61663]2022-12-02  2:09:38 6 [Warning] InnoDB: Retry attempts for reading partial data failed.
 
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61667]2022-12-02  2:09:38 6 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61671]2022-12-02  2:09:38 6 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61675]2022-12-02  2:09:38 6 [ERROR] InnoDB: File (unknown): 'read' returned OS error 71. Cannot continue operation
 
# 2022-12-02T02:11:07 [3746473] | [rr 3807036 61691]221202  2:09:38 [rr 3807036 61694][ERROR] mysqld got signal 6 ;
 
 
 
(rr) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=21621471700544) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=21621471700544) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=21621471700544, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x0000754155d90476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x0000754155d767f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x0000558ae1be2ece in os_file_handle_error_cond_exit (name=name@entry=0x0, operation=operation@entry=0x558ae2c50ca0 "read", should_abort=should_abort@entry=true, on_error_silent=on_error_silent@entry=false)
 
    at /data/Server/10.6A/storage/innobase/os/os0file.cc:3064
 
#6  0x0000558ae1be99c6 in os_file_read_page (type=..., file=<optimized out>, buf=buf@entry=0x493d3f3cc000, offset=offset@entry=491520, n=n@entry=16384, o=o@entry=0x0, exit_on_err=<optimized out>)
 
    at /data/Server/10.6A/storage/innobase/os/os0file.cc:2950
 
#7  0x0000558ae1bea042 in os_file_read_func (type=..., file=<optimized out>, buf=buf@entry=0x493d3f3cc000, offset=offset@entry=491520, n=n@entry=16384) at /data/Server/10.6A/storage/innobase/os/os0file.cc:3344
 
#8  0x0000558ae1bea326 in os_aio (type=..., buf=buf@entry=0x493d3f3cc000, offset=<optimized out>, n=n@entry=16384) at /data/Server/10.6A/storage/innobase/os/os0file.cc:3790
 
#9  0x0000558ae21365c0 in fil_space_t::io (this=this@entry=0x612000002bc0, type=..., offset=<optimized out>, len=len@entry=16384, buf=<optimized out>, bpage=bpage@entry=0x493d3ede80b0)
 
    at /data/Server/10.6A/storage/innobase/fil/fil0fil.cc:2748
 
#10 0x0000558ae2041cdf in buf_read_page_low (err=err@entry=0x13aa24238a40, space=<optimized out>, sync=sync@entry=true, mode=mode@entry=132, page_id=..., zip_size=zip_size@entry=0, unzip=<optimized out>)
 
    at /data/Server/10.6A/storage/innobase/buf/buf0rea.cc:319
 
#11 0x0000558ae204744f in buf_read_page (page_id=..., zip_size=zip_size@entry=0) at /data/Server/10.6A/storage/innobase/buf/buf0rea.cc:457
 
#12 0x0000558ae1fee0aa in buf_page_get_low (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x13aa24239450, err=<optimized out>, 
    allow_ibuf_merge=<optimized out>) at /data/Server/10.6A/storage/innobase/buf/buf0buf.cc:2496
 
#13 0x0000558ae1ff2663 in buf_page_get_gen (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x13aa24239450, err=0x0, allow_ibuf_merge=false)
 
    at /data/Server/10.6A/storage/innobase/buf/buf0buf.cc:2962
 
#14 0x0000558ae1f62777 in btr_copy_blob_prefix (buf=<optimized out>, len=<optimized out>, id=..., offset=offset@entry=38) at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7404
 
#15 0x0000558ae1f8952e in btr_copy_externally_stored_field_prefix_low (buf=buf@entry=0x6290018e7288 '\276' <repeats 200 times>..., len=len@entry=8193, zip_size=zip_size@entry=0, id=..., id@entry=..., offset=offset@entry=38)
 
    at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7604
 
#16 0x0000558ae1f89e87 in btr_copy_externally_stored_field (len=len@entry=0x13aa24239920, data=data@entry=0x493d3ef4848e "", zip_size=zip_size@entry=0, local_len=0, local_len@entry=20, heap=heap@entry=0x6290018e7200)
 
    at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7704
 
#17 0x0000558ae1f8a27e in btr_rec_copy_externally_stored_field (rec=rec@entry=0x493d3ef48461 "\200", offsets=offsets@entry=0x13aa2423a620, zip_size=0, no=no@entry=7, len=len@entry=0x13aa24239920, heap=heap@entry=0x6290018e7200)
 
    at /data/Server/10.6A/storage/innobase/btr/btr0cur.cc:7761
 
#18 0x0000558ae1dc406d in row_sel_store_mysql_field (mysql_rec=mysql_rec@entry=0x61a0000816b8 "\340\v\001", prebuilt=prebuilt@entry=0x621000091188, rec=rec@entry=0x493d3ef48461 "\200", index=index@entry=0x61600446b008, 
    offsets=offsets@entry=0x13aa2423a620, field_no=7, templ=<optimized out>) at /data/Server/10.6A/storage/innobase/row/row0sel.cc:3019
 
#19 0x0000558ae1dc4d43 in row_sel_store_mysql_rec (mysql_rec=mysql_rec@entry=0x61a0000816b8 "\340\v\001", prebuilt=prebuilt@entry=0x621000091188, rec=0x493d3ef48461 "\200", vrow=0x0, rec_clust=false, index=0x61600446b008, 
    offsets=0x13aa2423a620) at /data/Server/10.6A/storage/innobase/row/row0sel.cc:3236
 
#20 0x0000558ae1de42b8 in row_search_mvcc (buf=buf@entry=0x61a0000816b8 "\340\v\001", mode=<optimized out>, mode@entry=PAGE_CUR_UNSUPP, prebuilt=<optimized out>, match_mode=match_mode@entry=0, direction=direction@entry=1)
 
    at /data/Server/10.6A/storage/innobase/row/row0sel.cc:5683
 
#21 0x0000558ae199fa6c in ha_innobase::general_fetch (this=this@entry=0x61d0001bb2b8, buf=0x61a0000816b8 "\340\v\001", direction=direction@entry=1, match_mode=match_mode@entry=0)
 
    at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:9332
 
#22 0x0000558ae19c5490 in ha_innobase::rnd_next (this=0x61d0001bb2b8, buf=<optimized out>) at /data/Server/10.6A/storage/innobase/handler/ha_innodb.cc:9536
 
#23 0x0000558ae0f24d43 in handler::ha_rnd_next (this=0x61d0001bb2b8, buf=0x61a0000816b8 "\340\v\001") at /data/Server/10.6A/sql/handler.cc:3416
 
#24 0x0000558ae1562e52 in rr_sequential (info=0x62b0000d6c18) at /data/Server/10.6A/sql/records.cc:519
 
#25 0x0000558ae0753b58 in READ_RECORD::read_record (this=0x62b0000d6c18) at /data/Server/10.6A/sql/records.h:81
 
#26 sub_select (join=0x62b0000d3fe0, join_tab=0x62b0000d6b50, end_of_records=false) at /data/Server/10.6A/sql/sql_select.cc:21391
 
#27 0x0000558ae07caa72 in do_select (join=join@entry=0x62b0000d3fe0, procedure=<optimized out>) at /data/Server/10.6A/sql/sql_select.cc:20915
 
#28 0x0000558ae07f43a4 in JOIN::exec_inner (this=this@entry=0x62b0000d3fe0) at /data/Server/10.6A/sql/sql_select.cc:4796
 
#29 0x0000558ae07f46d7 in JOIN::exec (this=this@entry=0x62b0000d3fe0) at /data/Server/10.6A/sql/sql_select.cc:4574
 
#30 0x0000558ae07ee39d in mysql_select (thd=thd@entry=0x62b0000cb218, tables=0x62b0000d2a58, fields=..., conds=0x62b0000d3588, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2148272640, 
    result=0x62b0000d3fb0, unit=0x62b0000cf388, select_lex=0x62b0000d2370) at /data/Server/10.6A/sql/sql_select.cc:5053
 
#31 0x0000558ae07efccd in handle_select (thd=thd@entry=0x62b0000cb218, lex=lex@entry=0x62b0000cf2c0, result=result@entry=0x62b0000d3fb0, setup_tables_done_option=setup_tables_done_option@entry=0)
 
    at /data/Server/10.6A/sql/sql_select.cc:555
 
#32 0x0000558ae064824c in execute_sqlcom_select (thd=thd@entry=0x62b0000cb218, all_tables=<optimized out>) at /data/Server/10.6A/sql/sql_parse.cc:6256
 
#33 0x0000558ae066f6ee in mysql_execute_command (thd=thd@entry=0x62b0000cb218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.6A/sql/sql_parse.cc:3946
 
#34 0x0000558ae067f57e in mysql_parse (thd=thd@entry=0x62b0000cb218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x13aa2423c620) at /data/Server/10.6A/sql/sql_parse.cc:8016
 
#35 0x0000558ae0685db9 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b0000cb218, packet=packet@entry=0x62900164e219 '1' <repeats 200 times>..., packet_length=packet_length@entry=98, 
    blocking=blocking@entry=true) at /data/Server/10.6A/sql/sql_parse.cc:1896
 
--Type <RET> for more, q to quit, c to continue without paging--c
 
#36 0x0000558ae068ae18 in do_command (thd=0x62b0000cb218, blocking=blocking@entry=true) at /data/Server/10.6A/sql/sql_parse.cc:1409
 
#37 0x0000558ae0aa6786 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x608000000e38, put_in_cache=put_in_cache@entry=true) at /data/Server/10.6A/sql/sql_connect.cc:1415
 
#38 0x0000558ae0aa6dec in handle_one_connection (arg=0x608000000e38) at /data/Server/10.6A/sql/sql_connect.cc:1317
 
#39 0x0000754155de2b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#40 0x0000754155e73bb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
 
(rr)

Generated at Thu Feb 08 10:13:53 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.