Bug #87966 5.5 to 5.6 upgrade assertion sym_node->table != NULL, orphan temporary table
Submitted: 4 Oct 2017 6:44 Modified: 4 Oct 2017 12:53
Reporter: Nikolai Ikhalainen Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.6.37 OS:Any
Assigned to: CPU Architecture:Any

[4 Oct 2017 6:44] Nikolai Ikhalainen
Description:
Upgrade from mysql-community-server-minimal-5.5.57-2.el7.x86_64 to 5.6.37-2.el7.

Unable to start mysql 5.6 with --skip-grant-tables due to orphan innodb temporary table.

original bug report: https://bugs.launchpad.net/percona-server/+bug/1719284

How to repeat:
docker run --rm  -it -e MYSQL_ALLOW_EMPTY_PASSWORD=1 --name lp1719284 --entrypoint=/bin/bash mysql/mysql-server:5.5
yum install -y procps-ng
mysql_install_db --force ; chown -R mysql:mysql /var/lib/mysql
mysqld
mysql -e 'create database if not exists test; create temporary table test.t(c int) engine=innodb;select sleep(100)' &
sleep 5; kill -9 $(pgrep -xn mysqld)
cp -ap /var/lib/mysql /var/lib/mysql1/
yum install -y http://dev.mysql.com/get/mysql-community-release-el7-5.noarch.rpm
yum remove -y mysql-community-server-minimal
yum install -y mysql-community-server.x86_64
yum list mysql-community-server.x86_64
# Loaded plugins: ovl
# Installed Packages
# mysql-community-server.x86_64 5.6.37-2.el7 @mysql56-community
mysqld_safe --skip-grant-tables
[4 Oct 2017 6:47] Nikolai Ikhalainen
2017-10-04 06:30:46 791 [Note] InnoDB: The log sequence numbers 0 and 0 in ibdata files do not match the log sequence number 1601736 in the ib_logfiles!
2017-10-04 06:30:46 791 [Note] InnoDB: Database was not shutdown normally!
2017-10-04 06:30:46 791 [Note] InnoDB: Starting crash recovery.
2017-10-04 06:30:46 791 [Note] InnoDB: Reading tablespace information from the .ibd files...
2017-10-04 06:30:46 791 [Note] InnoDB: Restoring possible half-written data pages 
2017-10-04 06:30:46 791 [Note] InnoDB: from the doublewrite buffer...
2017-10-04 06:30:46 791 [Warning] InnoDB: Resizing redo log from 2*320 to 2*3072 pages, LSN=1601736
2017-10-04 06:30:46 791 [Warning] InnoDB: Starting to delete and rewrite log files.
2017-10-04 06:30:46 791 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
2017-10-04 06:30:46 791 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
2017-10-04 06:30:46 791 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2017-10-04 06:30:46 791 [Warning] InnoDB: New log files created, LSN=1601736
2017-10-04 06:30:46 7f4abb50d740  InnoDB: Assertion failure in thread 139958946944832 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.
06:30:46 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=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=151
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 = 68108 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)[0x8e8bbb]
/usr/sbin/mysqld(handle_fatal_signal+0x491)[0x675481]
/lib64/libpthread.so.0(+0xf5e0)[0x7f4abb0ea5e0]
/lib64/libc.so.6(gsignal+0x37)[0x7f4ab9ce41f7]
/lib64/libc.so.6(abort+0x148)[0x7f4ab9ce58e8]
/usr/sbin/mysqld[0x988569]
/usr/sbin/mysqld(_Z7yyparsev+0xe5b)[0xabc90b]
/usr/sbin/mysqld[0x989ef1]
/usr/sbin/mysqld[0x98df07]
/usr/sbin/mysqld[0x9b3a24]
/usr/sbin/mysqld[0x9b57d1]
/usr/sbin/mysqld[0x96161e]
/usr/sbin/mysqld[0x9dc65f]
/usr/sbin/mysqld[0x91ab58]
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x48)[0x5b5958]
/usr/sbin/mysqld[0x6fde80]
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0x940)[0x7045b0]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x8ad)[0x5af31d]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f4ab9cd0c05]

Resolved:
stack_bottom = 0 thread_stack 0x40000
0x8e8bbb my_print_stacktrace + 59
0x675481 handle_fatal_signal + 1169
0x7f4abb0ea5e0 _end + -1177290672
0x7f4ab9ce41f7 _end + -1198287769
0x7f4ab9ce58e8 _end + -1198281896
0x988569 pars_update_statement(upd_node_t*, sym_node_t*, void*) + 1785
0xabc90b yyparse() + 3675
0x989ef1 pars_sql(pars_info_t*, char const*) + 145
0x98df07 que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) + 71
0x9b3a24 row_drop_table_for_mysql(char const*, trx_t*, bool, bool) + 2020
0x9b57d1 row_mysql_drop_temp_tables() + 881
0x96161e recv_recovery_rollback_active() + 46
0x9dc65f innobase_start_or_create_for_mysql() + 10975
0x91ab58 innobase_init(void*) + 2408
0x5b5958 ha_initialize_handlerton(st_plugin_int*) + 72
0x6fde80 plugin_initialize(st_plugin_int*) + 112
0x7045b0 plugin_init(int*, char**, int) + 2368
0x5af31d mysqld_main(int, char**) + 2221
0x7f4ab9cd0c05 _end + -1198367115
0x5a1e8d _start + 41
[4 Oct 2017 9:43] Alexey Kopytov
Is this a duplicate of bug #69274 ?
[4 Oct 2017 12:36] MySQL Verification Team
Hello Nikolai,

Thank you for the report.
This is most likely duplicate of Bug#69274.
This was easy to reproduce with "In-Place" upgrade method, and as our Shane pointed out in Bug#69274, "it is not supported to do upgrade + crash recovery in one step".  Also, as part of an in-place upgrade "If you use InnoDB, configure MySQL to perform a slow shutdown by setting innodb_fast_shutdown to 0" 

https://dev.mysql.com/doc/refman/5.6/en/upgrading.html#upgrade-procedure-inplace  

I noticed that if 5.5 is restarted post kill -9 and later cleanly shutdown then this issue is not observed. Please could you confirm this at your end too?

Probably more clarification in the In-place upgrade section? I mean the details as documented here - https://dev.mysql.com/doc/mysql-enterprise-backup/3.12/en/restore-upgrade.html
 
########
-- 5.5.57
rm -rf 87966
scripts/mysql_install_db --basedir=$PWD --datadir=$PWD/87966
bin/mysqld --no-defaults --basedir=$PWD --datadir=$PWD/87966 --core-file --socket=/tmp/mysql_ushastry.sock  --port=3306 --log-error=$PWD/87966/log.err 2>&1 &

[umshastr@hod03]/export/umesh/server/binaries/GABuilds/mysql-5.5.57:
[umshastr@hod03]/export/umesh/server/binaries/GABuilds/mysql-5.5.57: bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.57 MySQL Community Server (GPL)
.
root@localhost [(none)]> create database if not exists test; create temporary table test.t(c int) engine=innodb;select sleep(100);sleep 5;
-- Session 3 kill -9 mysqld
ERROR 2013 (HY000): Lost connection to MySQL server during query
root@localhost [(none)]> \q
Bye
[1]+  Killed                  bin/mysqld --no-defaults --basedir=$PWD --datadir=$PWD/87966 --core-file --socket=/tmp/mysql_ushastry.sock --port=3306 --log-error=$PWD/87966/log.err 2>&1

-- bring up 5.6 instance and point datadir to 5.5.57's datadir

[umshastr@hod03]/export/umesh/server/binaries/GABuilds: cd mysql-5.6.37/
[umshastr@hod03]/export/umesh/server/binaries/GABuilds/mysql-5.6.37: bin/mysqld --no-defaults --basedir=$PWD --datadir=/export/umesh/server/binaries/GABuilds/mysql-5.5.57/87966 --core-file --socket=/tmp/mysql_ushastry.sock  --port=3306 --log-error=/export/umesh/server/binaries/GABuilds/mysql-5.5.57/87966/log.err 2>&1 &
[1] 667
[umshastr@hod03]/export/umesh/server/binaries/GABuilds/mysql-5.6.37: 2017-10-04 10:58:54 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-10-04 10:58:54 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2017-10-04 10:58:54 0 [Note] bin/mysqld (mysqld 5.6.37) starting as process 667 ...

[1]+  Aborted                 (core dumped) bin/mysqld --no-defaults --basedir=$PWD --datadir=/export/umesh/server/binaries/GABuilds/mysql-5.5.57/87966 --core-file --socket=/tmp/mysql_ushastry.sock --port=3306 --log-error=/export/umesh/server/binaries/GABuilds/mysql-5.5.57/87966/log.err 2>&1

-- extract from error log
.
2017-10-04 10:58:55 7fdc31cba740  InnoDB: Assertion failure in thread 140583704962880 in file pars0pars.cc line 865
InnoDB: Failing assertion: sym_node->table != NULL
.
.
-- bt

(gdb) bt
#0  0x00007fdc318b2771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000664a4c in handle_fatal_signal (sig=6) at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/sql/signal_handler.cc:230
#2  <signal handler called>
#3  0x00007fdc302ac5d7 in raise () from /lib64/libc.so.6
#4  0x00007fdc302adcc8 in abort () from /lib64/libc.so.6
#5  0x0000000000958429 in pars_retrieve_table_def (sym_node=0x2d032b8)
    at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/pars/pars0pars.cc:865
#6  0x000000000095a90a in pars_update_statement (node=0x2d033a0, cursor_sym=0x0, search_cond=0x2d03670)
    at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/pars/pars0pars.cc:1280
#7  0x0000000000a77794 in yyparse () at pars0grm.y:442
#8  0x0000000000959495 in pars_sql (info=0x2cf5918,
    str=0xc3c098 "PROCEDURE DROP_TABLE_PROC () IS\nsys_foreign_id CHAR;\ntable_id CHAR;\nindex_id CHAR;\nforeign_id CHAR;\nspace_id INT;\nfound INT;\nDECLARE CURSOR cur_fk IS\nSELECT ID FROM SYS_FOREIGN\nWHERE FOR_NAME = :table"...) at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/pars/pars0pars.cc:2243
#9  0x000000000095e7e8 in que_eval_sql (info=0x2cf5918,
    sql=0xc3c098 "PROCEDURE DROP_TABLE_PROC () IS\nsys_foreign_id CHAR;\ntable_id CHAR;\nindex_id CHAR;\nforeign_id CHAR;\nspace_id INT;\nfound INT;\nDECLARE CURSOR cur_fk IS\nSELECT ID FROM SYS_FOREIGN\nWHERE FOR_NAME = :table"..., reserve_dict_mutex=0, trx=0x2cd5ca8)
    at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/que/que0que.cc:1244
#10 0x0000000000985d34 in row_drop_table_for_mysql (name=0x2cf20a8 "tmp/#sql7f9c_1_0", trx=0x2cd5ca8, drop_db=<optimized out>, nonatomic=<optimized out>)
    at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/row/row0mysql.cc:4199
#11 0x0000000000986fa3 in row_mysql_drop_temp_tables () at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/row/row0mysql.cc:4484
#12 0x000000000092fdea in recv_recovery_rollback_active () at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/log/log0recv.cc:3484
#13 0x00000000009aee8b in innobase_start_or_create_for_mysql () at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/srv/srv0start.cc:2613
#14 0x00000000008f456d in innobase_init (p=<optimized out>) at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/storage/innobase/handler/ha_innodb.cc:3428
#15 0x00000000005aa828 in ha_initialize_handlerton (plugin=0x28d6550) at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/sql/handler.cc:662
#16 0x00000000006ec351 in plugin_initialize (plugin=0x28d6550) at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/sql/sql_plugin.cc:1138
#17 0x00000000006f00f6 in plugin_init (argc=0x132788c <remaining_argc>, argv=0x27ef5c0, flags=0)
    at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/sql/sql_plugin.cc:1432
#18 0x000000000059cd5d in init_server_components () at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/sql/mysqld.cc:4905
#19 0x00000000005a1f45 in mysqld_main (argc=8, argv=0x27ef5c0) at /export/home/pb2/build/sb_0-23718186-1496438722.64/mysql-5.6.37/sql/mysqld.cc:5504
#20 0x00007fdc30298af5 in __libc_start_main () from /lib64/libc.so.6
#21 0x0000000000593a65 in _start ()
(gdb)

Thanks,
Umesh
[4 Oct 2017 12:53] Nikolai Ikhalainen
Hi,

> I noticed that if 5.5 is restarted post kill -9 and later cleanly shutdown then this issue is not observed.
> Please could you confirm this at your end too?

Thank you!
the issue resolved with clean shutdown (set global innodb_fast_shutdown=0;) before upgrade. Looks clearly as a duplicate for 69274.