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

[4 Feb 2011 9:19] Shane Bester
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.
[4 Feb 2011 9:20] MySQL Verification Team
testcase....

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

[4 Feb 2011 15:56] MySQL Verification Team
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.
[5 Feb 2011 1:25] MySQL Verification Team
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 :(
[7 Feb 2011 14:30] Jon Olav Hauglid
I've reported assertion [4] as Bug#59986
[10 Feb 2011 10:20] Marko Mäkelä
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
[27 Apr 2011 0:21] Paul DuBois
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