[MDEV-25401] Assertion `!is_set() || (m_status == DA_OK_BULK && is_bulk_op())' failed in Diagnostics_area::set_ok_status on SAVEPOINT Created: 2021-04-13  Updated: 2023-08-04  Resolved: 2023-08-02

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, XA
Affects Version/s: 10.6, 10.7, 10.8, 10.9, 10.10, 10.11, 11.0
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Rucha Deodhar
Resolution: Duplicate Votes: 0
Labels: not-10.2, not-10.3, not-10.4, not-10.5, regression, rr-profile-analyzed, sporadic

Issue Links:
Duplicate
duplicates MDEV-29975 Assertion `m_status == DA_ERROR' fail... Closed
Problem/Incident
is caused by MDEV-515 innodb bulk insert Closed
is caused by MDEV-24818 Concurrent use of InnoDB table is imp... Closed
is caused by MDEV-25297 InnoDB: Failing assertion: trx->roll_... Closed
Relates
relates to MDEV-25315 Assertion `ptr' failed in ut_align_do... Closed

 Description   

Issue is sporadic. Keep repeating test till it crashes. Normally only ~two attempts needed. Seems to affect 10.6+

DROP DATABASE test;
 
CREATE DATABASE test;
 
USE test;
 
SET sql_mode='';
 
SET SESSION unique_checks=0,foreign_key_checks=0;
 
CREATE TABLE t (c INT,c2 INT) ENGINE=InnoDB;
 
INSERT INTO t VALUES (0,0);
 
XA START 'a';
 
UPDATE t SET c=0;
 
SAVEPOINT s;
 
CREATE TEMPORARY TABLE t2 (c INT PRIMARY KEY,c2 INT) ENGINE=InnoDB;
 
INSERT INTO t2 VALUES (0,0),(0,0);
 
UPDATE t SET c=0;
 
SAVEPOINT s;

Leads to:

10.6.0 f74704c7d963ddcd1109843a5861c6bd76409c8d (Debug)

 
mysqld: /test/10.6_dbg/sql/sql_error.cc:334: void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*): Assertion `!is_set() || (m_status == DA_OK_BULK && is_bulk_op())' failed.

10.6.0 f74704c7d963ddcd1109843a5861c6bd76409c8d (Debug)

 
Core was generated by `/test/MD120421-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
[Current thread is 1 (Thread 0x14c3e8063700 (LWP 2873965))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x00005613269b9c9e in my_write_core (sig=sig@entry=6) at /test/10.6_dbg/mysys/stacktrace.c:424
 
#2  0x0000561326158b07 in handle_fatal_signal (sig=6) at /test/10.6_dbg/sql/signal_handler.cc:343
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x000014c3e94c7859 in __GI_abort () at abort.c:79
 
#6  0x000014c3e94c7729 in __assert_fail_base (fmt=0x14c3e965d588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x561326b203d0 "!is_set() || (m_status == DA_OK_BULK && is_bulk_op())", file=0x561326b202b0 "/test/10.6_dbg/sql/sql_error.cc", line=334, function=<optimized out>) at assert.c:92
 
#7  0x000014c3e94d8f36 in __GI___assert_fail (assertion=assertion@entry=0x561326b203d0 "!is_set() || (m_status == DA_OK_BULK && is_bulk_op())", file=file@entry=0x561326b202b0 "/test/10.6_dbg/sql/sql_error.cc", line=line@entry=334, function=function@entry=0x561326b20408 "void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*)") at assert.c:101
 
#8  0x0000561325e3d5e5 in Diagnostics_area::set_ok_status (this=0x14c394006ab8, affected_rows=affected_rows@entry=0, last_insert_id=last_insert_id@entry=0, message=message@entry=0x0) at /test/10.6_dbg/sql/sql_error.h:1017
 
#9  0x0000561325e9c4f1 in my_ok (message=0x0, id=0, affected_rows_arg=0, thd=0x14c394000db8) at /test/10.6_dbg/sql/sql_class.h:5486
 
#10 mysql_execute_command (thd=thd@entry=0x14c394000db8) at /test/10.6_dbg/sql/sql_parse.cc:5677
 
#11 0x0000561325e83a02 in mysql_parse (thd=thd@entry=0x14c394000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14c3e8062410) at /test/10.6_dbg/sql/sql_parse.cc:8004
 
#12 0x0000561325e92726 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14c394000db8, packet=packet@entry=0x14c39400b369 "SAVEPOINT s", packet_length=packet_length@entry=11, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:1331
 
#13 0x0000561325e95ac7 in do_command (thd=0x14c394000db8, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1399
 
#14 0x0000561325fef176 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x56132964b568, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
 
#15 0x0000561325fef77b in handle_one_connection (arg=arg@entry=0x56132964b568) at /test/10.6_dbg/sql/sql_connect.cc:1312
 
#16 0x000056132649d253 in pfs_spawn_thread (arg=0x56132954ed18) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
 
#17 0x000014c3e99d5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#18 0x000014c3e95c4293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.38 (dbg), 10.2.38 (opt), 10.3.29 (dbg), 10.3.29 (opt), 10.4.19 (dbg), 10.4.19 (opt), 10.5.10 (dbg), 10.5.10 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.33 (dbg), 5.7.33 (opt), 8.0.23 (dbg), 8.0.23 (opt)

 Comments   
Comment by Marko Mäkelä [ 2021-04-20 ]

I can easily repeat this with the following:

--source include/have_innodb.inc
 
SET SESSION unique_checks=0,foreign_key_checks=0;
 
CREATE TABLE t (c INT,c2 INT) ENGINE=InnoDB;
 
INSERT INTO t VALUES (0,0);
 
XA START 'a';
 
UPDATE t SET c=0;
 
SAVEPOINT s;
 
CREATE TEMPORARY TABLE t2 (c INT PRIMARY KEY,c2 INT) ENGINE=InnoDB;
 
--error ER_DUP_ENTRY
 
INSERT INTO t2 VALUES (0,0),(0,0);
 
UPDATE t SET c=0;
 
SAVEPOINT s;


./mtr --rr innodb.insert_into_empty-MDEV-25401
 
rr replay var/log/mysqld.1.rr/latest-trace

The assertion fails due to some failure in the error handling of the last SAVEPOINT statement. As part of MDEV-25297, InnoDB purposely forgot the earlier savepoint when that INSERT failed. (Note: this test case is rather weird, because I might expect CREATE TEMPORARY TABLE to commit the previous transaction.)
Here is some output from the rr replay session to show that the problem is with the incorrect error handling for the SAVEPOINT statement:

10.6 8751aa7397b2e698fa0b46ec3e60abb9e2fd7e1b

 
Thread 2 received signal SIGABRT, Aborted.
 
[Switching to Thread 2650636.2650648]
 
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
50	../sysdeps/unix/sysv/linux/raise.c: Tiedostoa tai hakemistoa ei ole.
 
(rr) f 4
 
#4  0x0000562d4e73c1ec in Diagnostics_area::set_ok_status (this=0x7f1d900077b8, affected_rows=affected_rows@entry=0, last_insert_id=last_insert_id@entry=0, message=message@entry=0x0)
 
    at /mariadb/10.6/sql/sql_error.cc:334
 
334	  DBUG_ASSERT(!is_set() || (m_status == DA_OK_BULK && is_bulk_op()));
 
(rr) watch -l m_status
 
Hardware watchpoint 1: -location m_status
 
(rr) rc
 
Continuing.
 
 
 
Thread 2 received signal SIGABRT, Aborted.
 
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
50	../sysdeps/unix/sysv/linux/raise.c: Tiedostoa tai hakemistoa ei ole.
 
(rr) 
Continuing.
 
 
 
Thread 2 hit Hardware watchpoint 1: -location m_status
 
 
 
Old value = Diagnostics_area::DA_ERROR
 
New value = Diagnostics_area::DA_EMPTY
 
Diagnostics_area::set_error_status (this=this@entry=0x7f1d900077b8, sql_errno=sql_errno@entry=1030, 
    message=message@entry=0x7f1da15f9c60 "Got error 153 \"No savepoint with that name\" from storage engine InnoDB", sqlstate=sqlstate@entry=0x562d4f30e7e8 "HY000", ucid=
 
      @0x7f1da15f9c08: {m_user_condition_value = 0x0}, error_condition=0x0) at /mariadb/10.6/sql/sql_error.cc:467
 
467	  m_status= DA_ERROR;
 
(rr) bt
 
#0  Diagnostics_area::set_error_status (this=this@entry=0x7f1d900077b8, sql_errno=sql_errno@entry=1030, 
    message=message@entry=0x7f1da15f9c60 "Got error 153 \"No savepoint with that name\" from storage engine InnoDB", sqlstate=sqlstate@entry=0x562d4f30e7e8 "HY000", ucid=
 
      @0x7f1da15f9c08: {m_user_condition_value = 0x0}, error_condition=0x0) at /mariadb/10.6/sql/sql_error.cc:467
 
#1  0x0000562d4e71dc4f in THD::raise_condition (this=this@entry=0x7f1d90001ab8, sql_errno=sql_errno@entry=1030, sqlstate=0x562d4f30e7e8 "HY000", sqlstate@entry=0x0, level=<optimized out>, ucid=
 
      @0x7f1da15f9c08: {m_user_condition_value = 0x0}, msg=msg@entry=0x7f1da15f9c60 "Got error 153 \"No savepoint with that name\" from storage engine InnoDB") at /mariadb/10.6/sql/sql_class.cc:1146
 
#2  0x0000562d4e6824c2 in THD::raise_condition (msg=0x7f1da15f9c60 "Got error 153 \"No savepoint with that name\" from storage engine InnoDB", level=<optimized out>, sqlstate=0x0, sql_errno=1030, 
    this=0x7f1d90001ab8) at /mariadb/10.6/sql/sql_class.h:4780
 
#3  my_message_sql (error=1030, str=0x7f1da15f9c60 "Got error 153 \"No savepoint with that name\" from storage engine InnoDB", MyFlags=0) at /mariadb/10.6/sql/mysqld.cc:3224
 
#4  0x0000562d4f231271 in my_error (nr=nr@entry=1030, MyFlags=MyFlags@entry=0) at /mariadb/10.6/mysys/my_error.c:124
 
#5  0x0000562d4ea43d9d in ha_release_savepoint (thd=thd@entry=0x7f1d90001ab8, sv=sv@entry=0x7f1d9001aec0) at /mariadb/10.6/sql/handler.cc:2622
 
#6  0x0000562d4e8ec3d3 in trans_savepoint (thd=thd@entry=0x7f1d90001ab8, name=<optimized out>) at /mariadb/10.6/sql/transaction.cc:599
 
#7  0x0000562d4e7942e3 in mysql_execute_command (thd=thd@entry=0x7f1d90001ab8) at /mariadb/10.6/sql/sql_parse.cc:5688
 
#8  0x0000562d4e79625f in mysql_parse (thd=thd@entry=0x7f1d90001ab8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f1da15fa4c0) at /mariadb/10.6/sql/sql_parse.cc:8017
 
#9  0x0000562d4e798964 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f1d90001ab8, packet=0x7f1da15fa4c0 "\377\377\377\377", packet@entry=0x7f1d9010ff99 "SAVEPOINT s", 
    packet_length=packet_length@entry=11, blocking=blocking@entry=true) at /mariadb/10.6/sql/sql_parse.cc:1897

Comment by Roel Van de Paar [ 2021-11-05 ]

Note that when this executed on optimized builds, the second savepoint gives this output:

10.7.1 12eb8ad7b98b03a6a7659fce7b75bdc8696ccaf6 (Debug)

 
....
 
10.7.1-opt>SAVEPOINT s;
 
Query OK, 0 rows affected (0.000 sec)
 
 
 
10.7.1-opt>CREATE TEMPORARY TABLE t2 (c INT PRIMARY KEY,c2 INT) ENGINE=InnoDB;
 
Query OK, 0 rows affected (0.000 sec)
 
 
 
10.7.1-opt>INSERT INTO t2 VALUES (0,0),(0,0);
 
ERROR 1062 (23000): Duplicate entry '0' for key 'PRIMARY'
 
10.7.1-opt>UPDATE t SET c=0;
 
Query OK, 0 rows affected (0.000 sec)
 
Rows matched: 1  Changed: 0  Warnings: 0
 
 
 
10.7.1-opt>SAVEPOINT s;
 
ERROR 1030 (HY000): Got error 153 "No savepoint with that name" from storage engine InnoDB

Comment by Roel Van de Paar [ 2023-03-02 ]

Likely the same issue as MDEV-29975, more information there.

Comment by Alice Sherepa [ 2023-08-02 ]

not reproducible on 10.6 691e964d2357b579f64e0 -11.1, fixed by 18e4978edc13991e5c (MDEV-29975)

Generated at Thu Feb 08 09:37:24 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.