Bug #110345 MySQL crash on MacOS typically when restoring a MySQL 5.7 sql
Submitted: 11 Mar 2023 21:50 Modified: 20 Apr 2023 21:01
Reporter: Steve Drew Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:8.0.32 OS:MacOS (Ventura 13.0.1)
Assigned to: CPU Architecture:ARM

[11 Mar 2023 21:50] Steve Drew
Description:
This has happened about 10 times in the past few weeks, after upgrading from MySQL 5.7 to 8.  MySQL 5.7 never crashed.

It typically happens after I restore a database (small database not complex and about 5 MB in size).

After this crash occurs it is impossible to get MySQL started again unless you use innodb recovery level 6 and then cannot do anything but dump all databases in readonly and restore.

I tried increasing thread_stack = 10M, as suggested by others seeing similar stack trace, but still occurs.

2023-03-11T21:21:17.049454Z 40990 [ERROR] [MY-013183] [InnoDB] Assertion failure: dict0dict.cc:1223:table2 == nullptr thread 0x2cf483000
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.
2023-03-11T21:21:17Z UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x127d59000
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 = 2cf482f28 thread_stack 0xa00000
0   mysqld                              0x000000010389bbe8 my_print_stacktrace(unsigned char const*, unsigned long) + 68
1   mysqld                              0x00000001030531b0 print_fatal_signal(int) + 572
2   mysqld                              0x00000001030533b4 my_server_abort() + 88
3   mysqld                              0x0000000103896544 my_abort() + 20
4   mysqld                              0x0000000103b6ca30 ut_dbg_assertion_failed(char const*, char const*, unsigned long long) + 400
5   mysqld                              0x000000010394016c ut::hash_string(char const*) + 0
6   mysqld                              0x000000010395dca4 dict_table_t* dd_open_table_one<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*, std::__1::deque<char const*, ut::allocator<char const*, ut::detail::allocator_base_pfs<char const*> > >&) + 5088
7   mysqld                              0x000000010394da78 dict_table_t* dd_open_table<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*) + 60
8   mysqld                              0x00000001039f74f0 ha_innobase::open(char const*, int, unsigned int, dd::Table const*) + 400
9   mysqld                              0x0000000102c9bbdc handler::ha_open(TABLE*, char const*, int, int, dd::Table const*) + 100
10  mysqld                              0x0000000102ffad1c open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*) + 2412
11  mysqld                              0x0000000102eb6f74 open_table(THD*, Table_ref*, Open_table_context*) + 2364
12  mysqld                              0x0000000102eba524 open_tables(THD*, Table_ref**, unsigned int*, unsigned int, Prelocking_strategy*) + 596
13  mysqld                              0x0000000102ebc394 open_tables_for_query(THD*, Table_ref*, unsigned int) + 108
14  mysqld                              0x0000000102f79438 Sql_cmd_dml::prepare(THD*) + 336
15  mysqld                              0x0000000102f79a3c Sql_cmd_dml::execute(THD*) + 372
16  mysqld                              0x0000000102f3a338 mysql_execute_command(THD*, bool) + 3852
17  mysqld                              0x0000000102f3858c dispatch_sql_command(THD*, Parser_state*) + 740
18  mysqld                              0x0000000102f37520 dispatch_command(THD*, COM_DATA const*, enum_server_command) + 5468
19  mysqld                              0x0000000102f37cb8 do_command(THD*) + 364
20  mysqld                              0x0000000103041764 handle_connection(void*) + 476
21  mysqld                              0x0000000103bcd370 pfs_spawn_thread(void*) + 288
22  libsystem_pthread.dylib             0x0000000197fe606c _pthread_start + 148
23  libsystem_pthread.dylib             0x0000000197fe0e2c thread_start + 8

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (123c0c030): select id from SH_Admin.DatabaseInfo where IsProduction=1 and DatabaseName='sh_admin'
Connection ID (thread ID): 40990
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

How to repeat:

Cannot force it to occur, but typically occurs after server has been running for a while and then attempt to import a new database which was a MySQL 5.7 dump file.
[13 Mar 2023 14:28] MySQL Verification Team
Hi Mr. Drew,

Thank you for your bug report.

We also use macOS 13.0.1. We have also upgraded from latest 5.7 to the 8.0 release that you have cited above.

However, we have never, ever got the assertion. There are many other bug reports with assertions in the the open tables, but not a single one that had problems with hashing functions .......

That means that your table is quite corrupted. What you can try to do is to make another copy of that table. First use mysqldump to get a backup copy of the 8.0 version of the table.

Then, you should try to find 5.7 version of that table, mysqldump it , drop the current 8.0 problematic table and then restore it by running the SQL script obtained by mysqldump.

You will find all this explained in detail in our Reference Manual.

Can't repeat.
[13 Mar 2023 15:29] MySQL Verification Team
Hi,

On another thought, we wonder whether you can upload the original 5.7 table that crashes. 

If not, then 8.0.32 dump of that table ?????
[13 Mar 2023 21:56] Steve Drew
I dont think that is the problem as after recovering I can import the same file again with no issues.

It has happened with many different import files.

Now I always restart MySql before I do an import and so far have prevented the crash.
[14 Mar 2023 12:59] MySQL Verification Team
Hi,

Can you send us 8.0  mysqldump output from the problematic 8.0 table??

Please, use "Files" tab for the upload.
[14 Mar 2023 14:11] MySQL Verification Team
Mr. Drew,

Also, please, let us know what happens if you import the mysqldump file, without restarting MySQL server ???

Let us know which commands should we run on MySQL server, prior to the restore of that table, so that we also see a crash, as in your stacktrace !!!!!!

Waiting on your full feedback.
[15 Mar 2023 17:55] MySQL Verification Team
Hi,

> It typically happens after I restore a database

How are you restoring the database? Do you run SQL to create and populate database or you are restoring from binary files? If you are copying datadir where do you copy it from?
[15 Mar 2023 18:55] Jakub Lopuszanski
Hi!
I have a question.
Does your error log contain a line about `lower_case_table_names=2`, like this one:

2023-03-15T01:31:50.082266Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /System/Volumes/Data/export/home/pb2/var/mtr-12192/var-meb/6/mysqld.1/data/ is case insensitive
[16 Mar 2023 13:29] MySQL Verification Team
Hi Mr. Drew,

We truly need some answers from you ........

Can you try to send us 8.0  mysqldump output from the problematic 8.0 table??

Please, use "Files" tab for the upload.

Also, please, let us know what happens if you import the mysqldump file, without restarting MySQL server ???

Let us know which commands should we run on MySQL server, prior to the restore of that table, so that we also see a crash, as in your stacktrace !!!!!!

We are still waiting on your full feedback.
[16 Mar 2023 23:03] Steve Drew
I am doing a mysqldump from 5.7 
eg:  mysqldump mydb >mydb.sql

Then on Mysql 8.0
mysql -e "create database mydb"
mysql <mydb.sql

I do not know which table to dump. and cannot even get mysql started after this occurs. Except if I use innodb_force_recovery = 6. 

I do not see any messages regarding lower case names in the log file.

It has not happened in a few days. I will keep testing and see if there is a way I can reproduce.

my.cnf file is as follows.

sql_mode = "NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION"
port            = 3306
socket          = /tmp/mysql.sock
innodb_file_per_table      = 1
innodb_log_file_size = 100M
innodb_buffer_pool_instances = 4
innodb_buffer_pool_size    = 2GB
innodb_flush_log_at_trx_commit=2
group_concat_max_len    = 10240
interactive_timeout     = 300
wait_timeout            = 300
table_open_cache        = 800
max_allowed_packet      = 50M
tmp_table_size          = 8M
max_heap_table_size     = 64M
max_connections         = 280
innodb_lock_wait_timeout = 20
thread_stack = 10M
[17 Mar 2023 10:02] Jakub Lopuszanski
Hi Steve Drew,
thanks for the details shared so far.
I need more specific info, though:

1. Does the sql dump contain any table with at least one upper-case letter in its name (or name of the database)?
2. What is the file system you use to store the data-dir of the MySQL 8.0? In paticular: is it case insensitive?
3. Can you share full error log file (or at least everything from the moment mysqld is started for the last time before crash) from a crash incident?
[17 Mar 2023 13:07] MySQL Verification Team
Mr. Drew,

If you manage to repeat the problem, please upload the dump.
[20 Apr 2023 21:00] Steve Drew
It occurred again after restoring a mysql 5.7.34 dump file.

2023-03-21T19:07:05.786088Z 0 [System] [MY-010931] [Server] /opt/homebrew/opt/mysql/bin/mysqld: ready for connections. Version: '8.0.32'  socket: '/tmp/mysql.sock'  port: 3306  Homebrew.
2023-04-04T00:40:07.478283Z 28569 [ERROR] [MY-013183] [InnoDB] Assertion failure: dict0dict.cc:1223:table2 == nullptr thread 0x2c4963000
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.
2023-04-04T00:40:07Z UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x13fe47c00
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 = 2c4962f28 thread_stack 0xa00000
0   mysqld                              0x000000010563bbe8 my_print_stacktrace(unsigned char const*, unsigned long) + 68
1   mysqld                              0x0000000104df31b0 print_fatal_signal(int) + 572
2   mysqld                              0x0000000104df33b4 my_server_abort() + 88
3   mysqld                              0x0000000105636544 my_abort() + 20
4   mysqld                              0x000000010590ca30 ut_dbg_assertion_failed(char const*, char const*, unsigned long long) + 400
5   mysqld                              0x00000001056e016c ut::hash_string(char const*) + 0
6   mysqld                              0x00000001056fdca4 dict_table_t* dd_open_table_one<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*, std::__1::deque<char const*, ut::allocator<char const*, ut::detail::allocator_base_pfs<char const*> > >&) + 5088
7   mysqld                              0x00000001056eda78 dict_table_t* dd_open_table<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*) + 60
8   mysqld                              0x00000001057974f0 ha_innobase::open(char const*, int, unsigned int, dd::Table const*) + 400
9   mysqld                              0x0000000104a3bbdc handler::ha_open(TABLE*, char const*, int, int, dd::Table const*) + 100
10  mysqld                              0x0000000104d9ad1c open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*) + 2412
11  mysqld                              0x0000000104c56f74 open_table(THD*, Table_ref*, Open_table_context*) + 2364
12  mysqld                              0x0000000104c5a524 open_tables(THD*, Table_ref**, unsigned int*, unsigned int, Prelocking_strategy*) + 596
13  mysqld                              0x0000000104c5c394 open_tables_for_query(THD*, Table_ref*, unsigned int) + 108
14  mysqld                              0x0000000104d19438 Sql_cmd_dml::prepare(THD*) + 336
15  mysqld                              0x0000000104d19a3c Sql_cmd_dml::execute(THD*) + 372
16  mysqld                              0x0000000104cda338 mysql_execute_command(THD*, bool) + 3852
17  mysqld                              0x0000000104cd858c dispatch_sql_command(THD*, Parser_state*) + 740
18  mysqld                              0x0000000104cd7520 dispatch_command(THD*, COM_DATA const*, enum_server_command) + 5468
19  mysqld                              0x0000000104cd7cb8 do_command(THD*) + 364
20  mysqld                              0x0000000104de1764 handle_connection(void*) + 476
21  mysqld                              0x000000010596d370 pfs_spawn_thread(void*) + 288
22  libsystem_pthread.dylib             0x0000000188daa06c _pthread_start + 148
23  libsystem_pthread.dylib             0x0000000188da4e2c thread_start + 8

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
[20 Apr 2023 21:01] Steve Drew
Sorry this is actually the latest one.

2023-04-13T03:11:22.404667Z 0 [System] [MY-010931] [Server] /opt/homebrew/opt/mysql/bin/mysqld: ready for connections. Version: '8.0.32'  socket: '/tmp/mysql.sock'  port: 3306  Homebrew.
2023-04-20T20:50:12.570662Z 17038 [ERROR] [MY-013183] [InnoDB] Assertion failure: dict0dict.cc:1223:table2 == nullptr thread 0x319e2b000
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.
2023-04-20T20:50:12Z UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x1151af200
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 = 319e2af28 thread_stack 0xa00000
0   mysqld                              0x0000000104fe3be8 my_print_stacktrace(unsigned char const*, unsigned long) + 68
1   mysqld                              0x000000010479b1b0 print_fatal_signal(int) + 572
2   mysqld                              0x000000010479b3b4 my_server_abort() + 88
3   mysqld                              0x0000000104fde544 my_abort() + 20
4   mysqld                              0x00000001052b4a30 ut_dbg_assertion_failed(char const*, char const*, unsigned long long) + 400
5   mysqld                              0x000000010508816c ut::hash_string(char const*) + 0
6   mysqld                              0x00000001050a5ca4 dict_table_t* dd_open_table_one<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*, std::__1::deque<char const*, ut::allocator<char const*, ut::detail::allocator_base_pfs<char const*> > >&) + 5088
7   mysqld                              0x0000000105095a78 dict_table_t* dd_open_table<dd::Table>(dd::cache::Dictionary_client*, TABLE const*, char const*, dd::Table const*, THD*) + 60
8   mysqld                              0x000000010513f4f0 ha_innobase::open(char const*, int, unsigned int, dd::Table const*) + 400
9   mysqld                              0x00000001043e3bdc handler::ha_open(TABLE*, char const*, int, int, dd::Table const*) + 100
10  mysqld                              0x0000000104742d1c open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*) + 2412
11  mysqld                              0x00000001045fef74 open_table(THD*, Table_ref*, Open_table_context*) + 2364
12  mysqld                              0x0000000104602524 open_tables(THD*, Table_ref**, unsigned int*, unsigned int, Prelocking_strategy*) + 596
13  mysqld                              0x0000000104604394 open_tables_for_query(THD*, Table_ref*, unsigned int) + 108
14  mysqld                              0x00000001046c1438 Sql_cmd_dml::prepare(THD*) + 336
15  mysqld                              0x00000001046c1a3c Sql_cmd_dml::execute(THD*) + 372
16  mysqld                              0x0000000104682338 mysql_execute_command(THD*, bool) + 3852
17  mysqld                              0x000000010468058c dispatch_sql_command(THD*, Parser_state*) + 740
18  mysqld                              0x000000010467f520 dispatch_command(THD*, COM_DATA const*, enum_server_command) + 5468
19  mysqld                              0x000000010467fcb8 do_command(THD*) + 364
20  mysqld                              0x0000000104789764 handle_connection(void*) + 476
21  mysqld                              0x0000000105315370 pfs_spawn_thread(void*) + 288
22  libsystem_pthread.dylib             0x000000019e04606c _pthread_start + 148
23  libsystem_pthread.dylib             0x000000019e040e2c thread_start + 8

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (12313de30): select SType.id, SType.Created, SType.CreatedBy, SType.LastModified, SType.LastModifiedBy, SType.IsDeleted, SType.Queue_id, SType.Name, SType.Description, SType.Details, SType.DisplayOrder, SType.Color, SType.ColorHex, SType.Duration, SType.MinAdvancedCancelHours, SType.MinAdvancedBookingHours, SType.MaxAdvancedBookingDays, SType.AllowBooking, SType.AllowOnlineBooking, SType.AllowOnlineJoin, SType.AllowKioskJoin, SType.KioskAskMeetMethod, SType.Enabled, SType.Category_id, SType.ServicePriority, SType.RequiredWaiver_id, SType.NextServiceType_id, SType.NextServiceTypeStage, SType.IncreasePriorityMins, SType.IncreasePriority, SType.ForceArrived, SType.EnableOnlineMeeting, SType.EnableMeetsMeeting, SType.EnableZoomMeeting, SType.EnableAttachment, SType.AttachmentRequired, SType.AttachmentLabel, SType.RedirectToServiceType_id, SType.UseBusinessHours, SType.MethodInPerson, SType.MethodByPhone, SType.MethodOnline, SType.EnableMeetingMethods, SType.DisableMessages,
                Queue.QueueName as QueueName,

Connection ID (thread ID): 17038
Status: NOT_KILLED
[21 Apr 2023 8:44] Jakub Lopuszanski
So, IIUC, please correct me if I am wrong:

1. There were at least several days since the server was started til the day it crashed. 
In the first log we see started 2023-03-21 -> crashed 2023-04-04
In the second log we see started 2023-04-13 -> crashed 2023-04-20

2. There are no log entries, even benign ones, before "ready for connections"

3. The first log does not contain any hint about the SQL query being executed

4. The second log hints that the problem might involve a table named SType (although we only see a prefix of the SQL so it's not clear to me if that is a name of table, a view, or an alias). It definitely involves a table named QueueName, though.

If so, then the query which crashed the server involves at least one table which has at least one upper-case letter in its name: QueueName.

Questions:
Q1. were QueueName or SType among the tables imported from 5.7.34 dump?
Q2. do you think it is possible that these tables were not referenced by any query before the crash?
Q3. can you please check the  5.7.34 dump file to see how the QueueName table was referred to in it exactly - was it QueueName, queuename, Queuename?
Q4. could you please check how the *.ibd file for QueueName on disc in the data-dir is named? Ideally a full path would be helpful.
[21 Apr 2023 12:35] MySQL Verification Team
Hi Mr. Drew,

We agree with all questions that are posed by Mr. Jakub Lopuszanski .

We would just like to note that a stacktrace is similar to the one that you posted at the start of this report.

We would also like to remind you NOT to use mixed-case table names on the macOS. It is simply unreliable, which is a fault of the OS and not of MySQL.

We can not go further without a full test case. If we would have one, then we will have to replace one VERY long macro with a function or method , in order to diagnose it. It is quite possible that macOS returns the filename with lower case only .......

We are waiting on your feedback.