apply log crashes - signal 11 (ib_warn_row_too_big)

[babine]

Trying to innobackupex from a "5.5.38-35.2-log Percona Server (GPL), Release 35.2, Revision 674" master to a new slave.

apply-log fails with "19:04:21 UTC - xtrabackup got signal 11 ;"

Stack trace is as follow :
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x2b) [0x8ed15b]
xtrabackup(handle_fatal_signal+0x252) [0x799182]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0) [0x7f6a8e1f50a0]
xtrabackup(THD::raise_condition(unsigned int, char const*, Sql_condition::enum_warning_level, char const*)+0x22) [0x7d3e92]
xtrabackup(push_warning_printf(THD*, Sql_condition::enum_warning_level, unsigned int, char const*, ...)+0xb9) [0x8862d9]
xtrabackup(ib_warn_row_too_big(dict_table_t const*)+0x7f) [0x69bbff]
xtrabackup(dict_index_add_to_cache(dict_table_t*, dict_index_t*, unsigned long, unsigned long)+0x94b) [0x7284cb]
xtrabackup() [0x6a35fb]
xtrabackup(dict_load_table(char const*, unsigned long, dict_err_ignore_t)+0xb7e) [0x6a108e]
xtrabackup(dict_load_table_on_id(unsigned long, dict_err_ignore_t)+0x4ff) [0x6a1f7f]
xtrabackup(dict_table_open_on_id(unsigned long, unsigned long, dict_table_op_t)+0xf8) [0x726dc8]
xtrabackup(row_purge_step(que_thr_t*)+0x19f) [0x93e3ef]
xtrabackup(que_run_threads(que_thr_t*)+0x530) [0x71da10]
xtrabackup(trx_purge(unsigned long, unsigned long, bool)+0x97e) [0x6aea2e]
xtrabackup(srv_purge_coordinator_thread+0x53e) [0x63377e]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50) [0x7f6a8e1ecb50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f6a8c8b970d]

ib_warn_row_too_big may mean it's somehow related to https://bugs.launchpad.net/ius/+bug/1398199

Attached is the full log.

Relevant version numbers (on the new slave where apply log is run) :
ii libmysqlclient18:amd64 5.5.41-0+wheezy1 amd64 MySQL database client library
ii mysql-common 5.5.41-0+wheezy1 all MySQL database common files, e.g. /etc/mysql/my.cnf
ii percona-xtrabackup 2.2.8-5059-1.wheezy amd64 Open source backup tool for InnoDB and XtraDB
ii xtrabackup 2.2.8-5059-1.wheezy all Transitional package for percona-xtrabackup

[babine (babine)]

Downgraded from (debian package)

xtrabackup version 2.2.8 based on MySQL server 5.6.22 Linux (x86_64) (revision id: )

to

xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )

And it did finish correctly.

[Sergei Glushchenko (sergei.glushchenko)]

Regression was introduced in server with this commit

        revno: 2875.469.109
        committer: Annamalai Gurusami <email address hidden>
        branch nick: mysql-5.5
        timestamp: Wed 2014-09-17 10:42:31 +0530
        message:
          Bug #17852083 PRINT A WARNING WHEN DDL HAS AN ERROR IN INNODB_STRICT_MODE = 1

          Problem:

          Creation of a table fails when innodb_strict_mode is enabled, but the same
          table is created without any warning when innodb_strict_mode is enabled.

          Solution:

          If creation of a table fails with an error when innodb_strict_mode is
          enabled, it must issue a warning when innodb_strict_mode is disabled.

          rb#6723 approved by Krunal.

It tries to raise SQL level warning when no user threads are running. Should be reproducible with Oracle MySQL during recovery.

[Laurent Minost (lolomin)]

Hi,

I'm not really totally sure but does this stack trace is related to the above bug please ? :

xtrabackup version 2.2.10 based on MySQL server 5.6.22 Linux (x86_64) (revision id: )
xtrabackup: cd to /data/mysql
xtrabackup: This target seems to be not prepared yet.
2015-04-10 18:02:13 7fe076d33740 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
xtrabackup: Warning: cannot open ./xtrabackup_logfile. will try to find.
  xtrabackup: 'ib_logfile0' seems to be 'xtrabackup_logfile'. will retry.
xtrabackup: xtrabackup_logfile detected: size=2981888, start_lsn=(2529057519583)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2981888
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2981888
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.7
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: The log sequence numbers 2387850439738 and 2387850439738 in ibdata files do not match the log sequence number 2529057519583 in the ib_logfiles!
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer...
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
16:02:13 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
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.

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 0x10000
InnoDB: 5.6.22 started; log sequence number 2529057519583
xtrabackup(my_print_stacktrace+0x2b) [0x8ed1db]
xtrabackup(handle_fatal_signal+0x252) [0x799202]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0) [0x7fe07691f8d0]
xtrabackup(THD::raise_condition(unsigned int, char const*, Sql_condition::enum_warning_level, char const*)+0x22) [0x7d3f12]
xtrabackup(push_warning_printf(THD*, Sql...

[Sergei Glushchenko (sergei.glushchenko)]

Hi Laurent,

This stack trace looks related to the bug. I also added the reference to the upstream MySQL bug report.

[Laurent Minost (lolomin)]

Hi Sergei,

Thanks for confirmation.

Is there any workaround at the moment please ?

I've just upgraded the concerned node in PXDBC to v5.5.41-25.11-853.wheezy and Percona Xtrabackup to v2.2.10-1.wheezy and faced this bug but after trying to downgrade to v5.5.37 of PXDBC and v2.2.3 of Percona Xtrabackup, the server still crashes but with another stack trace described in this thread : http://www.percona.com/forums/questions-discussions/mysql-and-percona-server/33640-production-percona-db-crashing-repeatedly ... :(

Regards,

Laurent

[Sergei Glushchenko (sergei.glushchenko)]

upstream fix:

commit 901ce5314b6b0d4115b0237491e2afaafe5a274e
Author: Thiru <email address hidden>
Commit: Thiru <email address hidden>

    Bug #20144839 AFTER UPDATING TO MYSQL 5.6.22 SERVER
                CRASHES ON EVERY START ATTEMPT

    Description:
    ------------
    push_warning_printf function is used to print the warning message
    to the client. So this function should not invoke while recovering
    the server. Moreover current_thd is NULL while starting the server.

    Solution:
    ---------
     - Avoiding the warning to be printed while recovery.
    This patch already pushed in mysql-5.6.

diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
index fab832d..676a20f 100644
--- a/storage/innobase/handler/ha_innodb.cc
+++ b/storage/innobase/handler/ha_innodb.cc
@@ -12102,6 +12102,10 @@ ib_warn_row_too_big(const dict_table_t* table)

        THD* thd = current_thd;

+ if (thd == NULL) {
+ return;
+ }
+
        push_warning_printf(
                thd, MYSQL_ERROR::WARN_LEVEL_WARN, HA_ERR_TO_BIG_ROW,
                "Row size too large (> %lu). Changing some columns to TEXT"

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-xtrabackup/pull/60
https://github.com/percona/percona-xtrabackup/pull/61

[Jervin R (revin)]

This is still happening on one customer server with slightly shorter trace. PXB 2.2.11, custom built on Gentoo (cmake . && make -j8)

17:01:56 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
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.

Thread pointer: 0x124bf20
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 0x10000
xtrabackup(my_print_stacktrace+0x2e) [0x9620ee]
xtrabackup(handle_fatal_signal+0x24a) [0x7cf98a]
/lib/libpthread.so.0(+0xf510) [0x7f5a759f8510]
xtrabackup(THD::raise_condition(unsigned int, char const*, Sql_condition::enum_warning_level, char const*)+0x5d) [0x733c3d]
xtrabackup(push_warning_printf(THD*, Sql_condition::enum_warning_level, unsigned int, char const*, ...)+0xcd) [0x72c48d]
xtrabackup(ib_warn_row_too_big(dict_table_t const*)+0x87) [0x5d2497]
xtrabackup(dict_index_add_to_cache(dict_table_t*, dict_index_t*, unsigned long, unsigned long)+0x4ac) [0x6fa55c]
xtrabackup() [0x6a7294]
xtrabackup(dict_load_table(char const*, unsigned long, dict_err_ignore_t)+0x977) [0x6a6087]
xtrabackup() [0x5a226e]
xtrabackup(main+0x8b9) [0x5a37f9]
/lib/libc.so.6(__libc_start_main+0xe6) [0x7f5a7402eba6]
xtrabackup() [0x598aa5]

Please report a bug at https://bugs.launchpad.net/percona-xtrabackup
innobackupex: got a fatal error with the following stacktrace: at /usr/bin/innobackupex line 2641
 main::apply_log() called at /usr/bin/innobackupex line 1570
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2641.

[Sergei Glushchenko (sergei.glushchenko)]

Probably a merge issue in upstream MySQL. Looks like patch from comment #7 haven't ended up in upstream MySQL 5.6.24. Does patch itself work?

[Sergei Glushchenko (sergei.glushchenko)]

That is from history:

origin/mysql-server - [5.6] » git show --pretty=full 901ce53
commit 901ce5314b6b0d4115b0237491e2afaafe5a274e
Author: Thiru <email address hidden>
Commit: Thiru <email address hidden>

    Bug #20144839 AFTER UPDATING TO MYSQL 5.6.22 SERVER
                CRASHES ON EVERY START ATTEMPT

    Description:
    ------------
    push_warning_printf function is used to print the warning message
    to the client. So this function should not invoke while recovering
    the server. Moreover current_thd is NULL while starting the server.

    Solution:
    ---------
     - Avoiding the warning to be printed while recovery.
    This patch already pushed in mysql-5.6.

diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
index fab832d..676a20f 100644
--- a/storage/innobase/handler/ha_innodb.cc
+++ b/storage/innobase/handler/ha_innodb.cc
@@ -12102,6 +12102,10 @@ ib_warn_row_too_big(const dict_table_t* table)

        THD* thd = current_thd;

+ if (thd == NULL) {
+ return;
+ }
+
        push_warning_printf(
                thd, MYSQL_ERROR::WARN_LEVEL_WARN, HA_ERR_TO_BIG_ROW,
                "Row size too large (> %lu). Changing some columns to TEXT"
origin/mysql-server - [5.6] » git show --pretty=full 7b17ebb
commit 7b17ebbd86fc9459d14e93760b1d45e327615cc9
Merge: 4423b9b 901ce53
Author: Thiru <email address hidden>
Commit: Thiru <email address hidden>

    Bug #20144839 AFTER UPDATING TO MYSQL 5.6.22 SERVER
                CRASHES ON EVERY START ATTEMPT

        NULL merge from mysql-5.5 to mysql-5.6

Comment states that patch is already pushed to 5.6, but it is not the case...

[Sergei Glushchenko (sergei.glushchenko)]

OK. Patch above was pushed to 5.5. Fix for 5.6 was:

origin/mysql-server - [5.6] » git show --pretty=full a61c0774ff02361edea2ce0a011095d122d86dc8
commit a61c0774ff02361edea2ce0a011095d122d86dc8
Author: Thiru <email address hidden>
Commit: Thiru <email address hidden>

    Bug #20144839 AFTER UPDATING TO MYSQL 5.6.22 SERVER CRASHES ON EVERY START ATTEMPT

    Description:

    push_warning_printf function is used to print the warning message
    to the client. So this function should not invoke while recovering
    the server. Moreover current_thd is NULL while starting the server.

    Solution:

    Avoiding the warning to be printed while recovery.

    Reviewed-by: Jimmy Yang <email address hidden>
    RB: 7511

diff --git a/storage/innobase/dict/dict0dict.cc b/storage/innobase/dict/dict0dict.cc
index 8c5b9c4..8045389 100644
--- a/storage/innobase/dict/dict0dict.cc
+++ b/storage/innobase/dict/dict0dict.cc
@@ -2423,10 +2423,10 @@ too_big:
                        dict_mem_index_free(new_index);
                        dict_mem_index_free(index);
                        return(DB_TOO_BIG_RECORD);
- } else {
-
+ } else if (current_thd != NULL) {
+ /* Avoid the warning to be printed
+ during recovery. */
                        ib_warn_row_too_big(table);
-
                }
        }

And it present in both PXB 2.2.11 and MySQL 5.6.24. Apparently it doesn't work in all cases.

[Sergei Glushchenko (sergei.glushchenko)]

For xtrabackup, current_thd is not null. We probably should make sure that we set current_thd same way as it done for InnoDB. I will investigate and file a bug if needed.

[Laurent Minost (lolomin)]

Hi Sergei,

Still having this problem with my PXDBC installation of 5.5.41-25.11-853 using Percona Xtrabackup v2.2.11-1.wheezy, but it seems that all xtrabackup/innobackupex part is doing well :

innobackup.move.log and innobackup.prepare.log are both reporting :
150630 08:55:16 innobackupex: completed OK!

But after all this process, mysql is crashing at start :

150630 8:55:17 [Note] WSREP: SST complete, seqno: 20200769
150630 8:55:17 [Warning] Using unique option prefix myisam_recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
150630 8:55:17 [Note] Plugin 'FEDERATED' is disabled.
150630 8:55:17 InnoDB: The InnoDB memory heap is disabled
150630 8:55:17 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150630 8:55:17 InnoDB: Compressed tables use zlib 1.2.7
150630 8:55:17 InnoDB: Using Linux native AIO
150630 8:55:17 InnoDB: Initializing buffer pool, size = 20.0G
150630 8:55:18 InnoDB: Completed initialization of buffer pool
150630 8:55:18 InnoDB: highest supported file format is Barracuda.
150630 8:55:19 InnoDB: Waiting for the background threads to start
06:55:20 UTC - mysqld got signal 11 ;
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 XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=268435456
read_buffer_size=131072
max_used_connections=0
max_threads=702
thread_count=2
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1798672 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+0x29)[0x7abeb9]
/usr/sbin/mysqld(handle_fatal_signal+0x372)[0x6aa6d2]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f5e078e78d0]
/usr/sbin/mysqld(_ZN3THD15raise_conditionEjPKcN11MYSQL_ERROR18enum_warning_levelES1_+0x22)[0x589062]
/usr/sbin/mysqld(_Z19push_warning_printfP3THDN11MYSQL_ERROR18enum_warning_levelEjPKcz+0xc7)[0x596d17]
/usr/sbin/mysqld(ib_warn_row_too_big+0x6d)[0x7d2d5d]
/usr/sbin/mysqld[0x869bbc]
/usr/sbin/mysqld[0x8774d3]
/usr/sbin/mysqld[0x8748cd]
/usr/sbin/mysqld[0x873a88]
/usr/sbin/mysqld[0x874e56]
/usr/sbin/mysqld[0x873a88]
/usr/sbin/mysqld[0x874e56]
/usr/sbin/mysqld[0x873a88]
/usr/sbin/mysqld[0x874e56]
/usr/sbin/mysqld[0x8753da]
/usr/sbin/mysqld[0x8e4220]
/usr/sbin/mysqld[0x8dd158]
/usr/sbin/mysqld[0x80e126]
/usr/sbin/mysqld[0x8040fc]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x80a4)[0x7f5e078e00a4]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f5e...

[Sergei Glushchenko (sergei.glushchenko)]

Hi Laurent,

Upstream bug fix released in 5.5.42. I suggest to upgrade.
For possible xtrabackup issues track bug 1467574.

[Laurent Minost (lolomin)]

Thanks Sergei for this informations but 5.5.42 is at my knowledge not yet released for Percona XtraDB Cluster ?

Regards,

Laurent

[Sergei Glushchenko (sergei.glushchenko)]

It is according to this blog post https://www.percona.com/blog/2015/03/04/percona-server-5-5-42-37-1-now-available/ and 5.5.43 is released as well.

[Sergei Glushchenko (sergei.glushchenko)]

Ah, sorry, it is Percona Server, not Cluster.

[Sergei Glushchenko (sergei.glushchenko)]

I wonder if downgrade to 5.5.40 will help. The bug was introduced in 5.5.41.

[Laurent Minost (lolomin)]

I will try to downgrade to https://www.percona.com/downloads/Percona-XtraDB-Cluster/Percona-XtraDB-Cluster-5.5.39-25.11/binary/debian/wheezy/x86_64/Percona-XtraDB-Cluster-5.5.39-25.11-r824-wheezy-x86_64-bundle.tar and will let you now , thks ! :)

[Shahriyar Rzayev (rzayev-sehriyar)]

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