Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-25401

Assertion `!is_set() || (m_status == DA_OK_BULK && is_bulk_op())' failed in Diagnostics_area::set_ok_status on SAVEPOINT

Details

    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)

      Attachments

        Issue Links

          Activity

            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
            

            marko Marko Mäkelä added a comment - 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

            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
            

            Roel Roel Van de Paar added a comment - 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

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

            Roel Roel Van de Paar added a comment - Likely the same issue as MDEV-29975 , more information there.
            alice Alice Sherepa added a comment - - edited

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

            alice Alice Sherepa added a comment - - edited not reproducible on 10.6 691e964d2357b579f64e0 -11.1, fixed by 18e4978edc13991e5c ( MDEV-29975 )

            People

              rucha174 Rucha Deodhar
              Roel Roel Van de Paar
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.