InnoDB error after 5.5 - 5.6 upgrade on Slave

[Michael Shield]

Hi,

We are doing a 5.5 mysql to 5.6 Percona server update, Master has completed, as has 2nd slave.

Main slave failed during the "--skip-grant-tables" phase, following the upgrade guide.

I have tried defining the tmpdir, but this appears to make no difference.

error is as follows. Note the replication on both slaves had been stopped prior to the update beginning on the master. A similar group of files were present on the second slave, but after a failed attempt to restart replication, they were removed, and no further errors occured on that server.

Master vr4
primary slave vr11
secondary slave vr9

[root@h77-245-67-66 tmp]# /usr/sbin/mysqld --skip-grant-tables --user=mysql &
[1] 13162
[root@h77-245-67-66 tmp]# 2017-09-25 10:18:04 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation f or more details).
2017-09-25 10:18:04 0 [Note] /usr/sbin/mysqld (mysqld 5.6.37-82.2-log) starting as process 13162 ...
2017-09-25 10:18:04 13162 [Note] Plugin 'FEDERATED' is disabled.
2017-09-25 10:18:04 13162 [Note] InnoDB: Using atomics to ref count buffer pool pages
2017-09-25 10:18:04 13162 [Note] InnoDB: The InnoDB memory heap is disabled
2017-09-25 10:18:04 13162 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-09-25 10:18:04 13162 [Note] InnoDB: Memory barrier is not used
2017-09-25 10:18:04 13162 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-09-25 10:18:04 13162 [Note] InnoDB: Using Linux native AIO
2017-09-25 10:18:04 13162 [Note] InnoDB: Using CPU crc32 instructions
2017-09-25 10:18:04 13162 [Note] InnoDB: Initializing buffer pool, size = 24.0G
2017-09-25 10:18:04 13162 [Note] InnoDB: Completed initialization of buffer pool
2017-09-25 10:18:05 13162 [Note] InnoDB: Highest supported file format is Barracuda.
2017-09-25 10:18:05 7fbb539fa7e0 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
2017-09-25 10:18:05 13162 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysqltmp/#sqld17_dd9ab8_6592'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadic t.html for how to resolve the issue.
2017-09-25 10:18:05 13162 [ERROR] InnoDB: Tablespace open failed for '"mysqltmp"."#sqld17_dd9ab8_6592"', ignored.
2017-09-25 10:18:05 7fbb539fa7e0 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
2017-09-25 10:18:05 13162 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysqltmp/#sqld17_dd9ab8_6593'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadic t.html for how to resolve the issue.
2017-09-25 10:18:05 13162 [ERROR] InnoDB: Tablespace open failed for '"mysqltmp"."#sqld17_dd9ab8_6593"', ignored.
2017-09-25 10:18:05 7fbb539fa7e0 InnoDB: Assertion failure in thread 140442538584032 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.
09:18:05 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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=67108864
read_buffer_size=4194304
max_used_connections=0
max_threads=4098
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 = 33693261 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 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8da27c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x65b061]
/lib64/libpthread.so.0[0x3e9b40f7e0]
/lib64/libc.so.6(gsignal+0x35)[0x3e9ac325e5]
/lib64/libc.so.6(abort+0x175)[0x3e9ac33dc5]
/usr/sbin/mysqld[0x9b4669]
/usr/sbin/mysqld(_Z7yyparsev+0xe1b)[0xaf722b]
/usr/sbin/mysqld[0x9b5f71]
/usr/sbin/mysqld[0x9b9f56]
/usr/sbin/mysqld[0x9e121c]
/usr/sbin/mysqld[0x9e333d]
/usr/sbin/mysqld[0x98e23e]
/usr/sbin/mysqld[0xa0b543]
/usr/sbin/mysqld[0x94767c]
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x48)[0x59bc58]
/usr/sbin/mysqld[0x6e9ee1]
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0x982)[0x6f04b2]
/usr/sbin/mysqld[0x5944fd]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x40d)[0x59557d]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x3e9ac1ed1d]
/usr/sbin/mysqld[0x586e8d]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.

[1]+ Exit 1 /usr/sbin/mysqld --skip-grant-tables --user=mysql

Do you have any suggestions ? I could either restore this mornings backup and roll forward, create a new set of backup data on the master and replace on the primary slave, but would need to be able to start the DB first.

Thanks,

Mike Shield

[Michael Shield (mike.shield)]

Forgot to add, we have added innodb_force_recovery = 1 to the cnf file, with no obvious effect

[Michael Shield (mike.shield)]

This has moved on.

Increasing innodb_force_recovery to be 3 allowed us to continue.

We were then only able to connect to the DB if we switched from socket to TCP.

mysql_upgrade completed, restarted, still can't use socket, and following error is now preventing replication from starting.

2017-09-25 13:16:03 30267 [Note] Plugin 'FEDERATED' is disabled.
2017-09-25 13:16:03 30267 [Note] InnoDB: Using atomics to ref count buffer pool pages
2017-09-25 13:16:03 30267 [Note] InnoDB: The InnoDB memory heap is disabled
2017-09-25 13:16:03 30267 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-09-25 13:16:03 30267 [Note] InnoDB: Memory barrier is not used
2017-09-25 13:16:03 30267 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-09-25 13:16:03 30267 [Note] InnoDB: Using Linux native AIO
2017-09-25 13:16:03 30267 [Note] InnoDB: Using CPU crc32 instructions
2017-09-25 13:16:03 30267 [Note] InnoDB: Initializing buffer pool, size = 24.0G
2017-09-25 13:16:03 30267 [Note] InnoDB: Completed initialization of buffer pool
2017-09-25 13:16:03 30267 [Note] InnoDB: Highest supported file format is Barracuda.
2017-09-25 13:16:04 30267 [Note] InnoDB: 128 rollback segment(s) are active.
2017-09-25 13:16:04 30267 [Note] InnoDB: Waiting for purge to start
2017-09-25 13:16:04 30267 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.37-82.2 started; log sequence number 6416161641968
2017-09-25 13:16:04 30267 [Note] Recovering after a crash using mysql-bin
2017-09-25 13:16:04 30267 [Note] Starting crash recovery...
2017-09-25 13:16:04 30267 [Note] Crash recovery finished.
2017-09-25 13:16:04 30267 [Note] RSA private key file not found: /home/mysql//private_key.pem. Some authentication plugins will not work.
2017-09-25 13:16:04 30267 [Note] RSA public key file not found: /home/mysql//public_key.pem. Some authentication plugins will not work.
2017-09-25 13:16:04 30267 [Note] Server hostname (bind-address): '*'; port: 3306
2017-09-25 13:16:04 30267 [Note] IPv6 is available.
2017-09-25 13:16:04 30267 [Note] - '::' resolves to '::';
2017-09-25 13:16:04 30267 [Note] Server socket created on IP: '::'.
2017-09-25 13:16:04 30267 [Warning] Found an entry in the 'db' table with empty database name; Skipped
2017-09-25 13:16:04 30267 [Warning] Found an entry in the 'db' table with empty database name; Skipped
2017-09-25 13:16:04 30267 [Warning] Found an entry in the 'db' table with empty database name; Skipped
2017-09-25 13:16:04 30267 [Warning] Found an entry in the 'db' table with empty database name; Skipped
2017-09-25 13:16:04 30267 [Warning] Found an entry in the 'db' table with empty database name; Skipped
2017-09-25 13:16:04 30267 [Warning] Found an entry in the 'db' table with empty database name; Skipped
2017-09-25 13:16:04 30267 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=h77-245-67-66-relay-bin' to avoid this problem.
2017-09-25 13:16:04 30267 [ERROR] Failed to open the relay log './mysqld-relay-bin.098231' (relay_log_pos 92593655).
2017-09-25 13:16:04 30267 [ERROR] Could not find target log file mentione...

[Nickolay Ihalainen (ihanick)]

Slave servers during upgrade should be started with --skip-slave-start in addition to skip grant
https://dev.mysql.com/doc/refman/5.6/en/replication-upgrade.html

Before upgrade, make a clean shutdown, if you have orphan tables, drop it before upgrade: https://dev.mysql.com/doc/refman/5.5/en/innodb-troubleshooting-datadict.html

I'm able to reproduce your crash with percona server 5.5.57-38.9 to 5.6.37-82.2 upgrade.

docker run -it -e MYSQL_ALLOW_EMPTY_PASSWORD=1 \
 --name lp1719284 --entrypoint=/bin/bash percona:5.5

mysql_install_db; chown -R /var/lib/mysql
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_safe) $(pgrep -xn mysqld)
cp -ap /var/lib/mysql /var/lib/mysql1/
rm -rf /var/lib/mysql/*
apt-get install -y percona-server-5.6
rm -rf /var/lib/mysql/*
cp -ap /var/lib/mysql1/* /var/lib/mysql/
mysqld_safe --skip-grant-tables

2017-10-04 05:39:40 7fd461df1740 InnoDB: Assertion failure in thread 140550151804736 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.
05:39:40 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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=0
max_threads=153
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 = 77247 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 0x30000
0x8c42fc my_print_stacktrace + 44
0x64b939 handle_fatal_signal + 1129
0x7fd4619d1890 _end + 1617425736
0x7fd45f957067 _end + 1583369503
0x7fd45f958448 _end + 1583374592
0x99503f pars_update_statement(upd_node_t*, sym_node_t*, void*) + 1663
0xad237e yyparse() + 2462
0x996a5f pars_sql(pars_info_t*, char const*) + 143
0x99a906 que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) + 70
0x9c1487 row_drop_table_for_mysql(char const*, trx_t*, bool, bool) + 1975
0x9c3512 row_mysql_drop_temp_tables() + 1474
0x96eb8e recv_recovery_rollback_active() + 46
0x9eafae innobase_start_or_create_for_mysql() + 1...

[Nickolay Ihalainen (ihanick)]

Percona Server 5.7.19-17 is also affected.

017-10-04 06:58:20 0x7fc9c1126740 InnoDB: Assertion failure in thread 140504504362816 in file pars0pars.cc line 822
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.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
06:58:20 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.
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=152
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 = 68315 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 0x30000
0xe92eac my_print_stacktrace + 44
0x79b0f9 handle_fatal_signal + 1145
0x7fc9c0d06890 _end + -1092175160
0x7fc9bec8c067 _end + -1126231393
0x7fc9bec8d448 _end + -1126226304
0x76f463 ut_dbg_assertion_failed(char const*, char const*, unsigned long) + 173
0xfeae28 pars_update_statement(upd_node_t*, sym_node_t*, void*) + 1352
0x120c21e yyparse() + 2462
0xfe986e pars_sql(pars_info_t*, char const*) + 158
0xfee592 que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) + 82
0x1032b30 row_drop_table_for_mysql(char const*, trx_t*, bool, bool, dict_table_t*) + 2304
0x10353e9 row_mysql_drop_temp_tables() + 1193
0xfa2bce recv_recovery_rollback_active() + 46
0x1087ac6 innobase_start_or_create_for_mysql() + 18486
0xf3be19 innobase_init(void*) + 3849
0x7fc011 ha_initialize_handlerton(st_plugin_int*) + 81
0xc895f6 plugin_initialize(st_plugin_int*) + 86
0xc913b8 plugin_init(int*, char**, int) + 1464
0x7932a6 init_server_components() + 982
0x794a49 mysqld_main(int, char**) + 2105
0x7fc9bec78b45 _end + -1126310531
0x78afb4 _start + 41

[Michael Shield (mike.shield)]

Nickolay ,

Thanks for your input, it would appear that I would have probably done much
better here if I'd seen the first article you referred to, which was very
clear on the correct order of upgrade.

We recovered in the end by restoring from a backup taken from another slave
which had been upgraded to 5.6, though I had to check a number of tables
once the restore completed.

Perhaps a link could be added to any Percona upgrade docs for clarity. I
suspect that an earlier successful upgrade test in AWS had given a false
sense of security.

Cheers,

MIke

*Mike Shield*
Systems & Database Lead Engineer
[phone] Office
[phone] Mobile

On 4 October 2017 at 08:03, Nickolay Ihalainen <email address hidden> wrote:

> Percona Server 5.7.19-17 is also affected.
>
> 017-10-04 06:58:20 0x7fc9c1126740 InnoDB: Assertion failure in thread
> 140504504362816 in file pars0pars.cc line 822
> 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.7/en/forcing-innodb-
> recovery.html
> InnoDB: about forcing recovery.
> 06:58:20 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.
> 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.
> Please help us make Percona Server better by reporting any
> bugs at http://bugs.percona.com/
>
> key_buffer_size=8388608
> read_buffer_size=131072
> max_used_connections=0
> max_threads=152
> 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 =
> 68315 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 0x30000
> 0xe92eac my_print_stacktrace + 44
> 0x79b0f9 handle_fatal_signal + 1145
> 0x7fc9c0d06890 _end + -1092175160
> 0x7fc9bec8c067 _end + -1126231393
> 0x7fc9bec8d448 _end + -1126226304
> 0x76f463 ut_dbg_assertion_failed(char const*, char const*, unsigned long)
> + 173
> 0xfeae28 pars_update_statement(upd_node_t*, sym_node_t*, void*) + 1352
> 0x120c21e yyparse() + 2462
> 0xfe986e pars_sql(pars_info_t*, char const*) + 158
> 0xfee592 que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) +
> 82
> 0x1032b30 row_drop_table_for_mysql(char const*, trx_t*, bool, bool,
> dict_table_t*) + 2304
> 0x10353e9 row_mysql_drop_temp_tables() + 1193
> 0xfa2bce recv_recovery_rollback_active() + 46...

[Nickolay Ihalainen (ihanick)]

Hi Michael,

The problem caused by incorrect upgrade procedure.

In place upgrade to mysql 5.6 or 5.7 require shutdown with innodb_fast_shutdown=0 before upgrading packages.

For current state: install 5.5 binaries, start mysqld with skip-slave-start, prevent external connections from application, execute innodb_fast_shutdown=0, shutdown mysqld.

For details you can look inside: https://bugs.mysql.com/bug.php?id=69274

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3743