[MDEV-23843] Assertions in Diagnostics_area upon table operations under FTWRL - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.4(EOL), 10.5
Fix Version/s: 10.4.19, 10.5.10
Component/s: Admin statements, Locking, Replication
Labels:
- affects-tests
- regression

Description

The failure appeared in 10.4 branch after this commit:

commit 16ea692ed490a1a2c6dc0b855247d5bd02bd2345

Author: Monty

Date:   Mon Sep 7 10:38:12 2020 +0300

    MDEV-23586 Mariabackup: GTID saved for replication in 10.4.14 is wrong

--source include/have_log_bin.inc

CREATE TABLE t (a INT);

FLUSH TABLES WITH READ LOCK;

--connect (con1,localhost,root,,)

SET lock_wait_timeout= 1;

OPTIMIZE TABLE t;

# Cleanup

--disconnect con1

--connection default

UNLOCK TABLES;

DROP TABLE t;

10.4 79e32e47
mysqld: /data/src/10.4/sql/sql_error.cc:445: void Diagnostics_area::set_error_status(uint, const char, const char, const Sql_user_condition_identity&, const Sql_condition*): Assertion `! is_set() \|\| m_can_overwrite_status' failed.
200929 17:06:23 [ERROR] mysqld got signal 6 ;

#7 0x00007fea87695f36 in __GI___assert_fail (assertion=0x5622d20ab0e0 "! is_set() \|\| m_can_overwrite_status", file=0x5622d20aae78 "/data/src/10.4/sql/sql_error.cc", line=445, function=0x5622d20ab108 "void Diagnostics_area::set_error_status(uint, const char, const char, const Sql_user_condition_identity&, const Sql_condition*)") at assert.c:101
#8 0x00005622d12a9330 in Diagnostics_area::set_error_status (this=0x7fea68006780, sql_errno=1205, message=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction", sqlstate=0x5622d20d068d "HY000", ucid=..., error_condition=0x0) at /data/src/10.4/sql/sql_error.cc:445
#9 0x00005622d12834ed in THD::raise_condition (this=0x7fea68000d90, sql_errno=1205, sqlstate=0x5622d20d068d "HY000", level=Sql_state_errno_level::WARN_LEVEL_ERROR, ucid=..., msg=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction") at /data/src/10.4/sql/sql_class.cc:1100
#10 0x00005622d11c50b2 in THD::raise_condition (this=0x7fea68000d90, sql_errno=1205, sqlstate=0x0, level=Sql_state_errno_level::WARN_LEVEL_ERROR, msg=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction") at /data/src/10.4/sql/sql_class.h:4385
#11 0x00005622d11b7a43 in my_message_sql (error=1205, str=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction", MyFlags=0) at /data/src/10.4/sql/mysqld.cc:3373
#12 0x00005622d1fc8bbd in my_error (nr=1205, MyFlags=0) at /data/src/10.4/mysys/my_error.c:125
#13 0x00005622d1494919 in MDL_context::acquire_lock (this=0x7fea68000eb0, mdl_request=0x7fea815cf750, lock_wait_timeout=1) at /data/src/10.4/sql/mdl.cc:2365
#14 0x00005622d17a5432 in MYSQL_BIN_LOG::write (this=0x5622d2b85a60 <mysql_bin_log>, event_info=0x7fea815cf990, with_annotate=0x0) at /data/src/10.4/sql/log.cc:6391
#15 0x00005622d12949b0 in THD::binlog_query (this=0x7fea68000d90, qtype=THD::STMT_QUERY_TYPE, query_arg=0x7fea68014348 "OPTIMIZE TABLE t", query_len=16, is_trans=false, direct=false, suppress_use=false, errcode=0) at /data/src/10.4/sql/sql_class.cc:7202
#16 0x00005622d13dd50e in write_bin_log (thd=0x7fea68000d90, clear_error=true, query=0x7fea68014348 "OPTIMIZE TABLE t", query_length=16, is_trans=false) at /data/src/10.4/sql/sql_table.cc:1988
#17 0x00005622d149cefe in Sql_cmd_optimize_table::execute (this=0x7fea68014ad0, thd=0x7fea68000d90) at /data/src/10.4/sql/sql_admin.cc:1391
#18 0x00005622d130718d in mysql_execute_command (thd=0x7fea68000d90) at /data/src/10.4/sql/sql_parse.cc:6098
#19 0x00005622d130c733 in mysql_parse (thd=0x7fea68000d90, rawbuf=0x7fea68014348 "OPTIMIZE TABLE t", length=16, parser_state=0x7fea815d0550, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7896
#20 0x00005622d12f8c3e in dispatch_command (command=COM_QUERY, thd=0x7fea68000d90, packet=0x7fea680088a1 "", packet_length=16, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1834
#21 0x00005622d12f74a6 in do_command (thd=0x7fea68000d90) at /data/src/10.4/sql/sql_parse.cc:1352
#22 0x00005622d14852bb in do_handle_one_connection (connect=0x5622d535bf40) at /data/src/10.4/sql/sql_connect.cc:1412
#23 0x00005622d1485004 in handle_one_connection (arg=0x5622d535bf40) at /data/src/10.4/sql/sql_connect.cc:1316
#24 0x00005622d1e9dbf2 in pfs_spawn_thread (arg=0x5622d530b5f0) at /data/src/10.4/storage/perfschema/pfs.cc:1869
#25 0x00007fea87bad609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#26 0x00007fea87781293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Only reproducible on 10.4, not on 10.2-10.3 or 10.5 (yet?).
Also, only on 10.4 a non-debug build returns ER_LOCK_WAIT_TIMEOUT for OPTIMIZE in the test case above. On other versions it only prints "Lock wait timeout exceeded; try restarting transaction" in the optimize output, but doesn't throw the error.
No obvious problem on a non-debug build.
Not reproducible without binary logging.

Attachments

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2020-09-29 14:09

Elena Stepanova made changes - 2020-09-29 16:06

Field	Original Value	New Value
Description	{code:sql} --source include/have_log_bin.inc CREATE TABLE t (a INT); FLUSH TABLES WITH READ LOCK; --connect (con1,localhost,root,,) SET lock_wait_timeout= 1; OPTIMIZE TABLE t; # Cleanup --disconnect con1 --connection default UNLOCK TABLES; DROP TABLE t; {code} {noformat:title=10.4 79e32e47} mysqld: /data/src/10.4/sql/sql_error.cc:445: void Diagnostics_area::set_error_status(uint, const char, const char, const Sql_user_condition_identity&, const Sql_condition): Assertion `! is_set() \|\| m_can_overwrite_status' failed. 200929 17:06:23 [ERROR] mysqld got signal 6 ; #7 0x00007fea87695f36 in __GI___assert_fail (assertion=0x5622d20ab0e0 "! is_set() \|\| m_can_overwrite_status", file=0x5622d20aae78 "/data/src/10.4/sql/sql_error.cc", line=445, function=0x5622d20ab108 "void Diagnostics_area::set_error_status(uint, const char, const char, const Sql_user_condition_identity&, const Sql_condition)") at assert.c:101 #8 0x00005622d12a9330 in Diagnostics_area::set_error_status (this=0x7fea68006780, sql_errno=1205, message=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction", sqlstate=0x5622d20d068d "HY000", ucid=..., error_condition=0x0) at /data/src/10.4/sql/sql_error.cc:445 #9 0x00005622d12834ed in THD::raise_condition (this=0x7fea68000d90, sql_errno=1205, sqlstate=0x5622d20d068d "HY000", level=Sql_state_errno_level::WARN_LEVEL_ERROR, ucid=..., msg=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction") at /data/src/10.4/sql/sql_class.cc:1100 #10 0x00005622d11c50b2 in THD::raise_condition (this=0x7fea68000d90, sql_errno=1205, sqlstate=0x0, level=Sql_state_errno_level::WARN_LEVEL_ERROR, msg=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction") at /data/src/10.4/sql/sql_class.h:4385 #11 0x00005622d11b7a43 in my_message_sql (error=1205, str=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction", MyFlags=0) at /data/src/10.4/sql/mysqld.cc:3373 #12 0x00005622d1fc8bbd in my_error (nr=1205, MyFlags=0) at /data/src/10.4/mysys/my_error.c:125 #13 0x00005622d1494919 in MDL_context::acquire_lock (this=0x7fea68000eb0, mdl_request=0x7fea815cf750, lock_wait_timeout=1) at /data/src/10.4/sql/mdl.cc:2365 #14 0x00005622d17a5432 in MYSQL_BIN_LOG::write (this=0x5622d2b85a60 <mysql_bin_log>, event_info=0x7fea815cf990, with_annotate=0x0) at /data/src/10.4/sql/log.cc:6391 #15 0x00005622d12949b0 in THD::binlog_query (this=0x7fea68000d90, qtype=THD::STMT_QUERY_TYPE, query_arg=0x7fea68014348 "OPTIMIZE TABLE t", query_len=16, is_trans=false, direct=false, suppress_use=false, errcode=0) at /data/src/10.4/sql/sql_class.cc:7202 #16 0x00005622d13dd50e in write_bin_log (thd=0x7fea68000d90, clear_error=true, query=0x7fea68014348 "OPTIMIZE TABLE t", query_length=16, is_trans=false) at /data/src/10.4/sql/sql_table.cc:1988 #17 0x00005622d149cefe in Sql_cmd_optimize_table::execute (this=0x7fea68014ad0, thd=0x7fea68000d90) at /data/src/10.4/sql/sql_admin.cc:1391 #18 0x00005622d130718d in mysql_execute_command (thd=0x7fea68000d90) at /data/src/10.4/sql/sql_parse.cc:6098 #19 0x00005622d130c733 in mysql_parse (thd=0x7fea68000d90, rawbuf=0x7fea68014348 "OPTIMIZE TABLE t", length=16, parser_state=0x7fea815d0550, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7896 #20 0x00005622d12f8c3e in dispatch_command (command=COM_QUERY, thd=0x7fea68000d90, packet=0x7fea680088a1 "", packet_length=16, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1834 #21 0x00005622d12f74a6 in do_command (thd=0x7fea68000d90) at /data/src/10.4/sql/sql_parse.cc:1352 #22 0x00005622d14852bb in do_handle_one_connection (connect=0x5622d535bf40) at /data/src/10.4/sql/sql_connect.cc:1412 #23 0x00005622d1485004 in handle_one_connection (arg=0x5622d535bf40) at /data/src/10.4/sql/sql_connect.cc:1316 #24 0x00005622d1e9dbf2 in pfs_spawn_thread (arg=0x5622d530b5f0) at /data/src/10.4/storage/perfschema/pfs.cc:1869 #25 0x00007fea87bad609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #26 0x00007fea87781293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 {noformat} Only reproducible on 10.4, not on 10.2-10.3 or 10.5. Also, only on 10.4 a non-debug build returns ER_LOCK_WAIT_TIMEOUT for OPTIMIZE in the test case above. On other versions it only prints "Lock wait timeout exceeded; try restarting transaction" in the optimize output, but doesn't throw the error. No obvious problem on a non-debug build. Not reproducible without binary logging.	The failure appeared in 10.4 branch after this commit: {noformat} commit 16ea692ed490a1a2c6dc0b855247d5bd02bd2345 Author: Monty Date: Mon Sep 7 10:38:12 2020 +0300 ~~MDEV-23586~~ Mariabackup: GTID saved for replication in 10.4.14 is wrong {noformat} {code:sql} --source include/have_log_bin.inc CREATE TABLE t (a INT); FLUSH TABLES WITH READ LOCK; --connect (con1,localhost,root,,) SET lock_wait_timeout= 1; OPTIMIZE TABLE t; # Cleanup --disconnect con1 --connection default UNLOCK TABLES; DROP TABLE t; {code} {noformat:title=10.4 79e32e47} mysqld: /data/src/10.4/sql/sql_error.cc:445: void Diagnostics_area::set_error_status(uint, const char, const char, const Sql_user_condition_identity&, const Sql_condition): Assertion `! is_set() \|\| m_can_overwrite_status' failed. 200929 17:06:23 [ERROR] mysqld got signal 6 ; #7 0x00007fea87695f36 in __GI___assert_fail (assertion=0x5622d20ab0e0 "! is_set() \|\| m_can_overwrite_status", file=0x5622d20aae78 "/data/src/10.4/sql/sql_error.cc", line=445, function=0x5622d20ab108 "void Diagnostics_area::set_error_status(uint, const char, const char, const Sql_user_condition_identity&, const Sql_condition)") at assert.c:101 #8 0x00005622d12a9330 in Diagnostics_area::set_error_status (this=0x7fea68006780, sql_errno=1205, message=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction", sqlstate=0x5622d20d068d "HY000", ucid=..., error_condition=0x0) at /data/src/10.4/sql/sql_error.cc:445 #9 0x00005622d12834ed in THD::raise_condition (this=0x7fea68000d90, sql_errno=1205, sqlstate=0x5622d20d068d "HY000", level=Sql_state_errno_level::WARN_LEVEL_ERROR, ucid=..., msg=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction") at /data/src/10.4/sql/sql_class.cc:1100 #10 0x00005622d11c50b2 in THD::raise_condition (this=0x7fea68000d90, sql_errno=1205, sqlstate=0x0, level=Sql_state_errno_level::WARN_LEVEL_ERROR, msg=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction") at /data/src/10.4/sql/sql_class.h:4385 #11 0x00005622d11b7a43 in my_message_sql (error=1205, str=0x7fea815cf280 "Lock wait timeout exceeded; try restarting transaction", MyFlags=0) at /data/src/10.4/sql/mysqld.cc:3373 #12 0x00005622d1fc8bbd in my_error (nr=1205, MyFlags=0) at /data/src/10.4/mysys/my_error.c:125 #13 0x00005622d1494919 in MDL_context::acquire_lock (this=0x7fea68000eb0, mdl_request=0x7fea815cf750, lock_wait_timeout=1) at /data/src/10.4/sql/mdl.cc:2365 #14 0x00005622d17a5432 in MYSQL_BIN_LOG::write (this=0x5622d2b85a60 <mysql_bin_log>, event_info=0x7fea815cf990, with_annotate=0x0) at /data/src/10.4/sql/log.cc:6391 #15 0x00005622d12949b0 in THD::binlog_query (this=0x7fea68000d90, qtype=THD::STMT_QUERY_TYPE, query_arg=0x7fea68014348 "OPTIMIZE TABLE t", query_len=16, is_trans=false, direct=false, suppress_use=false, errcode=0) at /data/src/10.4/sql/sql_class.cc:7202 #16 0x00005622d13dd50e in write_bin_log (thd=0x7fea68000d90, clear_error=true, query=0x7fea68014348 "OPTIMIZE TABLE t", query_length=16, is_trans=false) at /data/src/10.4/sql/sql_table.cc:1988 #17 0x00005622d149cefe in Sql_cmd_optimize_table::execute (this=0x7fea68014ad0, thd=0x7fea68000d90) at /data/src/10.4/sql/sql_admin.cc:1391 #18 0x00005622d130718d in mysql_execute_command (thd=0x7fea68000d90) at /data/src/10.4/sql/sql_parse.cc:6098 #19 0x00005622d130c733 in mysql_parse (thd=0x7fea68000d90, rawbuf=0x7fea68014348 "OPTIMIZE TABLE t", length=16, parser_state=0x7fea815d0550, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7896 #20 0x00005622d12f8c3e in dispatch_command (command=COM_QUERY, thd=0x7fea68000d90, packet=0x7fea680088a1 "", packet_length=16, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1834 #21 0x00005622d12f74a6 in do_command (thd=0x7fea68000d90) at /data/src/10.4/sql/sql_parse.cc:1352 #22 0x00005622d14852bb in do_handle_one_connection (connect=0x5622d535bf40) at /data/src/10.4/sql/sql_connect.cc:1412 #23 0x00005622d1485004 in handle_one_connection (arg=0x5622d535bf40) at /data/src/10.4/sql/sql_connect.cc:1316 #24 0x00005622d1e9dbf2 in pfs_spawn_thread (arg=0x5622d530b5f0) at /data/src/10.4/storage/perfschema/pfs.cc:1869 #25 0x00007fea87bad609 in start_thread (arg=<optimized out>) at pthread_create.c:477 #26 0x00007fea87781293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 {noformat} Only reproducible on 10.4, not on 10.2-10.3 or 10.5 (yet?). Also, only on 10.4 a non-debug build returns ER_LOCK_WAIT_TIMEOUT for OPTIMIZE in the test case above. On other versions it only prints "Lock wait timeout exceeded; try restarting transaction" in the optimize output, but doesn't throw the error. No obvious problem on a non-debug build. Not reproducible without binary logging.
Labels		regression

Elena Stepanova made changes - 2020-09-29 16:14

Summary

Assertion `! is_set() || m_can_overwrite_status' failed in Diagnostics_area::set_error_status (OPTIMIZE under FTWRL)

Assertion `! is_set() || m_can_overwrite_status' failed in Diagnostics_area::set_error_status (OPTIMIZE etc under FTWRL)

Elena Stepanova made changes - 2020-09-29 16:17

Summary

Assertion `! is_set() || m_can_overwrite_status' failed in Diagnostics_area::set_error_status (OPTIMIZE etc under FTWRL)

Assertions in Diagnostics_area upon table operations under FTWRL with binary logging

Elena Stepanova made changes - 2020-09-29 16:20

Labels

regression

affects-tests regression

Alice Sherepa made changes - 2020-10-12 13:22

Affects Version/s

10.5 [ 23123 ]

Alice Sherepa made changes - 2020-10-12 13:22

Fix Version/s

10.5 [ 23123 ]

Alice Sherepa made changes - 2020-10-12 13:22

Status

Open [ 1 ]

Confirmed [ 10101 ]

Elena Stepanova made changes - 2020-11-16 17:50

Summary

Assertions in Diagnostics_area upon table operations under FTWRL with binary logging

Assertions in Diagnostics_area upon table operations under FTWRL

Michael Widenius made changes - 2021-02-14 15:31

Assignee

Rucha Deodhar [ rucha174 ]

Michael Widenius [ monty ]

Michael Widenius made changes - 2021-02-14 15:31

Status

Confirmed [ 10101 ]

In Progress [ 3 ]

Michael Widenius made changes - 2021-02-14 20:13

Fix Version/s		10.4.18 [ 25110 ]
Fix Version/s		10.5.9 [ 25109 ]
Fix Version/s	10.4 [ 22408 ]
Fix Version/s	10.5 [ 23123 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

Daniel Bartholomew made changes - 2021-02-22 15:58

Fix Version/s		10.4.19 [ 25205 ]
Fix Version/s	10.4.18 [ 25110 ]

Elena Stepanova made changes - 2021-03-02 11:03

Fix Version/s		10.4 [ 22408 ]
Fix Version/s		10.5 [ 23123 ]
Fix Version/s	10.5.9 [ 25109 ]
Fix Version/s	10.4.19 [ 25205 ]

Michael Widenius made changes - 2021-03-02 11:37

Resolution	Fixed [ 1 ]
Status	Closed [ 6 ]	Stalled [ 10000 ]

Michael Widenius made changes - 2021-03-02 13:19

issue.field.resolutiondate

2021-03-02 13:19:11.0

2021-03-02 13:19:11.51

Michael Widenius made changes - 2021-03-02 13:19

Fix Version/s		10.4.19 [ 25205 ]
Fix Version/s		10.5.10 [ 25204 ]
Fix Version/s	10.4 [ 22408 ]
Fix Version/s	10.5 [ 23123 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:52

Workflow

MariaDB v3 [ 114003 ]

MariaDB v4 [ 158412 ]

People

Assignee:: Michael Widenius

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2020-09-29 14:09

Updated:: 2021-03-02 13:19

Resolved:: 2021-03-02 13:19

Git Integration

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

MariaDB Server

Details

Description

Attachments

Activity

People

Dates

Git Integration