[MDEV-24751] runtime error: member call on null pointer of type 'struct fil_space_t' in innodb_shutdown Created: 2021-02-01  Updated: 2021-03-24  Resolved: 2021-02-01

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: N/A
Fix Version/s: 10.3.28, 10.4.18, 10.5.9

Type: Bug Priority: Blocker
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: not-10.2, regression

Issue Links:
Duplicate
is duplicated by MDEV-25239 UBSAN: srv0start.cc:2069:31: runtime ... Closed
Problem/Incident
is caused by MDEV-24340 Unique final message of InnoDB during... Closed

 Description   

I have observed the following UBSAN error a number of times:

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Optimized)

 
2021-02-01 19:32:05 0 [Note] InnoDB: Starting shutdown...
 
2021-02-01 19:32:05 0 [Note] InnoDB: Dumping buffer pool(s) to /test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-opt/data/ib_buffer_pool
 
2021-02-01 19:32:05 0 [Note] InnoDB: Buffer pool(s) dump completed at 210201 19:32:05
 
/data/builds/10.6_opt_san/storage/innobase/srv/srv0start.cc:2069:31: runtime error: member call on null pointer of type 'struct fil_space_t'
 
    #0 0x559f02ac897c in innodb_shutdown() /data/builds/10.6_opt_san/storage/innobase/srv/srv0start.cc:2069
 
    #1 0x559f0234cd0a in innobase_end /data/builds/10.6_opt_san/storage/innobase/handler/ha_innodb.cc:3762
 
    #2 0x559f0234cd0a in innobase_end /data/builds/10.6_opt_san/storage/innobase/handler/ha_innodb.cc:3749
 
    #3 0x559f00868082 in ha_finalize_handlerton(st_plugin_int*) /data/builds/10.6_opt_san/sql/handler.cc:583
 
    #4 0x559eff6a23c1 in plugin_deinitialize /data/builds/10.6_opt_san/sql/sql_plugin.cc:1262
 
    #5 0x559eff6b78a5 in reap_plugins /data/builds/10.6_opt_san/sql/sql_plugin.cc:1338
 
    #6 0x559eff6bc312 in plugin_shutdown() /data/builds/10.6_opt_san/sql/sql_plugin.cc:2045
 
    #7 0x559efef806e1 in clean_up /data/builds/10.6_opt_san/sql/mysqld.cc:1981
 
    #8 0x559efefa845c in clean_up /data/builds/10.6_opt_san/sql/mysqld.cc:1947
 
    #9 0x559efefa845c in mysqld_main(int, char**) /data/builds/10.6_opt_san/sql/mysqld.cc:5728
 
    #10 0x14d06e6440b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x270b2)
 
    #11 0x559efee4e32d in _start (/test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-opt/bin/mariadbd+0x762b32d)
 
 
 
2021-02-01 19:32:06 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2021-02-01 19:32:06 0 [Note] InnoDB: Shutdown completed; log sequence number 42670; transaction id 19
 
2021-02-01 19:32:06 0 [Note] /test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-opt/bin/mysqld: Shutdown complete

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Debug)

 
2021-02-01 19:30:38 0 [Note] InnoDB: Starting shutdown...
 
2021-02-01 19:30:38 0 [Note] InnoDB: Dumping buffer pool(s) to /test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-dbg/data/ib_buffer_pool
 
2021-02-01 19:30:38 0 [Note] InnoDB: Buffer pool(s) dump completed at 210201 19:30:38
 
/data/builds/10.6_dbg_san/storage/innobase/srv/srv0start.cc:2069:31: runtime error: member call on null pointer of type 'struct fil_space_t'
 
    #0 0x55bbe01d544f in innodb_shutdown() /data/builds/10.6_dbg_san/storage/innobase/srv/srv0start.cc:2069
 
    #1 0x55bbdf988457 in innobase_end /data/builds/10.6_dbg_san/storage/innobase/handler/ha_innodb.cc:3762
 
    #2 0x55bbddbe5122 in ha_finalize_handlerton(st_plugin_int*) /data/builds/10.6_dbg_san/sql/handler.cc:583
 
    #3 0x55bbdc680210 in plugin_deinitialize /data/builds/10.6_dbg_san/sql/sql_plugin.cc:1262
 
    #4 0x55bbdc68f57c in reap_plugins /data/builds/10.6_dbg_san/sql/sql_plugin.cc:1338
 
    #5 0x55bbdc693530 in plugin_shutdown() /data/builds/10.6_dbg_san/sql/sql_plugin.cc:2045
 
    #6 0x55bbdbdcb6a9 in clean_up /data/builds/10.6_dbg_san/sql/mysqld.cc:1981
 
    #7 0x55bbdbdfa8ed in mysqld_main(int, char**) /data/builds/10.6_dbg_san/sql/mysqld.cc:5728
 
    #8 0x55bbdbdc3baa in main /data/builds/10.6_dbg_san/sql/main.cc:25
 
    #9 0x14baa0b0b0b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x270b2)
 
    #10 0x55bbdbc975ad in _start (/test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-dbg/bin/mariadbd+0x7b275ad)
 
 
 
2021-02-01 19:30:39 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2021-02-01 19:30:39 0 [Note] InnoDB: Shutdown completed; log sequence number 43218; transaction id 19
 
2021-02-01 19:30:39 0 [Note] /test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld: Shutdown complete

Nothing special needed, just init data dir (and data dir can be wiped before doing so):

rm -Rf /test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-opt/data
 
/test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-opt/scripts/mariadb-install-db --no-defaults --force --auth-root-authentication-method=normal --basedir=/test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-opt --datadir=/test/UBASAN_MD260121-mariadb-10.6.0-linux-x86_64-opt/data

Setup:

Compiled with GCC >=7.5.0 (I use GCC 9.3.0) and:
 
    -DWITH_ASAN=ON -DWITH_ASAN_SCOPE=ON -DWITH_UBSAN=ON -DWITH_RAPID=OFF -DWSREP_LIB_WITH_ASAN=ON 
Set before execution:
 
    export ASAN_OPTIONS=quarantine_size_mb=512:atexit=1:detect_invalid_pointer_pairs=3:dump_instruction_bytes=1:abort_on_error=1
 
    export UBSAN_OPTIONS=print_stacktrace=1

Bug confirmed present in:
MariaDB: 10.3.28 (dbg), 10.3.28 (opt), 10.4.18 (dbg), 10.4.18 (opt), 10.5.9 (dbg), 10.5.9 (opt), 10.6.0 (dbg), 10.6.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.37 (dbg), 10.2.37 (opt),



 Comments   
Comment by Roel Van de Paar [ 2021-02-01 ]

Issue confirmed not visible, using 10.6 debug 8a495d7f90f64566d083d9ccd04cd95023a40931, with this patch from Marko:

diff --git a/storage/innobase/srv/srv0start.cc b/storage/innobase/srv/srv0start.cc
 
index b0bc3d3ede9..1ca24926ed0 100644
 
--- a/storage/innobase/srv/srv0start.cc
 
+++ b/storage/innobase/srv/srv0start.cc
 
@@ -2103,7 +2103,9 @@ void innodb_shutdown()
 
 
 	srv_sys_space.shutdown();
 
 	if (srv_tmp_space.get_sanity_check_status()) {
 
-		fil_system.temp_space->close();
 
+		if (fil_system.temp_space) {
 
+			fil_system.temp_space->close();
 
+		}
 
 		srv_tmp_space.delete_files();
 
 	}
 
 	srv_tmp_space.shutdown();

10.6.0 8a495d7f90f64566d083d9ccd04cd95023a40931 (Debug)

 
2021-02-01 21:36:38 0 [Note] InnoDB: Starting shutdown...
 
2021-02-01 21:36:38 0 [Note] InnoDB: Dumping buffer pool(s) to /test/UBASAN_MD010221-mariadb-10.6.0-linux-x86_64-dbg/data/ib_buffer_pool
 
2021-02-01 21:36:38 0 [Note] InnoDB: Buffer pool(s) dump completed at 210201 21:36:38
 
2021-02-01 21:36:39 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2021-02-01 21:36:39 0 [Note] InnoDB: Shutdown completed; log sequence number 43218; transaction id 19
 
2021-02-01 21:36:39 0 [Note] /test/UBASAN_MD010221-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld: Shutdown complete

Comment by Marko Mäkelä [ 2021-02-01 ]

As far as I can tell, this bug is a regression that was caused by MDEV-24340. It looks like 10.3 could be affected as well. Maybe the test case for repeating it depends on some other changes that are only present in 10.5, such as MDEV-23855?
The fix is simple:

diff --git a/storage/innobase/srv/srv0start.cc b/storage/innobase/srv/srv0start.cc
 
index f7ea8c985f6..735ec7126b4 100644
 
--- a/storage/innobase/srv/srv0start.cc
 
+++ b/storage/innobase/srv/srv0start.cc
 
@@ -2656,7 +2656,9 @@ void innodb_shutdown()
 
 
 	srv_sys_space.shutdown();
 
 	if (srv_tmp_space.get_sanity_check_status()) {
 
-		fil_system.temp_space->close();
 
+		if (fil_system.temp_space) {
 
+			fil_system.temp_space->close();
 
+		}
 
 		srv_tmp_space.delete_files();
 
 	}
 
 	srv_tmp_space.shutdown();

10.2 is not affected, because MDEV-12266 was fixed only in 10.3.

Comment by Roel Van de Paar [ 2021-02-02 ]

marko Indeed. 10.3 And 10.4 now confirmed also. Not sure why that was missed originally. Not present in 10.2

Generated at Thu Feb 08 09:32:23 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.