segmentation faults from mtr rpl suite

Bug #1367173 reported by Teemu Ollakka on 2014-09-09
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL patches by Codership
Status tracked in 5.6
5.5
High
Teemu Ollakka
5.6
High
Teemu Ollakka
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
Status tracked in 5.6
5.5
New
Undecided
Unassigned
5.6
Fix Released
Undecided
Unassigned

Bug Description

Run mtr rpl tests without wsrep provider loaded, some of the rpl tests fail:

rpl.rpl_row_crash_safe 'row' [ fail ]
        Test ended at 2014-09-09 11:57:46

CURRENT_TEST: rpl.rpl_row_crash_safe

Server [mysqld.2 - pid: 13456, winpid: 13456, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2014-09-09 11:57:41 0 [Warning] The syntax '--master-retry-count' is deprecated and will be removed in a future release. Please use 'CHANGE MASTER TO master_retry_count = <num>' instead.
2014-09-09 11:57:41 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-09-09 11:57:41 13337 [Warning] Buffered warning: Could not increase number of max_open_files to more than 1024 (request: 4161)

2014-09-09 11:57:41 13337 [Warning] Buffered warning: Changed limits: table_cache: 431 (requested 2000)

2014-09-09 11:57:41 13337 [Note] Plugin 'FEDERATED' is disabled.
2014-09-09 11:57:41 7f7e5dbd5780 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2014-09-09 11:57:41 13337 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-09-09 11:57:41 7f7e5dbd5780 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2014-09-09 11:57:41 7f7e5dbd5780 InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2014-09-09 11:57:41 13337 [Note] InnoDB: The InnoDB memory heap is disabled
2014-09-09 11:57:41 13337 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-09-09 11:57:41 13337 [Note] InnoDB: Memory barrier is not used
2014-09-09 11:57:41 13337 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-09-09 11:57:41 13337 [Note] InnoDB: Using Linux native AIO
2014-09-09 11:57:41 13337 [Note] InnoDB: Using CPU crc32 instructions
2014-09-09 11:57:41 13337 [Note] InnoDB: Initializing buffer pool, size = 256.0M
2014-09-09 11:57:41 13337 [Note] InnoDB: Completed initialization of buffer pool
2014-09-09 11:57:41 13337 [Note] InnoDB: Highest supported file format is Barracuda.
2014-09-09 11:57:42 13337 [Note] InnoDB: 128 rollback segment(s) are active.
2014-09-09 11:57:42 13337 [Note] InnoDB: Waiting for purge to start
2014-09-09 11:57:42 13337 [Note] InnoDB: 5.6.20 started; log sequence number 1625977
2014-09-09 11:57:42 13337 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 5bec9613-37ff-11e4-b557-ec55f9513043.
2014-09-09 11:57:42 13337 [Note] Server hostname (bind-address): '*'; port: 13001
2014-09-09 11:57:42 13337 [Note] IPv6 is available.
2014-09-09 11:57:42 13337 [Note] - '::' resolves to '::';
2014-09-09 11:57:42 13337 [Note] Server socket created on IP: '::'.
2014-09-09 11:57:42 13337 [Note] Event Scheduler: Loaded 0 events
2014-09-09 11:57:42 13337 [Note] WSREP: Read nil XID from storage engines, skipping position init
2014-09-09 11:57:42 13337 [Note] WSREP: wsrep_load(): loading provider library 'none'
2014-09-09 11:57:42 13337 [Note] /home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld: ready for connections.
Version: '5.6.20-debug-log' socket: '/home/teemu/work/bzr/codership-mysql/5.6/build_debug/mysql-test/var/tmp/mysqld.2.sock' port: 13001 , wsrep_25.6.r4134
2014-09-09 11:57:42 13337 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port= 3306, master_log_file='', master_log_pos= 4, master_bind=''. New state master_host='127.0.0.1', master_port= 13000, master_log_file='master-bin.000001', master_log_pos= 4, master_bind=''.
2014-09-09 11:57:43 13337 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2014-09-09 11:57:43 13337 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:13000',replication started in log 'master-bin.000001' at position 4
2014-09-09 11:57:43 13337 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
2014-09-09 11:57:43 13337 [Note] Error reading relay log event: slave SQL thread was killed
2014-09-09 11:57:43 13337 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
2014-09-09 11:57:43 13337 [Note] Slave I/O thread killed while reading event
2014-09-09 11:57:43 13337 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 1588
2014-09-09 11:57:43 13337 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2014-09-09 11:57:43 13337 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:13000',replication started in log 'master-bin.000001' at position 1588
2014-09-09 11:57:43 13337 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 1588, relay log './slave-relay-bin.000002' position: 1752
2014-09-09 11:57:43 13337 [Note] Error reading relay log event: slave SQL thread was killed
2014-09-09 11:57:43 13337 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 11425, relay log './slave-relay-bin.000003' position: 10121
2014-09-09 11:57:44 13337 [Note] Crashing crash_after_apply.
SIGKILL myself
2014-09-09 11:57:44 0 [Warning] The syntax '--master-retry-count' is deprecated and will be removed in a future release. Please use 'CHANGE MASTER TO master_retry_count = <num>' instead.
2014-09-09 11:57:44 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-09-09 11:57:44 13457 [Warning] Buffered warning: Could not increase number of max_open_files to more than 1024 (request: 4161)

2014-09-09 11:57:44 13457 [Warning] Buffered warning: Changed limits: table_cache: 431 (requested 2000)

2014-09-09 11:57:44 13457 [Note] Plugin 'FEDERATED' is disabled.
2014-09-09 11:57:44 7fb6571da780 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2014-09-09 11:57:44 13457 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-09-09 11:57:44 7fb6571da780 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2014-09-09 11:57:44 7fb6571da780 InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2014-09-09 11:57:44 13457 [Note] InnoDB: The InnoDB memory heap is disabled
2014-09-09 11:57:44 13457 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-09-09 11:57:44 13457 [Note] InnoDB: Memory barrier is not used
2014-09-09 11:57:44 13457 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-09-09 11:57:44 13457 [Note] InnoDB: Using Linux native AIO
2014-09-09 11:57:44 13457 [Note] InnoDB: Using CPU crc32 instructions
2014-09-09 11:57:44 13457 [Note] InnoDB: Initializing buffer pool, size = 256.0M
2014-09-09 11:57:44 13457 [Note] InnoDB: Completed initialization of buffer pool
2014-09-09 11:57:44 13457 [Note] InnoDB: Highest supported file format is Barracuda.
2014-09-09 11:57:44 13457 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1625977
2014-09-09 11:57:44 13457 [Note] InnoDB: Database was not shutdown normally!
2014-09-09 11:57:44 13457 [Note] InnoDB: Starting crash recovery.
2014-09-09 11:57:44 13457 [Note] InnoDB: Reading tablespace information from the .ibd files...
2014-09-09 11:57:44 13457 [Note] InnoDB: Restoring possible half-written data pages
2014-09-09 11:57:44 13457 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1711704
InnoDB: Transaction 1368 was in the XA prepared state.
InnoDB: Transaction 1368 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 1792
2014-09-09 11:57:44 13457 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 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
InnoDB: Last MySQL binlog file position 0 6447, file name slave-bin.000001
InnoDB: Starting in background the rollback of uncommitted transactions
2014-09-09 11:57:46 7fb63d0ed700 InnoDB: Rollback of non-prepared transactions completed
2014-09-09 11:57:46 13457 [Note] InnoDB: 128 rollback segment(s) are active.
2014-09-09 11:57:46 13457 [Note] InnoDB: Waiting for purge to start
2014-09-09 11:57:46 13457 [Note] InnoDB: 5.6.20 started; log sequence number 1711704
2014-09-09 11:57:46 13457 [Note] Recovering after a crash using slave-bin
2014-09-09 11:57:46 13457 [Note] WSREP: Binlog recovery, found wsrep position 00000000-0000-0000-0000-000000000000:-1
2014-09-09 11:57:46 13457 [Note] WSREP: Binlog recovery scan stopped at Xid event 436
2014-09-09 11:57:46 13457 [Note] Starting crash recovery...
2014-09-09 11:57:46 7fb6571da780 InnoDB: Starting recovery for XA transactions...
2014-09-09 11:57:46 7fb6571da780 InnoDB: Transaction 1368 in prepared state after recovery
2014-09-09 11:57:46 7fb6571da780 InnoDB: Transaction contains changes to 2 rows
2014-09-09 11:57:46 7fb6571da780 InnoDB: 1 transactions in prepared state after recovery
2014-09-09 11:57:46 13457 [Note] Found 1 prepared transaction(s) in InnoDB
2014-09-09 11:57:46 13457 [Note] commit xid 'MySQLXid\2\0\0\0\0\0\0\0\264\1\0\0\0\0\0\0'
2014-09-09 11:57:46 13457 [Note] Crash recovery finished.
2014-09-09 11:57:46 13457 [Note] Server hostname (bind-address): '*'; port: 13001
2014-09-09 11:57:46 13457 [Note] IPv6 is available.
2014-09-09 11:57:46 13457 [Note] - '::' resolves to '::';
2014-09-09 11:57:46 13457 [Note] Server socket created on IP: '::'.
2014-09-09 11:57:46 13457 [Warning] Recovery from master pos 11623 and file master-bin.000001.
08:57:46 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.

key_buffer_size=1048576
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 = 61153 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x3133d40
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 = 7fff324bfc98 thread_stack 0x40000
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(my_print_stacktrace+0x38)[0xaa8fea]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(handle_fatal_signal+0x39f)[0x733f17]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7fb656796340]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld[0xb397c0]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_ZN11ha_innobase17wsrep_append_keysEP3THDbPKhS3_+0x6a2)[0xb39fe4]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld[0xb365fd]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_ZN7handler13ha_update_rowEPKhPh+0x171)[0x653f9b]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_ZN14Rpl_info_table13do_flush_infoEb+0x3f8)[0xa82158]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_ZN16Rpl_info_handler10flush_infoEb+0x2e)[0xa706ca]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_ZN14Relay_log_info10flush_infoEb+0xb8)[0xa764e4]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_ZN14Relay_log_info13rli_init_infoEv+0xa23)[0xa7614d]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_Z16global_init_infoP11Master_infobi+0x1d8)[0xa56615]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_Z10init_slavev+0xf1)[0xa560a7]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(_Z11mysqld_mainiPPc+0x91a)[0x61e781]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld(main+0x20)[0x612cad]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7fb655bc1ec5]
/home/teemu/work/bzr/codership-mysql/5.6/build_debug/sql/mysqld[0x612bc9]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): Connection ID (thread ID): 0
Status: NOT_KILLED

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.
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
rpl_mixing_engines.inc [commands=T]
-b-b-b-b-b-b-b-b-b-b-b- >> T << -b-b-b-b-b-b-b-b-b-b-b-
INSERT INTO tt_1(trans_id, stmt_id) VALUES (7, 1);
include/show_binlog_events.inc
Log_name Pos Event_type Server_id End_log_pos Info
master-bin.000001 # Query # # BEGIN
master-bin.000001 # Table_map # # table_id: # (test.tt_1)
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
master-bin.000001 # Xid # # COMMIT /* XID */
-e-e-e-e-e-e-e-e-e-e-e- >> T << -e-e-e-e-e-e-e-e-e-e-e-
-b-b-b-b-b-b-b-b-b-b-b- >> T << -b-b-b-b-b-b-b-b-b-b-b-
include/show_binlog_events.inc
Log_name Pos Event_type Server_id End_log_pos Info
master-bin.000001 # Query # # BEGIN
master-bin.000001 # Table_map # # table_id: # (test.tt_1)
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
master-bin.000001 # Xid # # COMMIT /* XID */
-e-e-e-e-e-e-e-e-e-e-e- >> T << -e-e-e-e-e-e-e-e-e-e-e-

include/rpl_reconnect.inc

 - saving '/home/teemu/work/bzr/codership-mysql/5.6/build_debug/mysql-test/var/log/rpl.rpl_row_crash_safe-row/' to '/home/teemu/work/bzr/codership-mysql/5.6/build_debug/mysql-test/var/log/rpl.rpl_row_crash_safe-row/'

Retrying test rpl.rpl_row_crash_safe, attempt(2/3)...

The stack trace shows that wsrep keys are appended, but they should not be since since wsrep provider is not loaded.

This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers