MySQL Bugs: #100838: Alter table causes crash + missing tablespace after restart

Bug #100838	Alter table causes crash + missing tablespace after restart
Submitted:	14 Sep 2020 10:55	Modified:	22 Nov 2021 9:53
Reporter:	Eric de Ruiter	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	8.0.19	OS:	Ubuntu
Assigned to:		CPU Architecture:	x86

Description:
During the execution a database migrations for our application we encountered a mysql crash (see backtrace below)
The migration in question was a simple alter table which added 3 new fields to an existing table (full query + table structure included in private comment). 
This query was successful run in our test environment which has an identical hw/database setup.

After the crash the mysql server was automatically restarted. But after the restart all queries to the table in question resulted in the following error.

   SQLSTATE[HY000]: General error: 1812 Tablespace is missing for table `xxxxxxxxx-xxx-xxxxxxx`.`xxxxxxxxx`

We ended up restoring the table from the secondary master.

After the restore the exact same migration was run without a crash.

-------------------------- backtrace -----------------------------------------------

12:05:03 UTC - mysqld got signal 11 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x7f2334a2dd60
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 = 7f2438459d50 thread_stack 0x46000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x3d) [0x563860de378d]
/usr/sbin/mysqld(handle_fatal_signal+0x303) [0x56385fe7d553]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x128a0) [0x7f26f0a468a0]
/usr/sbin/mysqld(mem_heap_free_block_free(mem_block_info_t*)+0x1c) [0x56386109f35c]
/usr/sbin/mysqld(row_mysql_prebuilt_free_blob_heap(row_prebuilt_t*)+0x30) [0x563860fd9320]
/usr/sbin/mysqld(ha_innobase::end_stmt()+0x26) [0x563860ea8c86]
/usr/sbin/mysqld(close_thread_table(THD*, TABLE**)+0x138) [0x56385fccd668]
/usr/sbin/mysqld(+0xe1d55f) [0x56385fcce55f]
/usr/sbin/mysqld(close_all_tables_for_name(THD*, TABLE_SHARE*, bool, TABLE*)+0x7e) [0x56385fcce61e]
/usr/sbin/mysqld(+0xd540f9) [0x56385fc050f9]
/usr/sbin/mysqld(mysql_alter_table(THD*, char const*, char const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*)+0x89bc) [0x56385fde64cc]
/usr/sbin/mysqld(Sql_cmd_alter_table::execute(THD*)+0x9c5) [0x56386018e2a5]
/usr/sbin/mysqld(mysql_execute_command(THD*, bool)+0x2811) [0x56385fd52741]
/usr/sbin/mysqld(Prepared_statement::execute(String*, bool)+0x7d4) [0x56385fd7e324]
/usr/sbin/mysqld(Prepared_statement::execute_loop(String*, bool)+0xb2) [0x56385fd80d32]
/usr/sbin/mysqld(mysqld_stmt_execute(THD*, Prepared_statement*, bool, unsigned long, PS_PARAM*)+0x189) [0x56385fd82449]
/usr/sbin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0xdef) [0x56385fd55c1f]
/usr/sbin/mysqld(do_command(THD*)+0x1c4) [0x56385fd57964]
/usr/sbin/mysqld(+0xfbd800) [0x56385fe6e800]
/usr/sbin/mysqld(+0x244b909) [0x5638612fc909]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7f26f0a3b6db]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f26eec62a3f]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f2335178f08): is an invalid pointer
Connection ID (thread ID): 1404340
Status: NOT_KILLED

How to repeat:
I was unable to reproduce it (as the migration ran without issues on our test / acceptance environments and also ran without issues afterwards)

Suggested fix:
The invalid tablespace issue after restart looks like this bug: https://bugs.mysql.com/bug.php?id=99174

This however does not explain the crash

Hi,

Can't reproduce this. You do seem to be affected by Bug#99174 but I'm not able to reproduce whole thing you experienced.

This also happened in MySQL 5.7. But unfortunately, the same is not reproducible.

2021-09-04T13:54:21.615341+08:00 19854251 [Note] Aborted connection 19854251 to db: 'norwex_live' user: 'root' host: '192.168.1.212' (Got an error reading communication packets)
14:41:20 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=16777216
read_buffer_size=262144
max_used_connections=59
max_threads=0
thread_count=2
connection_count=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 50446 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f3135ee3800
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 = 7f3139fbb510 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x3b)[0xf715bb]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x461)[0x7f4641]
/lib64/libpthread.so.0(+0xf100)[0x7f32b8d7f100]
/usr/local/mysql/bin/mysqld(_Z24mem_heap_free_block_freeP16mem_block_info_t+0x54)[0x1074514]
/usr/local/mysql/bin/mysqld(_Z33row_mysql_prebuilt_free_blob_heapP14row_prebuilt_t+0x30)[0x10eac00]
/usr/local/mysql/bin/mysqld(_ZN11ha_innobase8end_stmtEv+0x26)[0xffdc86]
/usr/local/mysql/bin/mysqld(_Z18close_thread_tableP3THDPP5TABLE+0x292)[0xcb9592]
/usr/local/mysql/bin/mysqld(_Z25close_all_tables_for_nameP3THDP11TABLE_SHAREbP5TABLE+0x1d6)[0xcc2506]
/usr/local/mysql/bin/mysqld(_Z17mysql_alter_tableP3THDPKcS2_P24st_ha_create_informationP10TABLE_LISTP10Alter_info+0x44a4)[0xd8b604]
/usr/local/mysql/bin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x591)[0xe94731]
/usr/local/mysql/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x8d8)[0xd14d28]
/usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x3ad)[0xd1a53d]
/usr/local/mysql/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xb76)[0xd1b196]
/usr/local/mysql/bin/mysqld(_Z10do_commandP3THD+0x1c7)[0xd1cca7]
/usr/local/mysql-5.7.27-1-linux-x86_64/lib/plugin/threadpool.so(_Z26threadpool_process_requestP3THD+0xf3)[0x7f312f5b4c23]
/usr/local/mysql-5.7.27-1-linux-x86_64/lib/plugin/threadpool.so(+0x5b8e)[0x7f312f5b5b8e]
/lib64/libpthread.so.0(+0x7dc5)[0x7f32b8d77dc5]
/lib64/libc.so.6(clone+0x6d)[0x7f32b783381d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f3135e19038): is an invalid pointer
Connection ID (thread ID): 19901512

2021-09-04T22:41:28.620996+08:00 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 358677042537
2021-09-04T22:41:28.627887+08:00 0 [Note] InnoDB: Ignoring data file './norwex_live/zs_announcement_personal.ibd' with space ID 110884, since the redo log references ./norwex_live/zs_announcement_personal.ibd with space ID 107286.
2021-09-04T22:41:28.627998+08:00 0 [Note] InnoDB: Ignoring data file './norwex_live/#sql-ib108899-168045272.ibd' with space ID 110884. Another data file called ./norwex_live/zs_announcement_personal.ibd exists with the same space ID.
2021-09-04T22:41:28.628019+08:00 0 [Note] InnoDB: Ignoring data file './norwex_live/#sql-ib108899-168045272.ibd' with space ID 110884. Another data file called ./norwex_live/zs_announcement_personal.ibd exists with the same space ID.
2021-09-04T22:41:28.634307+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 358677119635

I passed the bug report to our dev team but without a way to reproduce this it is hard to make any progress on it.

Thanks for the report

This looks like something that's been fixed long ago.

Posted by developer:
 
Fixed as of the upcoming 5.7.30, 8.0.20 release, and here's the changelog entry:

An add column operation caused an assertion failure. The failure was due
to a dangling pointer.

Also, in the change log 
https://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-30.html
https://dev.mysql.com/doc/relnotes/mysql/8.0/en/news-8-0-20.html