Bug #82910 Crash when using CONVERT_TZ() in a SELECT query
Submitted: 8 Sep 2016 15:55 Modified: 9 Sep 2016 12:24
Reporter: jocelyn fournier Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.6.xx OS:Any
Assigned to: CPU Architecture:Any

[8 Sep 2016 15:55] jocelyn fournier
Description:
Hi,

After switching from MySQL 5.5 to 5.6 I experienced a crash on a specific query using CONVERT_TZ(). Note it seems to only occurs if MySQL is restarted *after* the datas are inserted in the table.

Associated stack trace : 

2016-09-08 16:35:50 2b886d520700  InnoDB: Assertion failure in thread 47864949638912 in file trx0trx.cc line 1171
InnoDB: Failing assertion: UT_LIST_GET_LEN(trx->lock.trx_locks) == 0
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.
14:35:50 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=33554432
read_buffer_size=65536
max_used_connections=6
max_threads=3000
thread_count=5
connection_count=5
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 455158 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x1e229f090
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 = 2b886d51fe70 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x35)[0x911685]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x3d8)[0x675a88]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x2b41eeb320a0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x2b41efd58125]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x180)[0x2b41efd5b3a0]
/usr/local/mysql/bin/mysqld[0x9fbfc5]
/usr/local/mysql/bin/mysqld[0x9fc162]
/usr/local/mysql/bin/mysqld[0x92e4b8]
/usr/local/mysql/bin/mysqld(_Z13ha_commit_lowP3THDbb+0x87)[0x5914d7]
/usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG6commitEP3THDb+0x423)[0x8c9003]
/usr/local/mysql/bin/mysqld(_Z15ha_commit_transP3THDbb+0x12b)[0x59208b]
/usr/local/mysql/bin/mysqld(_Z17trans_commit_stmtP3THD+0x2b)[0x793f7b]
/usr/local/mysql/bin/mysqld(_Z21mysql_execute_commandP3THD+0x481d)[0x6f9c6d]
/usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x377)[0x6fc5b7]
/usr/local/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xb4c)[0x6fd82c]
/usr/local/mysql/bin/mysqld(_Z10do_commandP3THD+0xd7)[0x6ff737]
/usr/local/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x116)[0x6c6756]
/usr/local/mysql/bin/mysqld(handle_one_connection+0x45)[0x6c6835]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x2b41eeb29b50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x2b41efe03fbd]

The crash doesn't occur on MySQL 5.5.
If the table is created in MyISAM instead of InnoDB, no crash occurs.

Thanks and regards,
  Jocelyn Fournier

How to repeat:
Get the timezone dump from
https://www.dropbox.com/s/e6ntzpxs7s5wv9u/timezone.sql?dl=0

mysql -uroot mysql < timezone.sql

(the tables have been generated by
mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -u root mysql
)

use test;
DROP TABLE IF EXISTS envois3;
CREATE TABLE `envois3` (
  `starttime` datetime NOT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO envois3 VALUES ('2008-08-11 22:43:00');

restart MySQL

SELECT CONVERT_TZ(starttime,'SYSTEM','Europe/Lisbon') starttime FROM envois3;

=> Crash
[8 Sep 2016 18:03] MySQL Verification Team
I couldn't repeat which is your time_zone?. Thanks
[8 Sep 2016 18:23] jocelyn fournier
Hi Miguel,

When it crashes, system_time_zone is CEST. 
Using SELECT CONVERT_TZ(starttime,'CEST','Europe/Lisbon') starttime FROM envois3; it crashes as well.

HTH,
  Jocelyn
[8 Sep 2016 18:34] jocelyn fournier
Note I'm able to reproduce the crash on 3 different servers (2 linux Debian wheezy / jessie, 1 mac os 10.12). Tested with percona, mariadb 10.0, 10.1 and Vanilla MySQL, all on the same system timezone CEST, all are crashing.

I've also been able to reproduce the crash in debug mode on MariaDB 10.0.27 with a different stacktrace :

2016-09-08 09:49:53 2b9e715bf700  InnoDB: Assertion failure in thread 47959506679552 in file lock0lock.cc line 4251
InnoDB: Failing assertion: (trx)->in_ro_trx_list == (trx)->read_only

stack_bottom = 0x2b9e715bee68 thread_stack 0x48000
mysys/stacktrace.c:267(my_print_stacktrace)[0xe666ff]
sql/signal_handler.cc:161(handle_fatal_signal)[0x872064]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x2b5470aff0a0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x2b5472595125]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x180)[0x2b54725983a0]
lock/lock0lock.cc:4251(lock_table_create)[0xb88867]
lock/lock0lock.cc:4633(lock_table(unsigned long, dict_table_t*, lock_mode, que_thr_t*))[0xb89697]
row/row0sel.cc:4085(row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long))[0xc586d4]
handler/ha_innodb.cc:8864(ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function))[0xb33559]
sql/handler.h:2929(handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function))[0x8809e8]
sql/handler.cc:2642(handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function))[0x8785cb]
sql/tztime.cc:1902(tz_load_from_open_tables)[0x76f40b]
sql/tztime.cc:2347(my_tz_find(THD*, String const*))[0x7705fa]
sql/item_timefunc.cc:2029(Item_func_convert_tz::get_date(st_mysql_time*, unsigned long long))[0x933de4]
sql/item.cc:6575(Item::send(Protocol*, String*))[0x8955b5]
sql/protocol.cc:912(Protocol::send_result_set_row(List<Item>*))[0x5d73fa]
sql/sql_class.cc:2573(select_send::send_data(List<Item>&))[0x646107]
sql/sql_select.cc:18972(end_send)[0x6e31d8]
sql/sql_select.cc:18065(evaluate_join_record)[0x6e0f2f]
sql/sql_select.cc:17843(sub_select(JOIN*, st_join_table*, bool))[0x6e0828]
sql/sql_select.cc:17505(do_select)[0x6e008d]
sql/sql_select.cc:3084(JOIN::exec_inner())[0x6bd27a]
sql/sql_select.cc:2375(JOIN::exec())[0x6ba746]
sql/sql_select.cc:3310(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x6bdaf7]
sql/sql_select.cc:373(handle_select(THD*, LEX*, select_result*, unsigned long))[0x6b3f69]
sql/sql_parse.cc:5294(execute_sqlcom_select)[0x6883aa]
sql/sql_parse.cc:2563(mysql_execute_command(THD*))[0x68075f]
sql/sql_parse.cc:6576(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x68b040]
sql/sql_parse.cc:1311(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x67d972]
sql/sql_parse.cc:999(do_command(THD*))[0x67cc38]
sql/sql_connect.cc:1378(do_handle_one_connection(THD*))[0x79cd4d]
sql/sql_connect.cc:1294(handle_one_connection)[0x79caac]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x2b5470af6b50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x2b5472640fbd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x259ea68): SELECT *, UNIX_TIMESTAMP(starttime) AS unixstamp, CONVERT_TZ(starttime,'SYSTEM','Europe/Lisbon') starttime FROM envois

On MySQL 5.6.33 the debug build is crashing at startup :

mysqld: /root/mysql-5.6.33/sql/sql_base.cc:9517: void close_mysql_tables(THD*): Assertion `thd->transaction.stmt.is_empty()' failed.
13:06:37 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=33554432
read_buffer_size=65536
max_used_connections=0
max_threads=3000
thread_count=0
connection_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 455838 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x3161ea820
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 = 7ffe04fdee28 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xaeff8b]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x402)[0x76fafe]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x2abc8cdc90a0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x2abc8dfef125]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x180)[0x2abc8dff23a0]
/lib/x86_64-linux-gnu/libc.so.6(__assert_fail+0xf1)[0x2abc8dfe8311]
/usr/local/mysql/bin/mysqld(_Z18close_mysql_tablesP3THD+0x41)[0x7be2b3]
/usr/local/mysql/bin/mysqld(_Z10my_tz_initP3THDPKcc+0x79a)[0x8f2963]
/usr/local/mysql/bin/mysqld(_Z11mysqld_mainiPPc+0x8ac)[0x668494]
/usr/local/mysql/bin/mysqld(main+0x20)[0x65d06c]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xfd)[0x2abc8dfdbead]
/usr/local/mysql/bin/mysqld[0x65cf69]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): is an invalid pointer
Connection ID (thread ID): 0
Status: NOT_KILLED
[8 Sep 2016 20:04] jocelyn fournier
Also if I try to run a SET time_zone command (even invalid) before the query, it doesn't crash as well.

MariaDB [test]> show variables LIKE 'time_zone';
+---------------+--------+
| Variable_name | Value  |
+---------------+--------+
| time_zone     | SYSTEM |
+---------------+--------+
1 row in set (0.01 sec)

MariaDB [test]> show variables LIKE 'system_time_zone';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| system_time_zone | CEST  |
+------------------+-------+
1 row in set (0.00 sec)

MariaDB [test]> use test
Database changed
MariaDB [test]> SET time_zone='CEST';
ERROR 1298 (HY000): Unknown or incorrect time zone: 'CEST'
MariaDB [test]> SELECT CONVERT_TZ(starttime,'SYSTEM','Europe/Lisbon') starttime FROM envois3;
+---------------------+
| starttime           |
+---------------------+
| 2008-08-11 21:43:00 |
+---------------------+
[9 Sep 2016 1:05] MySQL Verification Team
Thank you for the feedback. Could you please point me where in the Manual says the table mysql.time_zone_name can be created with engine InnoDB instead of MyISAM. When I build from soure is:

c:\dbs>5.6\bin\mysql -uroot mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.34 Source distribution PULL: 2016-SEP-07

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show create table time_zone_name\G
*************************** 1. row ***************************
       Table: time_zone_name
Create Table: CREATE TABLE `time_zone_name` (
  `Name` char(64) NOT NULL,
  `Time_zone_id` int(10) unsigned NOT NULL,
  PRIMARY KEY (`Name`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8 COMMENT='Time zone names'
1 row in set (0.00 sec)

On another hand the file you uses has:

--
-- Table structure for table `time_zone_name`
--

DROP TABLE IF EXISTS `time_zone_name`;
/*!40101 SET @saved_cs_client     = @@character_set_client */;
/*!40101 SET character_set_client = utf8 */;
CREATE TABLE `time_zone_name` (
  `Name` char(64) NOT NULL,
  `Time_zone_id` int(10) unsigned NOT NULL,
  PRIMARY KEY (`Name`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='Time zone names';
/*!40101 SET character_set_client = @saved_cs_client */;

Thanks.
[9 Sep 2016 7:49] jocelyn fournier
Hi Miguel,

Indeed. It seems this table has been in InnoDB format for a long time now (2014) but I don't really know why (perhaps a wrong attempt to convert in a batch MyISAM tables into InnoDB format).
The point is it was working properly in 5.5 and it starts crashing badly in 5.6, without any warning in the log about the wrong system table format. 
So it would be nice to have an error "Storage engine 'InnoDB' does not support system tables" instead of a crash :)

Thanks and regards,
  Jocelyn Fournier
[9 Sep 2016 10:17] MySQL Verification Team
Thank you for the feedback. When I applied your timezone.sql file I got:

c:\dbs>5.6\bin\mysql -uroot mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.6.34 Source distribution PULL: 2016-SEP-07

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> source c:/dbs/timezone.sql
Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

<CUT>

Query OK, 0 rows affected (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

ERROR 1726 (HY000): Storage engine 'InnoDB' does not support system tables. [mysql.time_zone_name]
Query OK, 0 rows affected (0.00 sec)

ERROR 1146 (42S02): Table 'mysql.time_zone_name' doesn't exist

<CUT>

and when re-start the server:

2016-09-09 07:08:53 20880 [Note]   - '::' resolves to '::';
2016-09-09 07:08:53 20880 [Note] Server socket created on IP: '::'.
2016-09-09 07:08:53 20880 [Warning] Can't open and lock time zone table: Table 'mysql.time_zone_name' doesn't exist tryi
ng to live without them
2016-09-09 07:08:53 20880 [Note] Event Scheduler: Loaded 0 events
2016-09-09 07:08:53 20880 [Note] 5.6\bin\mysqld: ready for connections.
Version: '5.6.34'  socket: ''  port: 3306  Source distribution PULL: 2016-SEP-07

So I could say !bug. Thanks.
[9 Sep 2016 10:22] jocelyn fournier
Yes actually I tested the testcase on MariaDB which doesn't do this check. 

But if the system table in InnoDB format is already existing in the database (I don't know in which MySQL version the "Storage engine 'InnoDB' does not support system
tables" check was introduced at table creation), it does crash.
[9 Sep 2016 10:27] jocelyn fournier
Note that after switching from 5.5 to 5.6 with this innodb time_zone_name table, mysql_upgrade didn't report an issue with this table neither.
[9 Sep 2016 10:27] Louis R
Also, the table was in InnoDB *before* (for more than 2 years), so for a reason has been converted without a warning by a previous version of MySQL.
Even if it's not possible to convert the table to InnoDB with current versions without MariaDB, it was possible before I guess, as we've been able to have InnoDB system tables up & running with MySQL 5.5 for 2 years, and crash MySQL 5.6 on upgrade without any warning.
So maybe not a bug, but I think there's a real need for a warning somewhere, maybe at least at startup?
[9 Sep 2016 11:59] MySQL Verification Team
Thank you for the feedback. The today situation is:

Manual notice about to convert system tables to InnoDB:

http://dev.mysql.com/doc/refman/5.6/en/converting-tables-to-innodb.html

"Important
Do not convert MySQL system tables in the mysql database (such as user or host) to the InnoDB type. This is an unsupported operation. The system tables must always be of the MyISAM type."

Both version 5.5 and 5.6 doesn't permit to create/alter system table for InnoDB engine:

c:\dbs>5.5\bin\mysql -uroot mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.53 Source distribution PULL: 2016-SEP-07

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> source c:/dbs/timezone.sql
Query OK, 0 rows affected (0.00 sec)

<CUT>

Query OK, 0 rows affected (0.00 sec)

ERROR 1726 (HY000): Storage engine 'InnoDB' does not support system tables. [mysql.time_zone_name]
Query OK, 0 rows affected (0.00 sec)

ERROR 1146 (42S02): Table 'mysql.time_zone_name' doesn't exist

c:\dbs>5.5\bin\mysql -uroot mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.53 Source distribution PULL: 2016-SEP-07

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> alter table time_zone_name engine InnoDB;
ERROR 1726 (HY000): Storage engine 'InnoDB' does not support system tables. [mysql.time_zone_name]
[9 Sep 2016 12:24] jocelyn fournier
Well if in the manual it's specified to not convert the system table to InnoDB, it means it was allowed at some point :)

I agree those tables shouldn't have been converted to InnoDB, but in this particular case it wasn't causing any issue in MySQL 5.5, and with 5.6, it was really painful to find out what was wrong (server keep crashing, no offending query reported in the stack trace while in production, no error / warning, no clue from the stack trace...).

It could also occur while migrating for example from MariaDB to MySQL, since for example current MariaDB 5.5 version still allows this kind of MyISAM -> InnoDB conversion.

So I think at least adding an extra check in mysql_upgrade would be helpful :)