MySQL Bugs: #83730: Assertion "state == TRX_STATE_NOT_STARTED || state == TRX_STATE_FORCED

Bug #83730	Assertion "state == TRX_STATE_NOT_STARTED \|\| state == TRX_STATE_FORCED_ROLLBACK"
Submitted:	7 Nov 2016 22:14	Modified:	13 Nov 2016 8:33
Reporter:	Elena Stepanova	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.6/5.7/8.0	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	debug

Description:
2016-11-08 01:09:23 0x7f4148ce6700  InnoDB: Assertion failure in thread 139918371088128 in file trx0trx.ic line 63
InnoDB: Failing assertion: state == TRX_STATE_NOT_STARTED || state == TRX_STATE_FORCED_ROLLBACK

#6  0x0000000001be54db in ut_dbg_assertion_failed (expr=0x21e1cc0 "state == TRX_STATE_NOT_STARTED || state == TRX_STATE_FORCED_ROLLBACK", file=0x21e1b60 "/data/src/mysql-5.7/storage/innobase/include/trx0trx.ic", line=63) at /data/src/mysql-5.7/storage/innobase/ut/ut0dbg.cc:67
#7  0x0000000001bc47d8 in trx_state_eq (trx=0x7f414a962d08, state=TRX_STATE_ACTIVE) at /data/src/mysql-5.7/storage/innobase/include/trx0trx.ic:62
#8  0x0000000001bc60bf in trx_release_savepoint_for_mysql (trx=0x7f414a962d08, savepoint_name=0x7f4148ce3e00 "1DLGZMF4LC") at /data/src/mysql-5.7/storage/innobase/trx/trx0roll.cc:575
#9  0x00000000019c44e4 in innobase_release_savepoint (hton=0x3eda620, thd=0x7f40f8000b70, savepoint=0x7f40f8004700) at /data/src/mysql-5.7/storage/innobase/handler/ha_innodb.cc:4586
#10 0x0000000000f6fc29 in ha_release_savepoint (thd=0x7f40f8000b70, sv=0x7f40f80046d0) at /data/src/mysql-5.7/sql/handler.cc:2386
#11 0x0000000001519b1f in THD::restore_sub_statement_state (this=0x7f40f8000b70, backup=0x7f4148ce3f50) at /data/src/mysql-5.7/sql/sql_class.cc:4134
#12 0x000000000167048b in Trigger::execute (this=0x7f40f8018e20, thd=0x7f40f8000b70) at /data/src/mysql-5.7/sql/trigger.cc:477
#13 0x0000000001673d4c in Trigger_chain::execute_triggers (this=0x7f40f8018c80, thd=0x7f40f8000b70) at /data/src/mysql-5.7/sql/trigger_chain.cc:144
#14 0x000000000166a52e in Table_trigger_dispatcher::process_triggers (this=0x7f40f8018610, thd=0x7f40f8000b70, event=TRG_EVENT_INSERT, action_time=TRG_ACTION_BEFORE, old_row_is_record1=true) at /data/src/mysql-5.7/sql/table_trigger_dispatcher.cc:792
#15 0x0000000001500853 in call_before_insert_triggers (thd=0x7f40f8000b70, table=0x7f40f80168e0, event=TRG_EVENT_INSERT, insert_into_fields_bitmap=0x7f4148ce4150) at /data/src/mysql-5.7/sql/sql_base.cc:9405
#16 0x00000000014fd2f7 in fill_record_n_invoke_before_triggers (thd=0x7f40f8000b70, ptr=0x7f40f8017590, values=..., table=0x7f40f80168e0, event=TRG_EVENT_INSERT, num_fields=1) at /data/src/mysql-5.7/sql/sql_base.cc:9614
#17 0x000000000178e20b in Sql_cmd_insert::mysql_insert (this=0x7f40f80067e0, thd=0x7f40f8000b70, table_list=0x7f40f8006250) at /data/src/mysql-5.7/sql/sql_insert.cc:762
#18 0x00000000017949b5 in Sql_cmd_insert::execute (this=0x7f40f80067e0, thd=0x7f40f8000b70) at /data/src/mysql-5.7/sql/sql_insert.cc:3092
#19 0x00000000015758b3 in mysql_execute_command (thd=0x7f40f8000b70, first_level=true) at /data/src/mysql-5.7/sql/sql_parse.cc:3554
#20 0x000000000157b101 in mysql_parse (thd=0x7f40f8000b70, parser_state=0x7f4148ce56a0) at /data/src/mysql-5.7/sql/sql_parse.cc:5559
#21 0x00000000015709ba in dispatch_command (thd=0x7f40f8000b70, com_data=0x7f4148ce5df0, command=COM_QUERY) at /data/src/mysql-5.7/sql/sql_parse.cc:1427
#22 0x000000000156f940 in do_command (thd=0x7f40f8000b70) at /data/src/mysql-5.7/sql/sql_parse.cc:995
#23 0x000000000169a0f4 in handle_connection (arg=0x49e5de0) at /data/src/mysql-5.7/sql/conn_handler/connection_handler_per_thread.cc:300
#24 0x00000000018ca256 in pfs_spawn_thread (arg=0x4991c60) at /data/src/mysql-5.7/storage/perfschema/pfs.cc:2188
#25 0x00007f41509d90a4 in start_thread (arg=0x7f4148ce6700) at pthread_create.c:309
#26 0x00007f414f49c87d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

How to repeat:
CREATE TABLE t1 (a INT) ENGINE=InnoDB;
CREATE TABLE t2 (b INT) ENGINE=InnoDB;
CREATE TABLE t3 (c INT) ENGINE=InnoDB;

--delimiter $$
CREATE TRIGGER tr BEFORE INSERT ON t3 FOR EACH ROW BEGIN SAVEPOINT sv; INSERT INTO t2 VALUES (0); END $$
--delimiter ;

--connect (con1,localhost,root,,test)
START TRANSACTION;
DELETE FROM t1;

--connect (con2,localhost,root,,test)
START TRANSACTION;
INSERT INTO t2 VALUES (2);
UPDATE t2 SET b = b+1;
--send
INSERT INTO t1 VALUES (1);

--connection con1
INSERT INTO t3 VALUES (2);

Thank you for the bug report. I was able to reproduce only with debug server do you confirm?. Thanks.

C:\dbs>c:\dbs\5.7\bin\mysqld --defaults-file=c:\dbs\my57.ini --standalone --console
2016-11-07T22:35:40.407937Z 0 [Note] c:\dbs\5.7\bin\mysqld (mysqld 5.7.18-debug) starting as process 10296 ...
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: Uses event mutexes
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: Number of pools: 1
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2016-11-07T22:35:40.423560Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2016-11-07T22:35:40.595425Z 0 [Note] InnoDB: Completed initialization of buffer pool
2016-11-07T22:35:40.704829Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2016-11-07T22:35:41.048555Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2016-11-07T22:35:41.048555Z 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2016-11-07T22:35:41.267362Z 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2016-11-07T22:35:41.329838Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2016-11-07T22:35:41.329838Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2016-11-07T22:35:41.345444Z 0 [Note] InnoDB: Waiting for purge to start
2016-11-07T22:35:41.407989Z 0 [Note] InnoDB: 5.7.18 started; log sequence number 54564160
2016-11-07T22:35:41.407989Z 0 [Note] InnoDB: Loading buffer pool(s) from c:\dbs\5.7\data\ib_buffer_pool
2016-11-07T22:35:41.517362Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2016-11-07T22:35:41.532951Z 0 [Note] Server hostname (bind-address): '*'; port: 3570
2016-11-07T22:35:41.532951Z 0 [Note] IPv6 is available.
2016-11-07T22:35:41.532951Z 0 [Note]   - '::' resolves to '::';
2016-11-07T22:35:41.532951Z 0 [Note] Server socket created on IP: '::'.
2016-11-07T22:35:41.767311Z 0 [Note] Event Scheduler: Loaded 0 events
2016-11-07T22:35:41.767311Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
2016-11-07T22:35:41.767311Z 0 [Note] Beginning of list of non-natively partitioned tables
2016-11-07T22:35:41.782936Z 0 [Note] InnoDB: Buffer pool(s) load completed at 161107 20:35:41
2016-11-07T22:35:41.829828Z 0 [Note] End of list of non-natively partitioned tables
2016-11-07T22:35:41.829828Z 0 [Note] c:\dbs\5.7\bin\mysqld: ready for connections.
Version: '5.7.18-debug'  socket: ''  port: 3570  Source distribution PULL: 2016-NOV-05
2016-11-07 20:37:20 0x2708  InnoDB: Assertion failure in thread 9992 in file trx0trx.ic line 63
InnoDB: Failing assertion: state == TRX_STATE_NOT_STARTED || state == TRX_STATE_FORCED_ROLLBACK
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
R6010
- abort() has been called
22:37:20 UTC - mysqld got exception 0x80000003 ;
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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=2
max_threads=151
thread_count=2
connection_count=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68072 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x154ec64be70
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...
7ff77ad358e5    mysqld.exe!my_sigabrt_handler()[my_thr_init.c:449]
7ff77b537daf    mysqld.exe!raise()[winsig.c:594]
7ff77b534a50    mysqld.exe!abort()[abort.c:82]
7ff77b009cef    mysqld.exe!ut_dbg_assertion_failed()[ut0dbg.cc:68]
7ff77b0ad674    mysqld.exe!trx_state_eq()[trx0trx.ic:63]
7ff77b0af272    mysqld.exe!trx_release_savepoint_for_mysql()[trx0roll.cc:575]
7ff77add10d2    mysqld.exe!innobase_release_savepoint()[ha_innodb.cc:4591]
7ff779fd83ca    mysqld.exe!ha_release_savepoint()[handler.cc:2420]
7ff77a0cb4ce    mysqld.exe!THD::restore_sub_statement_state()[sql_class.cc:4139]
7ff77aa70b45    mysqld.exe!Trigger::execute()[trigger.cc:479]
7ff77aaa75f5    mysqld.exe!Trigger_chain::execute_triggers()[trigger_chain.cc:144]
7ff77a4fdb33    mysqld.exe!Table_trigger_dispatcher::process_triggers()[table_trigger_dispatcher.cc:792]
7ff77a1c673b    mysqld.exe!call_before_insert_triggers()[sql_base.cc:9407]
7ff77a1b2f52    mysqld.exe!fill_record_n_invoke_before_triggers()[sql_base.cc:9615]
7ff77a48d3f9    mysqld.exe!Sql_cmd_insert::mysql_insert()[sql_insert.cc:754]
7ff77a48bf5a    mysqld.exe!Sql_cmd_insert::execute()[sql_insert.cc:3103]
7ff77a06a04c    mysqld.exe!mysql_execute_command()[sql_parse.cc:3591]
7ff77a06605e    mysqld.exe!mysql_parse()[sql_parse.cc:5596]
7ff77a0708e2    mysqld.exe!dispatch_command()[sql_parse.cc:1463]
7ff77a06f723    mysqld.exe!do_command()[sql_parse.cc:998]
7ff77a025958    mysqld.exe!handle_connection()[connection_handler_per_thread.cc:300]
7ff77b3a8e42    mysqld.exe!pfs_spawn_thread()[pfs.cc:2190]
7ff77ad34186    mysqld.exe!win_thread_start()[my_thread.c:37]
7ff77b5375c5    mysqld.exe!_callthreadstartex()[threadex.c:376]
7ff77b537817    mysqld.exe!_threadstartex()[threadex.c:359]
7ffc71858364    KERNEL32.DLL!BaseThreadInitThunk()
7ffc71f85e91    ntdll.dll!RtlUserThreadStart()

This bug is duplicate of http://bugs.mysql.com/bug.php?id=82013 Oracle bug: 23700912 which is currently private.

2016-11-07T23:01:45.108690Z 0 [Note] c:\dbs\8.0\bin\mysqld: ready for connections.
Version: '8.0.1-dmr-debug'  socket: ''  port: 3580  Source distribution PULL: 2016-NOV-05
2016-11-07T23:03:40.190525Z 4 [ERROR] InnoDB: Assertion failure: trx0trx.ic:63:state == TRX_STATE_NOT_STARTED || state == TRX_STATE_FORCED_ROLLBACK
InnoDB: thread 11920
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
abort() has been called23:03:40 UTC - mysqld got exception 0x80000003 ;
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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

Adding a comment just to switch the report from 'Need Feedback' to whatever it is supposed to be.

>> I was able to reproduce only with debug server do you confirm?

I don't have a MySQL 5.7/8.0 release build handy, so I can't check it quickly; if it only fails for you on debug, it is probably so in general. Anyway, a report which will end up treated as a duplicate of something private is of no interest or use for anyone, so no point to bother.

Thank you for the feedback. Which version 5.7.X have you tested so I can test the release version of it?. Thanks.

# commit c28e258157f39f25e044bb72e8bae1ff00989a3d
# Author: Robert Golebiowski <robert.golebiowski@oracle.com>
# Date:   Tue Sep 27 11:21:02 2016 +0200
# 
#     Merge branch 'mysql-5.6' into mysql-5.7
#     
#     (cherry picked from commit 710bafee9de1c11577242d694f74f5fa38df3a88)
# 
cmake /data/src/mysql-5.7 -DCMAKE_INSTALL_PREFIX=/data/bld/mysql-5.7 -DCMAKE_BUILD_TYPE=Debug -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/data/releases/boost && make -j5 && make install

Thank you for the feedback.

2016-11-07 22:05:31 8556 [Note] c:\dbs\5.6\bin\mysqld: ready for connections.
Version: '5.6.36-debug'  socket: ''  port: 3560  Source distribution PULL: 2016-NOV-05
2016-11-07 22:07:00 c90  InnoDB: Assertion failure in thread 3216 in file trx0trx.ic line 60
InnoDB: Failing assertion: state == TRX_STATE_NOT_STARTED
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
R6010
- abort() has been called
00:07:00 UTC - mysqld got exception 0x80000003 ;
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=8388608
read_buffer_size=131072
max_used_connections=2
max_threads=151
thread_count=2
connection_count=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 67958 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x1e8c26aaef0
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...
7ff7c941ea45    mysqld.exe!my_sigabrt_handler()[my_thr_init.c:455]
7ff7c9a01e1f    mysqld.exe!raise()[winsig.c:594]
7ff7c9a03d50    mysqld.exe!abort()[abort.c:82]
7ff7c96b29cb    mysqld.exe!trx_state_eq()[trx0trx.ic:60]
7ff7c96b4e12    mysqld.exe!trx_release_savepoint_for_mysql()[trx0roll.cc:498]
7ff7c94a153c    mysqld.exe!innobase_release_savepoint()[ha_innodb.cc:3932]
7ff7c8f33f87    mysqld.exe!ha_release_savepoint()[handler.cc:2173]
7ff7c8f81a39    mysqld.exe!THD::restore_sub_statement_state()[sql_class.cc:4478]
7ff7c914dc98    mysqld.exe!Table_triggers_list::process_triggers()[sql_trigger.cc:2186]
7ff7c90c3dfb    mysqld.exe!fill_record_n_invoke_before_triggers()[sql_base.cc:9169]
7ff7c922bce1    mysqld.exe!mysql_insert()[sql_insert.cc:1038]
7ff7c9059347    mysqld.exe!mysql_execute_command()[sql_parse.cc:3480]
7ff7c9055fba    mysqld.exe!mysql_parse()[sql_parse.cc:6416]
7ff7c905f6a9    mysqld.exe!dispatch_command()[sql_parse.cc:1372]
7ff7c905e6c5    mysqld.exe!do_command()[sql_parse.cc:1036]
7ff7c90affe2    mysqld.exe!do_handle_one_connection()[sql_connect.cc:982]
7ff7c90afe12    mysqld.exe!handle_one_connection()[sql_connect.cc:900]
7ff7c98da2e5    mysqld.exe!pfs_spawn_thread()[pfs.cc:1862]
7ff7c941d016    mysqld.exe!pthread_start()[my_winthread.c:62]
7ff7c9a12395    mysqld.exe!_callthreadstartex()[threadex.c:376]
7ff7c9a125e7    mysqld.exe!_threadstartex()[threadex.c:359]
7ffc71858364    KERNEL32.DLL!BaseThreadInitThunk()
7ffc71f85e91    ntdll.dll!RtlUserThreadStart()

Duplicate of

Bug#82013 assertion: state == TRX_STATE_NOT_STARTED || state == TRX_STATE_FORCED_ROLLBACK

which is now public.