MySQL Bugs: #76425: bool Ha_trx_info::is_trx_read_write() const: Assertion `is

Bug #76425	bool Ha_trx_info::is_trx_read_write() const: Assertion `is_started()' failed.
Submitted:	21 Mar 2015 6:56	Modified:	12 May 2015 7:47
Reporter:	Roel Van de Paar	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Options	Severity:	S1 (Critical)
Version:	5.7.5-m16, 5.7.6	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Version: '5.7.6-m16-debug'  socket: '/sda/MS-mysql-5.7.6-m16-linux-x86_64-debug/socket.sock'  port: 10430  MySQL Community Server (GPL)
2015-03-21T06:55:02.266789Z 2 [Note] Changed GTID_MODE from OFF to OFF_PERMISSIVE.
mysqld: /bzr/mysql-5.7.6-m16_dbg/sql/transaction_info.h:110: bool Ha_trx_info::is_trx_read_write() const: Assertion `is_started()' failed.
06:55:03 UTC - mysqld got signal 6 ;
[...]
Query (7f3f7382c020): insert into t1 values(encrypt(0,'a'))

+bt
#0  0x00007f4017cbc771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000013a521c in my_write_core (sig=6) at /bzr/mysql-5.7.6-m16_dbg/mysys/stacktrace.c:247
#2  0x0000000000bb713c in handle_fatal_signal (sig=6) at /bzr/mysql-5.7.6-m16_dbg/sql/signal_handler.cc:220
#3  <signal handler called>
#4  0x00007f40168c05c9 in raise () from /lib64/libc.so.6
#5  0x00007f40168c1cd8 in abort () from /lib64/libc.so.6
#6  0x00007f40168b9536 in __assert_fail_base () from /lib64/libc.so.6
#7  0x00007f40168b95e2 in __assert_fail () from /lib64/libc.so.6
#8  0x0000000000c27f7b in Ha_trx_info::is_trx_read_write (this=0x7f3f7381b628) at /bzr/mysql-5.7.6-m16_dbg/sql/transaction_info.h:110
#9  0x0000000000c16742 in ha_check_and_coalesce_trx_read_only (thd=0x7f3f7381a000, ha_list=0x7f3f7381b628, all=false) at /bzr/mysql-5.7.6-m16_dbg/sql/handler.cc:1406
#10 0x0000000000c16a8f in ha_commit_trans (thd=0x7f3f7381a000, all=false, ignore_global_read_lock=false) at /bzr/mysql-5.7.6-m16_dbg/sql/handler.cc:1536
#11 0x000000000119a1c8 in trans_commit_stmt (thd=0x7f3f7381a000) at /bzr/mysql-5.7.6-m16_dbg/sql/transaction.cc:395
#12 0x00000000010a9735 in mysql_execute_command (thd=0x7f3f7381a000) at /bzr/mysql-5.7.6-m16_dbg/sql/sql_parse.cc:4566
#13 0x00000000010aae7a in mysql_parse (thd=0x7f3f7381a000, parser_state=0x7f40182b3e00) at /bzr/mysql-5.7.6-m16_dbg/sql/sql_parse.cc:5129
#14 0x00000000010a0bd4 in dispatch_command (command=COM_QUERY, thd=0x7f3f7381a000, packet=0x7f3f73846011 "insert into t1 values(encrypt(0,'a'))", packet_length=37) at /bzr/mysql-5.7.6-m16_dbg/sql/sql_parse.cc:1249
#15 0x000000000109f925 in do_command (thd=0x7f3f7381a000) at /bzr/mysql-5.7.6-m16_dbg/sql/sql_parse.cc:835
#16 0x00000000011c2fd9 in handle_connection (arg=0x7f400ebf78c0) at /bzr/mysql-5.7.6-m16_dbg/sql/conn_handler/connection_handler_per_thread.cc:298
#17 0x00000000013d2299 in pfs_spawn_thread (arg=0x7f400fbb2d50) at /bzr/mysql-5.7.6-m16_dbg/storage/perfschema/pfs.cc:2147
#18 0x00007f4017cb7df3 in start_thread () from /lib64/libpthread.so.0
#19 0x00007f40169811ad in clone () from /lib64/libc.so.6

How to repeat:
DROP DATABASE test;CREATE DATABASE test;USE test;
create table t1(a int)ENGINE=InnoDB;
SET @@GLOBAL.GTID_MODE=OFF_PERMISSIVE;
ALTER TABLE t1 engine=InnoDB;
SET SESSION GTID_NEXT='11111111-AAAA-2222-BBBB-111111111111:1';
insert into t1 values(encrypt(0,'a'));

Hello Roel,

Thank you for the report and test case.
Confirmed that 5.7.6 optimized build is affected.

Thanks,
Umesh

// 5.7.6 - opt build is affected

bin/mysql_install_db --basedir=/export/umesh/mysql-5.7.6 --datadir=/export/umesh/mysql-5.7.6/76425 -v
bin/mysqld --basedir=/export/umesh/mysql-5.7.6 --datadir=/export/umesh/mysql-5.7.6/76425 --sql_mode=ONLY_FULL_GROUP_BY --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/mysql-5.7.6/76425/log.err 2>&1 &

- build

commit: e1298eb6a8e2247361533811930a07fde7aff618
date: 2015-02-26 15:29:31 +0100
build-date: 2015-02-26 15:35:58 +0100
short: e1298eb
branch: mysql-5.7.6-m16-release

MySQL source 5.7.6

(gdb) bt
#0  0x00007f70ae16f771 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000006f64d4 in handle_fatal_signal (sig=11) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/signal_handler.cc:220
#2  <signal handler called>
#3  is_started (this=<optimized out>) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/transaction_info.h:116
#4  ha_check_and_coalesce_trx_read_only (all=false, ha_list=<optimized out>, thd=0x7f7068000b40) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/handler.cc:1420
#5  ha_commit_trans (thd=0x7f7068000b40, all=<optimized out>, ignore_global_read_lock=<optimized out>) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/handler.cc:1536
#6  0x0000000000b9f92e in trans_commit_stmt (thd=<optimized out>) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/transaction.cc:395
#7  0x0000000000af2e24 in mysql_execute_command (thd=0x7f7068000b40) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/sql_parse.cc:4566
#8  0x0000000000af5248 in mysql_parse (thd=0x7f7068000b40, parser_state=<optimized out>) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/sql_parse.cc:5129
#9  0x0000000000af6788 in dispatch_command (command=COM_QUERY, thd=0x7f7068000b40, packet=0x7f7068009c21 "insert into t1 values(encrypt(0,'a'))", packet_length=37)
    at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/sql_parse.cc:1249
#10 0x0000000000bb94a4 in handle_connection (arg=<optimized out>) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/sql/conn_handler/connection_handler_per_thread.cc:298
#11 0x0000000000f79aba in pfs_spawn_thread (arg=0x362f8f0) at /export/home/pb2/build/sb_0-14552753-1424962715.41/mysql-5.7.6-m16/storage/perfschema/pfs.cc:2147
#12 0x00007f70ae16adf3 in start_thread () from /lib64/libpthread.so.0
#13 0x00007f70ace3647d in clone () from /lib64/libc.so.6

Thanks for your feedback. This has been fixed in an upcoming version and the following was added to the 5.7.8 changelog:

When a server was configured with gtid_mode=ON, log-bin=OFF, and with autocommit enabled, during commit it was possible to encounter an ASSERTION `IS_STARTED()' FAILED error. This was possible when an applier thread committed a transaction's GTID into the gtid_executed table before transaction prepare when binary logging was disabled, or binary logging was enabled and log_slave_updates was disabled. The cause was that when the server was saving a transaction's GTID into the gtid_executed table, the calculated transaction context could be committed during the save phase when autocommit was enabled. The fix ensures that the transaction context is calculated after saving the GTID's state, and then commit is executed on any remaining transactions.