[MDEV-13452] Assertion `!recv_no_log_write' failed in lsn_t log_reserve_and_open Created: 2017-08-04  Updated: 2017-08-23  Resolved: 2017-08-07

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2
Fix Version/s: 10.2.9

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File recv_no_log_write.test    
Issue Links:
Duplicate
is duplicated by MDEV-13616 innodb.innodb-64k-crash 'innodb' fai... Closed
Relates
relates to MDEV-13451 Assertion `!recv_no_ibuf_operations' ... Closed

 Description   

10.2 6d51817d2cd79edbc15328bef532a5375f184219

 
2017-08-04 18:04:05 140563532476480 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-08-04 18:04:05 140563532476480 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1633912
 
2017-08-04 18:04:05 140563532476480 [Note] InnoDB: Starting a batch to recover 272 pages from redo log.
 
mysqld: /data/src/10.2/storage/innobase/log/log0log.cc:362: lsn_t log_reserve_and_open(ulint): Assertion `!recv_no_log_write' failed.
 
170804 18:04:06 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fd77d360ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x0000558b60644192 in log_reserve_and_open (len=199) at /data/src/10.2/storage/innobase/log/log0log.cc:362
 
#9  0x0000558b60663365 in mtr_t::Command::finish_write (this=0x7ffd21be28a0, len=199) at /data/src/10.2/storage/innobase/mtr/mtr0mtr.cc:899
 
#10 0x0000558b6066248d in mtr_t::commit_checkpoint (this=0x7ffd21be2920, checkpoint_lsn=1633912, write_mlog_checkpoint=true) at /data/src/10.2/storage/innobase/mtr/mtr0mtr.cc:623
 
#11 0x0000558b608bf759 in fil_names_clear (lsn=1633912, do_write=true) at /data/src/10.2/storage/innobase/fil/fil0fil.cc:6580
 
#12 0x0000558b60656171 in recv_recovery_from_checkpoint_start (flush_lsn=1633893) at /data/src/10.2/storage/innobase/log/log0recv.cc:3353
 
#13 0x0000558b6076c187 in innobase_start_or_create_for_mysql () at /data/src/10.2/storage/innobase/srv/srv0start.cc:2219
 
#14 0x0000558b605acf99 in innobase_init (p=0x558b63c40210) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:4422
 
#15 0x0000558b602a41b3 in ha_initialize_handlerton (plugin=0x558b63b4d430) at /data/src/10.2/sql/handler.cc:512
 
#16 0x0000558b6004e9e3 in plugin_initialize (tmp_root=0x7ffd21bea9b0, plugin=0x558b63b4d430, argc=0x558b61578770 <remaining_argc>, argv=0x558b63a04370, options_only=false) at /data/src/10.2/sql/sql_plugin.cc:1413
 
#17 0x0000558b6004f5ec in plugin_init (argc=0x558b61578770 <remaining_argc>, argv=0x558b63a04370, flags=2) at /data/src/10.2/sql/sql_plugin.cc:1695
 
#18 0x0000558b5ff5c062 in init_server_components () at /data/src/10.2/sql/mysqld.cc:5255
 
#19 0x0000558b5ff5d0e7 in mysqld_main (argc=144, argv=0x558b63a04370) at /data/src/10.2/sql/mysqld.cc:5845
 
#20 0x0000558b5ff51fc0 in main (argc=22, argv=0x7ffd21beb748) at /data/src/10.2/sql/main.cc:25

Test case is attached.
Run it with --repeat=N --force-restart --mem. Sometimes it fails with the assertion failure from MDEV-13451, but mostly with this one.

 Comments   
Comment by Marko Mäkelä [ 2017-08-07 ]

This assertion fails nondeterministically during recovery. When retrying startup with the same dataset (re-applying the same redo log), no crash is observed.
I will try to reproduce with

ASAN_OPTIONS=abort_on_error=1:disable_coredump=0

so that I can get a stack trace from every thread. Due to the low reproducibility, running with --manual-gdb is not an option.

Comment by Marko Mäkelä [ 2017-08-07 ]

Stack trace:

#7  0x00007fb3bdbe8f12 in __GI___assert_fail (assertion=0x309e880 <.str.12> "!recv_no_log_write", file=0x309e380 <.str> "/mariadb/10.2/storage/innobase/log/log0log.cc", line=362, function=0x309e820 <__PRETTY_FUNCTION__._Z20log_reserve_and_openm> "lsn_t log_reserve_and_open(ulint)") at assert.c:101
 
#8  0x0000000001ad095c in log_reserve_and_open (len=199) at /mariadb/10.2/storage/innobase/log/log0log.cc:362
 
#9  0x0000000001b238eb in mtr_t::Command::finish_write (this=0x7fff22f3a780, len=199) at /mariadb/10.2/storage/innobase/mtr/mtr0mtr.cc:899
 
#10 0x0000000001b23100 in mtr_t::commit_checkpoint (this=0x7fff22f3a980, checkpoint_lsn=1633912, write_mlog_checkpoint=true) at /mariadb/10.2/storage/innobase/mtr/mtr0mtr.cc:623
 
#11 0x00000000021b37aa in fil_names_clear (lsn=1633912, do_write=true) at /mariadb/10.2/storage/innobase/fil/fil0fil.cc:6580

This code would only be executed in a ‘slow path’. Normally, mtr_t::Command::finish_write() would invoke log_reserve_and_write_fast(), which does not contain the assertion.

This bug affects debug builds only. There is no real harm done; only a misplaced debug assertion is failing.

Comment by Marko Mäkelä [ 2017-08-23 ]

The fix in MariaDB 10.2.8 was insufficient. On the very same call path, log_close() would trigger the same debug assertion, as witnessed on buildbot:
http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/4961/steps/test/logs/stdio

2017-08-23  1:22:13 3876 [Note] InnoDB: Starting crash recovery from checkpoint LSN=22835950
 
2017-08-23  1:22:13 3876 [Note] InnoDB: Starting a batch to recover 201 pages from redo log.
 
2017-08-23  1:22:14 3876 [Note] InnoDB: Starting a batch to recover 168 pages from redo log.
 
Assertion failed: !recv_no_log_write, file D:\winx64-debug\build\src\storage\innobase\log\log0log.cc, line 487
 
…
 
mysqld.exe!_wassert()[assert.cpp:404]
 
mysqld.exe!log_close()[log0log.cc:487]
 
mysqld.exe!mtr_t::Command::finish_write()[mtr0mtr.cc:907]
 
mysqld.exe!mtr_t::commit_checkpoint()[mtr0mtr.cc:625]
 
mysqld.exe!fil_names_clear()[fil0fil.cc:6589]
 
mysqld.exe!recv_recovery_from_checkpoint_start()[log0recv.cc:3346]
 
mysqld.exe!innobase_start_or_create_for_mysql()[srv0start.cc:2222]

The fix (which will be in MariaDB 10.2.9) is simple: remove the assertion from log_close(). Every caller that requires this assertion already contains it.

This bug only affects the debug server startup. It has no impact on production (non-debug) servers.

Generated at Thu Feb 08 08:05:42 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.