MySQL Bugs: #59936: multiple XA assertions - transactional statement fuzzer

Bug #59936	multiple XA assertions - transactional statement fuzzer
Submitted:	4 Feb 2011 9:19	Modified:	27 Apr 2011 0:21
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S1 (Critical)
Version:	5.5.10, 5.6.2	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	regression, xa

Description:
The testcase attached exposes multiple problems, depending on seed and number of threads.

[1] (single thread test)
Version: '5.6.2-m5-valgrind-max-debug'  socket: 'sock'  port: 3306  Source distribution
110204 10:30:46  InnoDB: Assertion failure in thread 464209680 in file ./storage/innobase/row/row0sel.c line 3885
InnoDB: Failing assertion: trx->state == TRX_STATE_NOT_STARTED || trx->state == TRX_STATE_ACTIVE
(gdb) bt
#0  in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  in abort () at abort.c:92
#2  in row_search_for_mysql at ./storage/innobase/row/row0sel.c:3884
#3  in ha_innobase::index_read at ./storage/innobase/handler/ha_innodb.cc:6127
#4  in ha_innobase::index_first at ./storage/innobase/handler/ha_innodb.cc:6429
#5  in handler::ha_index_first at ./sql/handler.cc:2301
#6  in handler::read_range_first at ./sql/handler.cc:5355
#7  in handler::multi_range_read_next at ./sql/handler.cc:4647
#8  in DsMrr_impl::dsmrr_next at ./sql/handler.cc:4933
#9  in ha_innobase::multi_range_read_next at ./storage/innobase/handler/ha_innodb.cc:12604
#10 in QUICK_RANGE_SELECT::get_next at ./sql/opt_range.cc:8908
#11 in rr_quick at ./sql/records.cc:347
#12 in join_init_read_record at ./sql/sql_select.cc:18373
#13 in sub_select at ./sql/sql_select.cc:17451
#14 in do_select at ./sql/sql_select.cc:16997
#15 in JOIN::exec at ./sql/sql_select.cc:3361
#16 in mysql_select at ./sql/sql_select.cc:3584
#17 in handle_select at ./sql/sql_select.cc:323
#18 in mysql_execute_command at ./sql/sql_parse.cc:2902
#19 in mysql_parse  at ./sql/sql_parse.cc:5550
#20 in dispatch_command at ./sql/sql_parse.cc:1078
#21 in do_command at ./sql/sql_parse.cc:815
#22 in do_handle_one_connection at ./sql/sql_connect.cc:748
#23 in handle_one_connection at ./sql/sql_connect.cc:684
#24 in start_thread at pthread_create.c:301
#25 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
(gdb) frame 2
#2  0x0000000000a0af42 in row_search_for_mysql (buf=0x15a29590 "\377", mode=1, prebuilt=0x157d3138, match_mode=0, direction=0) at ./storage/innobase/row/row0sel.c:3884
3884            ut_ad(trx->state == TRX_STATE_NOT_STARTED
(gdb) p trx->state
$1 = TRX_STATE_PREPARED
(gdb) 

[2] (single thread test)

110204 10:39:16  InnoDB: Assertion failure in thread 140737018169104 in file ./storage/innobase/trx/trx0trx.c line 1728

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffe3f98710 (LWP 6925)]
0x00000030e14329a5 in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
64        return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) bt
#0  in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  in abort () at abort.c:92
#2  in trx_start_if_not_started_xa at ./storage/innobase/trx/trx0trx.c:1728
#3  in row_insert_for_mysql at ./storage/innobase/row/row0mysql.c:1175
#4  in ha_innobase::write_row at ./storage/innobase/handler/ha_innodb.cc:5428
#5  in handler::ha_write_row at ./sql/handler.cc:5871
#6  in write_record at ./sql/sql_insert.cc:1737
#7  in mysql_insert at ./sql/sql_insert.cc:931
#8  in mysql_execute_command at ./sql/sql_parse.cc:2845
#9  in mysql_parse at ./sql/sql_parse.cc:5550
#10 in dispatch_command at ./sql/sql_parse.cc:1078
#11 in do_command at ./sql/sql_parse.cc:815
#12 in do_handle_one_connection at ./sql/sql_connect.cc:748
#13 in handle_one_connection at ./sql/sql_connect.cc:684
#14 in start_thread at pthread_create.c:301
#15 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
(gdb) frame 2
#2  0x0000000000a4c15e in trx_start_if_not_started_xa (trx=0x7fffc0013e18) at /home/sbester/build/bzr/mysql-trunk/storage/innobase/trx/trx0trx.c:1728
1728            ut_error;

(gdb) list
1723            case TRX_STATE_PREPARED:
1724            case TRX_STATE_COMMITTED_IN_MEMORY:
1725                    break;
1726            }
1727
1728            ut_error;
1729    }

[3] (3 threads with binlogging enabled)
Version: '5.6.2-m5-valgrind-max-debug-log'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
mysqld: ./sql/binlog.cc:4248: virtual int MYSQL_BIN_LOG::unlog(ulong, my_xid): Assertion `prepared_xids > 0' failed.
(gdb) bt
#0  __pthread_kill at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1  e in my_write_core (sig=6) at ./mysys/stacktrace.c:423
#2  5 in handle_segfault (sig=6) at ./sql/mysqld.cc:2511
#3  <signal handler called>
#4  in raise at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5  in abort at abort.c:92
#6  in __assert_fail at assert.c:81
#7  in MYSQL_BIN_LOG::unlog at ./sql/binlog.cc:4248
#8  in ha_commit_trans at ./sql/handler.cc:1253
#9  in trans_begin at ./sql/transaction.cc:111
#10 in mysql_execute_command at ./sql/sql_parse.cc:3667
#11 in mysql_parse at ./sql/sql_parse.cc:5550
#12 in dispatch_command at ./sql/sql_parse.cc:1078
#13 in do_command at ./sql/sql_parse.cc:815
#14 in do_handle_one_connection at ./sql/sql_connect.cc:748
#15 in handle_one_connection at ./sql/sql_connect.cc:684
#16 in start_thread at pthread_create.c:301
#17 in clone at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
(gdb) frame 7
#7  0x00000000008c5a80 in MYSQL_BIN_LOG::unlog at ./sql/binlog.cc:4248
4248      DBUG_ASSERT(prepared_xids > 0);
(gdb) p prepared_xids
$1 = 0

[4] (3 threads)
Version: '5.6.2-m5-valgrind-max-debug-log'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
mysqld: ./sql/sql_error.cc:358: void Diagnostics_area::set_ok_status(THD*, ulonglong, ulonglong, const char*): Assertion `! is_set()' failed.
110204 11:08:22 - mysqld got signal 6 ;
(gdb) bt
#0  __pthread_kill at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1  in my_write_core  at ./mysys/stacktrace.c:423
#2  in handle_segfault at ./sql/mysqld.cc:2511
#3  <signal handler called>
#4  in raise at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5  in abort at abort.c:92
#6  in __assert_fail at assert.c:81
#7  in Diagnostics_area::set_ok_status at ./sql/sql_error.cc:358
#8  in my_ok at ./sql/sql_class.h:2986
#9  in mysql_execute_command at ./sql/sql_parse.cc:4242
#10 in mysql_parse at ./sql/sql_parse.cc:5550
#11 in dispatch_command at ./sql/sql_parse.cc:1078
#12 in do_command at ./sql/sql_parse.cc:815
#13 in do_handle_one_connection at ./sql/sql_connect.cc:748
#14 in handle_one_connection at ./sql/sql_connect.cc:684
#15 in start_thread at pthread_create.c:301
#16 in clone at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

[3] and [4] hit 5.5.10 and 5.6.2
[1] and [2] hot 5.6.2

I don't have a simpler testcase than this.  Sorry.

How to repeat:
Run a debug build like this: mysqld --skip-gr --skip-na --log-bin --binlog-format=row --innodb_flush_log_at_trx_commit=0 --innodb_lock_wait_timeout=0 --lock_wait_timeout=0 

1. build the testcase and run it a few times to see if different assertions happen.  

2. you can set the seed to consistently reproduce a specific error for 1 thread test.

3. after fixing all problems with 1 thread, increase the number of threads to 3+

4. testcase should run single/multi threaded with/without valgrind with/without binlogging for a long time without crashing.

testcase....

Attachment: bug59936.c (text/plain), 10.97 KiB.

110204 13:31:40 [Note] bin/mysqld: ready for connections.
Version: '5.5.10-debug'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution
110204 13:54:45  InnoDB: Assertion failure in thread 140125460879104 in file /home/miguel/bzr/5.5/storage/innobase/row/row0sel.c line 3698
InnoDB: Failing assertion: trx->conc_state == 0 || trx->conc_state == 1
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.

I put: "Version: 5.5.10, 5.6.2"
Please run a testcase and if you find/fix bugs let me know.. I gave up on single-threaded simple *.sql testcases because of the fact that they were not deterministic enough and put different results.  hence the megatest :(

I've reported assertion [4] as Bug#59986

It seems to me that MySQL is the guilty party. InnoDB assertion failures are just the messenger, saying that something is wrong. A PREPARED transaction must not execute anything else than ROLLBACK or COMMIT. I added some assertions for this recently, in mysql-trunk-innodb. That would explain why some failures are only repeatable in 5.6.2.

My analysis of the errors:

[1] an attempt to fetch a record in a transaction that has been PREPAREd
[2] an attempt to insert a row after PREPARE or COMMIT (I guess PREPARE)
[3] should be outside InnoDB, in the binlog part of the XA transaction

Noted in 5.5.13, 5.6.3 changelogs.

The server did not check for certain invalid out of order sequences
of XA statements, and these sequences raised an assertion.

CHANGESET - http://lists.mysql.com/commits/133898