MySQL Bugs: #96524: --innodb-force-recovery=1 crashes FLUSH BINARY LOGS on debug build

Bug #96524	--innodb-force-recovery=1 crashes FLUSH BINARY LOGS on debug build
Submitted:	13 Aug 2019 14:08	Modified:	22 Oct 2019 10:57
Reporter:	Laurynas Biveinis (OCA)	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S6 (Debug Builds)
Version:	8.0.17	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
MTR -master.opt file:
--innodb-force-recovery=1

MTR .test file:
CREATE DATABASE transforms;

FLUSH BINARY LOGS;

DROP DATABASE transforms;

This results in
...
2019-08-13T14:07:44.075629Z 0 [ERROR] [MY-012803] [InnoDB] innodb_force_recovery is on. We do not allow database modifications by the user. Shut down mysqld and edit my.cnf to set innodb_force_recovery=0
2019-08-13T14:07:44.075968Z 0 [ERROR] [MY-011980] [InnoDB] Error persisting GTIDs to table
2019-08-13T14:07:44.076028Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: clone0repl.cc:451:debug_skip thread 123145462632448
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:07:44 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x62700031e100
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7000098e4be0 thread_stack 0xd2000
0   mysqld                              0x000000010e3eaa5a my_print_stacktrace(unsigned char*, unsigned long) + 250
1   mysqld                              0x000000010a2ef584 handle_fatal_signal + 1092
2   libsystem_platform.dylib            0x00007fff6a88eb5d _sigtramp + 29
3   mysqld                              0x0000000118989008 .str.8 + 1341832
4   libsystem_c.dylib                   0x00007fff6a7486a6 abort + 127
5   mysqld                              0x000000010fe6a0f7 ut_dbg_assertion_failed(char const*, char const*, unsigned long) + 1895
6   mysqld                              0x000000010e94d2ef Clone_persist_gtid::flush_gtids(THD*) + 2927
7   mysqld                              0x000000010e94d9e4 Clone_persist_gtid::periodic_write() + 356
8   mysqld                              0x000000010e967575 std::__1::__bind_return<void (*)(Clone_persist_gtid*), std::__1::tuple<Clone_persist_gtid*>, std::__1::tuple<>, __is_valid_bind_return<void (*)(Clone_persist_gtid*), std::__1::tuple<Clone_persist_gtid*>, std::__1::tuple<> >::value>::type std::__1::__bind<void (*)(Clone_persist_gtid*), Clone_persist_gtid*>::operator()<>() + 261
9   mysqld                              0x000000010e96713a void Runnable::operator()<void (*)(Clone_persist_gtid*), Clone_persist_gtid*>(void (*&&)(Clone_persist_gtid*), Clone_persist_gtid*&&) + 410
10  mysqld                              0x000000010e964e62 void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, Runnable, void (*)(Clone_persist_gtid*), Clone_persist_gtid*> >(void*) + 306
11  libsystem_pthread.dylib             0x00007fff6a8972eb _pthread_body + 126
12  libsystem_pthread.dylib             0x00007fff6a89a249 _pthread_start + 66
13  libsystem_pthread.dylib             0x00007fff6a89640d thread_start + 13

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): 
Connection ID (thread ID): 0
Status: NOT_KILLED

How to repeat:
See above

Add --nowarnings to -master.opt file to see that the test passes in the release build

Hello Laurynas,

Thank you for the report and feedback.
I quickly tried on tarball build but not seeing crash(it fails with warning, even with --nowarnings). Could you please confirm exact cmake commands, gcc etc used in your environment to reproduce this at our end? Thank you.

-
 ./mtr --debug-server --nowarnings Bug96524
Logging: ./mtr  --debug-server --nowarnings Bug96524
MySQL Version 8.0.17
Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/export/umesh/server/binaries/GABuilds/mysql-8.0.17/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[100%] main.Bug96524                             [ fail ]
        Test ended at 2019-08-16 09:17:17

Result file '/export/umesh/server/binaries/GABuilds/mysql-8.0.17/mysql-test/r/Bug96524.result' doesn't exist.
Either create a result file or disable check-testcases and run the test case. Use --nocheck-testcases option to disable check-testcases.

Mysqltest client output from logfile
----------- MYSQLTEST OUTPUT START -----------

CREATE DATABASE transforms;
FLUSH BINARY LOGS;
DROP DATABASE transforms;

------------ MYSQLTEST OUTPUT END -----------

 - the logfile can be found in '/export/umesh/server/binaries/GABuilds/mysql-8.0.17/mysql-test/var/log/main.Bug96524/Bug96524.log'

------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 0.000 of 18 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.Bug96524
--
 ./mtr --debug-server Bug96524
Logging: ./mtr  --debug-server Bug96524
MySQL Version 8.0.17
Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/export/umesh/server/binaries/GABuilds/mysql-8.0.17/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[100%] main.Bug96524                             [ fail ]
        Test ended at 2019-08-16 09:19:47

CURRENT_TEST: main.Bug96524

Could not execute 'check-warnings' for testcase 'main.Bug96524' (res: 1):
mysqltest: At line 64: Query 'LOAD DATA INFILE '$log_warning' INTO TABLE error_log
CHARACTER SET latin1
FIELDS TERMINATED BY 'xykls37' ESCAPED BY ''
  ignore 1 lines
(line)
SET file_name = '$log_error'' failed with wrong error 1881: 'Operation not allowed when innodb_force_recovery > 0.', should have failed with any of '0,1290' errors.
not ok
safe_process[3884]: Child process: 3885, exit: 1
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
CREATE DATABASE transforms;
FLUSH BINARY LOGS;
DROP DATABASE transforms;

Mysqltest client output from logfile
----------- MYSQLTEST OUTPUT START -----------

CREATE DATABASE transforms;
FLUSH BINARY LOGS;
DROP DATABASE transforms;

------------ MYSQLTEST OUTPUT END -----------

 - the logfile can be found in '/export/umesh/server/binaries/GABuilds/mysql-8.0.17/mysql-test/var/log/main.Bug96524/Bug96524.log'

------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 0.000 of 18 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.Bug96524

Sincerely,
Umesh

Perhaps it's -DWITH_INNODB_EXTRA_DEBUG=ON

macOS 10.14.6
$ clang --version
Apple LLVM version 10.0.1 (clang-1001.0.46.4)
Target: x86_64-apple-darwin18.7.0
Thread model: posix
InstalledDir: /Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin

Cmake options: -DBUILD_CONFIG=mysql_release -DCMAKE_EXPORT_COMPILE_COMMANDS=ON -DWITH_PAM=ON -DENABLE_DOWNLOADS=ON -DWITHOUT_TOKUDB=ON -DDOWNLOAD_BOOST=ON -DWITH_BOOST=~/percona/mysql-boost/ -DWITH_ROCKSDB=OFF -DWITH_KEYRING_VAULT=ON -DWITH_AUTHENTICATION_LDAP=ON -DWITH_SYSTEM_LIBS=ON -DWITH_RAPIDJSON=bundled -DWITH_MYSQLX=OFF -DWITH_ICU=/usr/local/opt/icu4c -DDEBUG_EXTNAME=OFF -DWITH_DEBUG=ON -DWITH_INNODB_EXTRA_DEBUG=ON

A duplicate of BUG#97312

Thank you Pedro.

regards,
Umesh