(Not a recent regression; a 10.7 test build from mid March 22 crashes in the same way)
This looks similar to MDEV-25401.
Sure it does, but I think the remarkable part here is the difference between 10.6 and 10.7+. Why is it that on 10.6+ the second INSERT ends with ER_DUP_ENTRY, while on 10.7+ it's a ER_ERROR_DURING_COMMIT?
When we execute the first SAVEPOINT a; statement, it works ok, adds the savepoint to trx_savepoints.
But when we execute the second SAVEPOINT a; we try to release the already existing savepoint with the same name. To do that, it enters savepoint_release() but then it crashes with savepoint doesnt exists which seemed strange(because the savepoint with same name exists. Why would we get this error?!). On debugging more I found that savepoint gets removed during second INSERT, during trx_roll_savepoint_free().
So after discussing with Thiru, he said to reassign the bug to him because it looks like it has something to do with innodb.
About the second insert giving different errors on 10.6 and 10.7+ is (discussed with Thiru):
In 10.7+, we are doing bulk insert (because unique_check and foreign_key_checks=0) on 10.7+, so it stored the values in buffer, without checking if it is duplicate or not but it is caught during marking end of statement during commiting the statement(not transaction), so it says error during commit.
In 10.6, we are not doing bulk insert when unique_check and foreign_key_checks=0, so it gets caught during inserting in the table. So it errors out with duplicate key.
Patch is in bb-10.6-MDEV-29975
10.7 patch is in bb-10.7-MDEV-29975
The 10.6 patch looks OK to push. It could be good to say "release the savepoint name" in the commit message, so that it cannot be mistaken with ROLLBACK TO SAVEPOINT.
The 10.7 patch looks potentially risky to me, and it could be a change of behavior compared to the 10.6 version. Would the 10.6 patch work also in 10.7?
The 10.6 patch would require an adjustment when applied to 10.7:
diff --git a/mysql-test/suite/innodb/t/insert_into_empty.test b/mysql-test/suite/innodb/t/insert_into_empty.test |
index 8fad8235b68..62c3ccce592 100644 |
--- a/mysql-test/suite/innodb/t/insert_into_empty.test
|
+++ b/mysql-test/suite/innodb/t/insert_into_empty.test
|
@@ -242,7 +242,7 @@ CREATE TABLE t (c INT KEY) ENGINE=InnoDB; |
--error ER_WRONG_VALUE_COUNT_ON_ROW |
INSERT INTO t VALUES (0,0); |
SAVEPOINT a;
|
---error ER_DUP_ENTRY
|
+--error ER_ERROR_DURING_COMMIT |
INSERT INTO t VALUES (0),(0); |
SAVEPOINT a;
|
SELECT * FROM t; |
I do not quite understand this test scenario. The test is executing in autocommit=1 mode, and there is no explicit START TRANSACTION or BEGIN statement. Shouldn’t the SAVEPOINT statements be disregarded (or result in a warning) when they are not being executed inside a transaction? There is no way for ROLLBACK TO SAVEPOINT to refer to them.
A more valid test from the InnoDB point of view would be one where the SAVEPOINT is executed inside a transaction.
SET sql_mode='',unique_checks=0,foreign_key_checks=0,autocommit=0; |
CREATE PROCEDURE p (OUT i INT) MODIFIES SQL DATA SAVEPOINT p; |
CREATE TABLE t1 (a INT) ENGINE=InnoDB; |
INSERT INTO t1 VALUES (); |
SAVEPOINT p;
|
CREATE TEMPORARY TABLE t2 (i INT KEY) ENGINE=InnoDB; |
INSERT INTO t2 VALUES(),(); |
CALL p (@b);
|
Leads to:
|
11.0.1 f2dc4d4c10ac36a73b5c1eb765352d3aee808d66 (Optimized) |
11.0.1-opt>INSERT INTO t2 VALUES(),();
|
ERROR 1062 (23000): Duplicate entry '0' for key 'PRIMARY'
|
11.0.1-opt>CALL p (@b);
|
ERROR 1030 (HY000): Got error 153 "No savepoint with that name" from storage engine InnoDB
|
On optimized builds. On debug it crashes:
|
11.0.1 f2dc4d4c10ac36a73b5c1eb765352d3aee808d66 (Debug) |
mariadbd: /test/11.0_dbg/sql/sql_error.cc:335: void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*): Assertion `!is_set() || (m_status == DA_OK_BULK && is_bulk_op())' failed.
|
|
11.0.1 f2dc4d4c10ac36a73b5c1eb765352d3aee808d66 (Debug) |
Core was generated by `/test/MD180223-mariadb-11.0.1-linux-x86_64-dbg/bin/mariadbd --no-defaults --cor'.
|
Program terminated with signal SIGABRT, Aborted.
|
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22754753246784)
|
at ./nptl/pthread_kill.c:44
|
[Current thread is 1 (Thread 0x14b200fbf640 (LWP 4047030))]
|
(gdb) bt
|
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=22754753246784) at ./nptl/pthread_kill.c:44
|
#1 __pthread_kill_internal (signo=6, threadid=22754753246784) at ./nptl/pthread_kill.c:78
|
#2 __GI___pthread_kill (threadid=22754753246784, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
|
#3 0x000014b21a661476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
|
#4 0x000014b21a6477f3 in __GI_abort () at ./stdlib/abort.c:79
|
#5 0x000014b21a64771b in __assert_fail_base (fmt=0x14b21a7fc150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55674898fd78 "!is_set() || (m_status == DA_OK_BULK && is_bulk_op())", file=0x55674898fc58 "/test/11.0_dbg/sql/sql_error.cc", line=335, function=<optimized out>) at ./assert/assert.c:92
|
#6 0x000014b21a658e96 in __GI___assert_fail (assertion=0x55674898fd78 "!is_set() || (m_status == DA_OK_BULK && is_bulk_op())", file=0x55674898fc58 "/test/11.0_dbg/sql/sql_error.cc", line=335, function=0x55674898fdb0 "void Diagnostics_area::set_ok_status(ulonglong, ulonglong, const char*)") at ./assert/assert.c:101
|
#7 0x0000556747e41577 in Diagnostics_area::set_ok_status (this=0x14b1b4006b60, affected_rows=affected_rows@entry=0, last_insert_id=last_insert_id@entry=0, message=message@entry=0x0) at /test/11.0_dbg/sql/sql_error.cc:335
|
#8 0x0000556747e90191 in my_ok (message=0x0, id=0, affected_rows_arg=0, thd=0x14b1b4000d58) at /test/11.0_dbg/sql/sql_class.h:4426
|
#9 mysql_execute_command (thd=0x14b1b4000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:5713
|
#10 0x0000556747dc93c2 in sp_instr_stmt::exec_core (this=0x14b1b408c960, thd=<optimized out>, nextp=0x14b200fbd374) at /test/11.0_dbg/sql/sp_head.cc:3857
|
#11 0x0000556747dd65d4 in sp_lex_keeper::reset_lex_and_exec_core (this=this@entry=0x14b1b408c9a8, thd=thd@entry=0x14b1b4000d58, nextp=nextp@entry=0x14b200fbd374, open_tables=open_tables@entry=false, instr=instr@entry=0x14b1b408c960) at /test/11.0_dbg/sql/sp_head.cc:3582
|
#12 0x0000556747dd6d43 in sp_instr_stmt::execute (this=0x14b1b408c960, thd=0x14b1b4000d58, nextp=0x14b200fbd374) at /test/11.0_dbg/sql/sp_head.cc:3763
|
#13 0x0000556747dcf338 in sp_head::execute (this=this@entry=0x14b1b408b930, thd=thd@entry=0x14b1b4000d58, merge_da_on_success=merge_da_on_success@entry=true) at /test/11.0_dbg/sql/sp_head.cc:1459
|
#14 0x0000556747dd15da in sp_head::execute_procedure (this=0x14b1b408b930, thd=thd@entry=0x14b1b4000d58, args=0x14b1b4005ed8) at /test/11.0_dbg/sql/sp_head.cc:2446
|
#15 0x0000556747e7f473 in do_execute_sp (thd=thd@entry=0x14b1b4000d58, sp=sp@entry=0x14b1b408b930) at /test/11.0_dbg/sql/sql_parse.cc:3026
|
#16 0x0000556747e83c00 in Sql_cmd_call::execute (this=0x14b1b40131f0, thd=0x14b1b4000d58) at /test/11.0_dbg/sql/sql_parse.cc:3271
|
#17 0x0000556747e90db6 in mysql_execute_command (thd=thd@entry=0x14b1b4000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:6003
|
#18 0x0000556747e927cf in mysql_parse (thd=thd@entry=0x14b1b4000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14b200fbe2c0) at /test/11.0_dbg/sql/sql_parse.cc:8002
|
#19 0x0000556747e94963 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14b1b4000d58, packet=packet@entry=0x14b1b400ae19 "CALL p (@b)", packet_length=packet_length@entry=11, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_class.h:242
|
#20 0x0000556747e967bc in do_command (thd=0x14b1b4000d58, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_parse.cc:1407
|
#21 0x0000556747fe76e2 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55674aa26d58, put_in_cache=put_in_cache@entry=true) at /test/11.0_dbg/sql/sql_connect.cc:1416
|
#22 0x0000556747fe7941 in handle_one_connection (arg=0x55674aa26d58) at /test/11.0_dbg/sql/sql_connect.cc:1318
|
#23 0x000014b21a6b3b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
|
#24 0x000014b21a745a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
|
Confirmed the crash in 10.6-11.0 (dbg), and the error message in 10.6-11.0 (opt). 10.5 Does not look to be affected.
If we remove TEMPORARY from the testcase for t2, we get:
|
11.0.1 f2dc4d4c10ac36a73b5c1eb765352d3aee808d66 (Debug) |
11.0.1-dbg>INSERT INTO t2 VALUES(),();
|
ERROR 1180 (HY000): Got error 1 "Operation not permitted" during COMMIT
|
11.0.1-dbg>CALL p (@b);
|
Query OK, 0 rows affected (0.000 sec)
|
Any non-affected version will produce (with and without TEMPORARY):
|
10.5.20 c41c79650aa2ef8eaf3f887b94db8cc7478eadd1 (Optimized) |
10.5.20-opt>INSERT INTO t2 VALUES(),();
|
ERROR 1062 (23000): Duplicate entry '0' for key 'PRIMARY'
|
10.5.20-opt>CALL p (@b);
|
Query OK, 0 rows affected (0.001 sec)
|
I am getting the error:
`ERROR 1180 (HY000) at line 2245: Got error 1 "Operation not permitted" during COMMIT`
on trying to import mysqldump into Mariadb 10.11.2
the line 2245 has
`INTO INTO plan_changes VALUES`
and then values follow.
The problem was caused by a duplicate entry (created on master running MariaDB 10.10.3). There is an index:
Indexes
PRIMARY id
UNIQUE user_id, requirement_id
and I found duplicate by running a query:
```
SELECT user_id, requirement_id, COUNT
cc
FROM plan_changes
GROUP BY user_id, requirement_id
HAVING cc > 1
```
Deleted one record on master, made dump again and I was able to import mysql dump on replica without issues.
Normally, on duplicate I was getting error on other tables:
```
Duplicate entry '9329-2023-02-01-0' for key 'listing_month'
```
Duplicates somehow get created when a table has primary key + unique key and we perform 'on duplicate update' query. Not every time but about 100 duplicates found on a large table.
Erland22 FYI, you can use {noformat}...{noformat} and {code:sql}...{code} tags in JIRA instead of ```.
Thank you, the 10.6 version looks good to me. The 10.8 version is a bit different due to MDEV-24621. I still need to understand it better, but I do not expect any problems there.
The 10.8 version is different, because if there is an outstanding error noticed at the end of a statement or during the execution of XA PREPARE, we must retain the transaction as active for further error handling. We kind of roll it back while keeping the transaction active.