Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2(EOL)
-
None
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.
Attachments
Issue Links
- is duplicated by
-
-
- Closed
-
- relates to
-
-
- Closed
-
Activity
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.
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.
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=0so that I can get a stack trace from every thread. Due to the low reproducibility, running with --manual-gdb is not an option.