Bug #88844 MySQL crash with InnoDB assertion failure in file pars0pars.cc
Submitted: 10 Dec 2017 12:54 Modified: 3 Jan 12:08
Reporter: Jo Goossens Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.6.38 OS:CentOS
Assigned to:

[10 Dec 2017 12:54] Jo Goossens
Description:
Hi,

We see crashing MySQL quite a lot on several servers after upgrading to 5.6.38. We rolled back to 5.6.36 and no such issue occur.

We can trigger it consistently by using OPTIMIZE TABLES. We suspect other causes as well, but we're unsure as we see it randomly crashing.

The issue is major, we've got corrupted tables and data loss in the meanwhile on some hosts and we've seen it happening on dozens of servers since recently!

How to repeat:
mysqlcheck -As --optimize

Result:

2017-12-08 00:11:32 7fa6d2ffd700  InnoDB: Assertion failure in thread 140354481280768 in file pars0pars.cc line 865
InnoDB: Failing assertion: sym_node->table != NULL
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/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
23:11:32 UTC - mysqld got signal 6 ;
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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

key_buffer_size=134217728
read_buffer_size=2097152
max_used_connections=10
max_threads=500
thread_count=9
connection_count=9
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2185470 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0x8e852b]
/usr/sbin/mysqld(handle_fatal_signal+0x491)[0x6750f1]
/lib64/libpthread.so.0(+0xf5e0)[0x7fa75620c5e0]
/lib64/libc.so.6(gsignal+0x37)[0x7fa754e061f7]
/lib64/libc.so.6(abort+0x148)[0x7fa754e078e8]
/usr/sbin/mysqld[0x988556]
/usr/sbin/mysqld(_Z7yyparsev+0x1e09)[0xabd929]
/usr/sbin/mysqld[0x989c41]
/usr/sbin/mysqld[0xab96b8]
/usr/sbin/mysqld[0xaa4eb2]
/usr/sbin/mysqld[0xaa55c8]
/usr/sbin/mysqld(_Z23fts_optimize_sync_tablem+0x42)[0xab16f2]
/usr/sbin/mysqld[0xab1ac4]
/lib64/libpthread.so.0(+0x7e25)[0x7fa756204e25]
/lib64/libc.so.6(clone+0x6d)[0x7fa754ec934d]
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.
171208 00:11:32 mysqld_safe Number of processes running now: 0
171208 00:11:32 mysqld_safe mysqld restarted
2017-12-08 00:11:32 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-12-08 00:11:32 0 [Note] /usr/sbin/mysqld (mysqld 5.6.38-log) starting as process 9570 ...
2017-12-08 00:11:33 9570 [Note] Plugin 'FEDERATED' is disabled.
2017-12-08 00:11:33 9570 [Note] InnoDB: Using atomics to ref count buffer pool pages
2017-12-08 00:11:33 9570 [Note] InnoDB: The InnoDB memory heap is disabled
2017-12-08 00:11:33 9570 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-12-08 00:11:33 9570 [Note] InnoDB: Memory barrier is not used
2017-12-08 00:11:33 9570 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-12-08 00:11:33 9570 [Note] InnoDB: Using Linux native AIO
2017-12-08 00:11:33 9570 [Note] InnoDB: Using CPU crc32 instructions
2017-12-08 00:11:33 9570 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2017-12-08 00:11:33 9570 [Note] InnoDB: Completed initialization of buffer pool
2017-12-08 00:11:33 9570 [Note] InnoDB: Highest supported file format is Barracuda.
2017-12-08 00:11:33 9570 [Note] InnoDB: Log scan progressed past the checkpoint lsn 48664636843
2017-12-08 00:11:33 9570 [Note] InnoDB: Database was not shutdown normally!
2017-12-08 00:11:33 9570 [Note] InnoDB: Starting crash recovery.
2017-12-08 00:11:33 9570 [Note] InnoDB: Reading tablespace information from the .ibd files...
2017-12-08 00:12:46 9570 [Note] InnoDB: Restoring possible half-written data pages
2017-12-08 00:12:46 9570 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 48669879296
InnoDB: Doing recovery: scanned up to log sequence number 48675122176
InnoDB: Doing recovery: scanned up to log sequence number 48680365056
InnoDB: Doing recovery: scanned up to log sequence number 48685607936
InnoDB: Doing recovery: scanned up to log sequence number 48690850816
InnoDB: Doing recovery: scanned up to log sequence number 48696093696
InnoDB: Doing recovery: scanned up to log sequence number 48701336576
InnoDB: Doing recovery: scanned up to log sequence number 48706579456
InnoDB: Doing recovery: scanned up to log sequence number 48711822336
InnoDB: Doing recovery: scanned up to log sequence number 48717065216
InnoDB: Doing recovery: scanned up to log sequence number 48722308096
InnoDB: Doing recovery: scanned up to log sequence number 48727550976
InnoDB: Doing recovery: scanned up to log sequence number 48732793856
InnoDB: Doing recovery: scanned up to log sequence number 48736271525
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 818 row operations to undo
InnoDB: Trx id counter is 307724288
2017-12-08 00:12:54 9570 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
[12 Dec 2017 18:52] Godofredo Miguel Solorzano
Thank you for the bug report. Looks like duplicate/related with bug https://bugs.mysql.com/bug.php?id=68987, please check. Thanks.
[12 Dec 2017 19:49] Jo Goossens
Well I would say perhaps no because we don't have the issue with 5.6.36 and only with 5.6.38, which is very very strange...

It only came to our attention recently and multiple times. However in most, if not all, cases it was with a Magento 2 database.
[13 Dec 2017 22:17] Godofredo Miguel Solorzano
Thank you for the feedback. When you did the upgrade did you run the mysql_upgrade utility?.
[14 Dec 2017 8:48] Jo Goossens
Hi

We certainly ran the upgrade script as far as I know it was done automatically.

I tested now on another but similar system with 5.6.38 still in place and see this message:

 mysql_upgrade
Looking for 'mysql' as: mysql
Looking for 'mysqlcheck' as: mysqlcheck
This installation of MySQL is already upgraded to 5.6.38, use --force if you still need to run mysql_upgrade
[29 Dec 2017 13:46] Shane Bester
Hi,

What we require is the SHOW CREATE TABLE for the table in question.
And also SHOW TABLE STATUS LIKE 'table';   so we can see approximately how large a table this is.

Are you sure your tmpdir is not getting filled when the crash occurs?
[29 Dec 2017 17:55] Shane Bester
I can confirm 5.6.38 is broken.  Either I get endless hang, or now seen a crash.

Version: '5.6.38'  socket: ''  port: 3306  MySQL Community Server (GPL)
2017-12-29 19:53:29 3ff4 InnoDB: FTS Optimize Removing table test/#sql2-36e8-1
...
 mysqld.exe!my_sigabrt_handler()[my_thr_init.c:455]
MSVCR100.dll!raise()
MSVCR100.dll!abort()
 mysqld.exe!pars_retrieve_table_def()[pars0pars.cc:867]
 mysqld.exe!pars_insert_statement()[pars0pars.cc:1375]
 mysqld.exe!yyparse()[pars0grm.y:380]
 mysqld.exe!pars_sql()[pars0pars.cc:2245]
 mysqld.exe!fts_parse_sql()[fts0sql.cc:214]
 mysqld.exe!fts_write_node()[fts0fts.cc:3918]
 mysqld.exe!fts_sync_write_words()[fts0fts.cc:4078]
 mysqld.exe!fts_sync()[fts0fts.cc:4652]
 mysqld.exe!fts_optimize_sync_table()[fts0opt.cc:2980]
 mysqld.exe!fts_optimize_thread()[fts0opt.cc:3108]
kernel32.dll!BaseThreadInitThunk()
ntdll.dll!RtlUserThreadStart()

Working on a testcase.......
[29 Dec 2017 18:35] Shane Bester
Also affects 5.7...

Version: '5.7.22'  socket: ''  port: 3306  (Built on 2017/12/20)
InnoDB: Assertion failure in thread 15060 in file pars0pars.cc line 822
InnoDB: Failing assertion: sym_node->table != NULL
[3 Jan 12:03] Jo Goossens
Hello,

Here is the output of the show create table of a table which caused issues:

mysql> show create table newance_blog_post \G
*************************** 1. row ***************************
       Table: newance_blog_post
Create Table: CREATE TABLE `newance_blog_post` (
  `post_id` int(11) NOT NULL AUTO_INCREMENT COMMENT 'Post ID',
  `title` varchar(255) DEFAULT NULL COMMENT 'Post Title',
  `meta_keywords` text COMMENT 'Post Meta Keywords',
  `meta_description` text COMMENT 'Post Meta Description',
  `identifier` varchar(100) DEFAULT NULL COMMENT 'Post String Identifier',
  `content_heading` varchar(255) DEFAULT NULL COMMENT 'Post Content Heading',
  `content` mediumtext COMMENT 'Post Content',
  `short_content` mediumtext COMMENT 'Short Post Content',
  `creation_time` timestamp NULL DEFAULT NULL COMMENT 'Post Creation Time',
  `update_time` timestamp NULL DEFAULT NULL COMMENT 'Post Modification Time',
  `publish_time` timestamp NULL DEFAULT NULL COMMENT 'Post Publish Time',
  `is_active` smallint(6) NOT NULL DEFAULT '1' COMMENT 'Is Post Active',
  `featured_img` varchar(255) NOT NULL COMMENT 'Image',
  `author_id` int(11) NOT NULL COMMENT 'Author ID',
  `online_time` timestamp NULL DEFAULT NULL COMMENT 'Post Online Time',
  `offline_time` timestamp NULL DEFAULT NULL COMMENT 'Post Offline Time',
  PRIMARY KEY (`post_id`),
  KEY `NEWANCE_BLOG_POST_IDENTIFIER` (`identifier`),
  FULLTEXT KEY `FTI_71B7343BC75FD226362D91CF1E7688C3` (`title`,`meta_keywords`,`meta_description`,`identifier`,`content`)
) ENGINE=InnoDB AUTO_INCREMENT=56 DEFAULT CHARSET=utf8 COMMENT='Newance Blog Post Table'
1 row in set (0.01 sec)

This is the status, but I'm unsure if the status is still comparable to when it happened.

mysql> SHOW TABLE STATUS LIKE 'newance_blog_post'\G
*************************** 1. row ***************************
           Name: newance_blog_post
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 33
 Avg_row_length: 7447
    Data_length: 245760
Max_data_length: 0
   Index_length: 32768
      Data_free: 0
 Auto_increment: 56
    Create_time: 2017-12-07 23:24:05
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options:
        Comment: Newance Blog Post Table
1 row in set (0.01 sec)

mysql>

Regards
Jo
[3 Jan 12:08] Jo Goossens
Well I just tried and MySQL 5.6.38 still crashes:

mysqlcheck --optimize belguniq_db2 newance_blog_post
mysqlcheck: Got error: 2013: Lost connection to MySQL server during query when executing 'OPTIMIZE TABLE ... '
root@web [~]#

Error log:

2018-01-03 13:07:09 7f26b2ffd700  InnoDB: Assertion failure in thread 139804188595968 in file pars0pars.cc line 865
InnoDB: Failing assertion: sym_node->table != NULL
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/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
12:07:09 UTC - mysqld got signal 6 ;
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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

key_buffer_size=134217728
read_buffer_size=2097152
max_used_connections=3
max_threads=500
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 = 2185470 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0x8e83fb]
/usr/sbin/mysqld(handle_fatal_signal+0x491)[0x674e51]
/lib64/libpthread.so.0(+0xf5e0)[0x7f26fb8925e0]
/lib64/libc.so.6(gsignal+0x37)[0x7f26fa6981f7]
/lib64/libc.so.6(abort+0x148)[0x7f26fa6998e8]
/usr/sbin/mysqld[0x988056]
/usr/sbin/mysqld(_Z7yyparsev+0x1e09)[0xabd659]
/usr/sbin/mysqld[0x989741]
/usr/sbin/mysqld[0xab93e8]
/usr/sbin/mysqld[0xaa4be2]
/usr/sbin/mysqld[0xaa52f8]
/usr/sbin/mysqld(_Z23fts_optimize_sync_tablem+0x42)[0xab1422]
/usr/sbin/mysqld[0xab17f4]
/lib64/libpthread.so.0(+0x7e25)[0x7f26fb88ae25]
/lib64/libc.so.6(clone+0x6d)[0x7f26fa75b34d]
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.
180103 13:07:09 mysqld_safe Number of processes running now: 0
180103 13:07:09 mysqld_safe mysqld restarted
2018-01-03 13:07:09 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-01-03 13:07:09 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2018-01-03 13:07:09 0 [Note] /usr/sbin/mysqld (mysqld 5.6.38-log) starting as process 19471 ...
2018-01-03 13:07:09 19471 [Note] Plugin 'FEDERATED' is disabled.
2018-01-03 13:07:09 19471 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-01-03 13:07:09 19471 [Note] InnoDB: The InnoDB memory heap is disabled
2018-01-03 13:07:09 19471 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-01-03 13:07:09 19471 [Note] InnoDB: Memory barrier is not used
2018-01-03 13:07:09 19471 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-01-03 13:07:09 19471 [Note] InnoDB: Using Linux native AIO
2018-01-03 13:07:09 19471 [Note] InnoDB: Using CPU crc32 instructions
2018-01-03 13:07:09 19471 [Note] InnoDB: Initializing buffer pool, size = 384.0M
2018-01-03 13:07:09 19471 [Note] InnoDB: Completed initialization of buffer pool
2018-01-03 13:07:10 19471 [Note] InnoDB: Highest supported file format is Barracuda.
2018-01-03 13:07:10 19471 [Note] InnoDB: Log scan progressed past the checkpoint lsn 9840054984
2018-01-03 13:07:10 19471 [Note] InnoDB: Database was not shutdown normally!
2018-01-03 13:07:10 19471 [Note] InnoDB: Starting crash recovery.
2018-01-03 13:07:10 19471 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-01-03 13:07:11 19471 [Note] InnoDB: Restoring possible half-written data pages
2018-01-03 13:07:11 19471 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 9840530884
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1474 row operations to undo
InnoDB: Trx id counter is 153535744
2018-01-03 13:07:12 19471 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
2018-01-03 13:07:13 19471 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2018-01-03 13:07:13 7f6c38c6c700  InnoDB: Rolling back trx with id 153535313, 1474 rows to undo

InnoDB: Progress in percents: 1 22018-01-03 13:07:13 19471 [Note] InnoDB: Waiting for purge to start
 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002018-01-03 13:07:13 19471 [Note] InnoDB: Rollback of trx with id 153535313 completed
2018-01-03 13:07:13 7f6c38c6c700  InnoDB: Rollback of non-prepared transactions completed
2018-01-03 13:07:13 19471 [Note] InnoDB: 5.6.38 started; log sequence number 9840530884
2018-01-03 13:07:13 19471 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2018-01-03 13:07:13 19471 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
2018-01-03 13:07:13 19471 [Note] Server socket created on IP: '127.0.0.1'.
2018-01-03 13:07:13 19471 [Note] Event Scheduler: Loaded 0 events
2018-01-03 13:07:13 19471 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.38-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)