[MDEV-11071] Assertion `thd->transaction.stmt.is_empty()' failed in Locked_tables_list::unlock_locked_tables Created: 2016-10-17  Updated: 2018-10-16  Resolved: 2018-06-15

Status: Closed
Project: MariaDB Server
Component/s: Locking, Storage Engine - InnoDB
Affects Version/s: 10.2
Fix Version/s: 10.2.16, 10.3.8

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: affects-tests

Issue Links:
Blocks
blocks MDEV-13900 Testing for MDEV-11369 (instant ADD C... Closed
Duplicate
is duplicated by MDEV-16794 Assertion `thd->transaction.stmt.is_e... Closed
is duplicated by MDEV-17314 Assertion `thd->transaction.stmt.is_e... Closed
Sub-Tasks:
Key
 Summary
 Type
 Status
 Assignee
MDEV-14421 Restore TEMPORARY tables in instant_a... Technical task Closed Elena Stepanova  
Sprint: 10.2.12, 10.2.14

 Description   

10.2 ca3c8d9b58fdc267b

 
mysqld: /data/src/10.2/sql/sql_base.cc:2153: void Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction.stmt.is_empty()' failed.
 
170926 17:12:24 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f4a73b09ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055baadf8c00a in Locked_tables_list::unlock_locked_tables (this=0x7f4a10004510, thd=0x7f4a10000b00) at /data/src/10.2/sql/sql_base.cc:2153
 
#9  0x000055baadf8c08f in Locked_tables_list::unlock_locked_table (this=0x7f4a10004510, thd=0x7f4a10000b00, mdl_ticket=0x0) at /data/src/10.2/sql/sql_base.cc:2196
 
#10 0x000055baae0c61f4 in mysql_create_table (thd=0x7f4a10000b00, create_table=0x7f4a10012588, create_info=0x7f4a64762920, alter_info=0x7f4a64762870) at /data/src/10.2/sql/sql_table.cc:5121
 
#11 0x000055baadffeabd in mysql_execute_command (thd=0x7f4a10000b00) at /data/src/10.2/sql/sql_parse.cc:3966
 
#12 0x000055baae00b24a in mysql_parse (thd=0x7f4a10000b00, rawbuf=0x7f4a10012438 "CREATE OR REPLACE TEMPORARY TABLE t1 (d INT) ENGINE=InnoDB ROW_FORMAT=COMPRESSED", length=80, parser_state=0x7f4a64763200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7875
 
#13 0x000055baadff8efb in dispatch_command (command=COM_QUERY, thd=0x7f4a10000b00, packet=0x7f4a1013ea71 "CREATE OR REPLACE TEMPORARY TABLE t1 (d INT) ENGINE=InnoDB ROW_FORMAT=COMPRESSED", packet_length=80, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1812
 
#14 0x000055baadff7875 in do_command (thd=0x7f4a10000b00) at /data/src/10.2/sql/sql_parse.cc:1360
 
#15 0x000055baae144ae1 in do_handle_one_connection (connect=0x55bab2530340) at /data/src/10.2/sql/sql_connect.cc:1354
 
#16 0x000055baae14486e in handle_one_connection (arg=0x55bab2530340) at /data/src/10.2/sql/sql_connect.cc:1260
 
#17 0x000055baae561616 in pfs_spawn_thread (arg=0x55bab253a8b0) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#18 0x00007f4a75a4e494 in start_thread (arg=0x7f4a64764700) at pthread_create.c:333
 
#19 0x00007f4a73bc693f in clone () from /lib/x86_64-linux-gnu/libc.so.6


--source include/have_innodb.inc
 
 
 
CREATE TEMPORARY TABLE t1 (a INT) ENGINE=InnoDB;
 
CREATE TEMPORARY TABLE t2 (b INT, c INT) ENGINE=InnoDB ROW_FORMAT=COMPACT;
 
LOCK TABLE t2 WRITE;
 
ALTER TABLE t2 DROP COLUMN c;
 
CREATE OR REPLACE TEMPORARY TABLE t1 (d INT) ENGINE=InnoDB ROW_FORMAT=COMPRESSED;

Reproducible on older 10.2 builds too.
First noticed some time around MDEV-10813 development.
No visible problems on non-debug builds.

 Comments   
Comment by Elena Stepanova [ 2017-11-17 ]

Here is another test case, which does not involve temporary tables.

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (d DATETIME DEFAULT CURRENT_TIMESTAMP, i INT) ENGINE=InnoDB;
 
INSERT INTO t1 (i) VALUES (1),(1);
 
LOCK TABLE t1 WRITE;
 
ALTER TABLE t1 ADD UNIQUE(i);
 
 
 
# Cleanup
 
UNLOCK TABLES;
 
DROP TABLE t1;

10.2 0c4d11e8199 debug

 
mysqld: /data/src/10.2/sql/sql_base.cc:2153: void Locked_tables_list::unlock_locked_tables(THD*): Assertion `thd->transaction.stmt.is_empty()' failed.
 
171117 19:36:45 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f1392de0ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x00005555d7b6ea84 in Locked_tables_list::unlock_locked_tables (this=0x7f1340004510, thd=0x7f1340000b00) at /data/src/10.2/sql/sql_base.cc:2153
 
#9  0x00005555d7b6ede1 in Locked_tables_list::unlink_all_closed_tables (this=0x7f1340004510, thd=0x7f1340000b00, lock=0x0, reopen_count=0) at /data/src/10.2/sql/sql_base.cc:2330
 
#10 0x00005555d7b6eeaf in Locked_tables_list::reopen_tables (this=0x7f1340004510, thd=0x7f1340000b00) at /data/src/10.2/sql/sql_base.cc:2364
 
#11 0x00005555d7caed11 in mysql_inplace_alter_table (thd=0x7f1340000b00, table_list=0x7f1340012530, table=0x7f1340132430, altered_table=0x7f134011ee30, ha_alter_info=0x7f138c24b610, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f138c24b680, alter_ctx=0x7f138c24c240) at /data/src/10.2/sql/sql_table.cc:7458
 
#12 0x00005555d7cb3bab in mysql_alter_table (thd=0x7f1340000b00, new_db=0x7f1340012b40 "test", new_name=0x0, create_info=0x7f138c24ce50, table_list=0x7f1340012530, alter_info=0x7f138c24cda0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9324
 
#13 0x00005555d7d2cc9c in Sql_cmd_alter_table::execute (this=0x7f1340012c08, thd=0x7f1340000b00) at /data/src/10.2/sql/sql_alter.cc:324
 
#14 0x00005555d7be920e in mysql_execute_command (thd=0x7f1340000b00) at /data/src/10.2/sql/sql_parse.cc:6197
 
#15 0x00005555d7bedabe in mysql_parse (thd=0x7f1340000b00, rawbuf=0x7f1340012448 "ALTER TABLE t1 ADD UNIQUE(i)", length=28, parser_state=0x7f138c24e200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7869
 
#16 0x00005555d7bdba4a in dispatch_command (command=COM_QUERY, thd=0x7f1340000b00, packet=0x7f13400088a1 "ALTER TABLE t1 ADD UNIQUE(i)", packet_length=28, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1805
 
#17 0x00005555d7bda3a8 in do_command (thd=0x7f1340000b00) at /data/src/10.2/sql/sql_parse.cc:1360
 
#18 0x00005555d7d2798d in do_handle_one_connection (connect=0x5555dac6c2d0) at /data/src/10.2/sql/sql_connect.cc:1354
 
#19 0x00005555d7d2771a in handle_one_connection (arg=0x5555dac6c2d0) at /data/src/10.2/sql/sql_connect.cc:1260
 
#20 0x00005555d8144e1a in pfs_spawn_thread (arg=0x5555dac76840) at /data/src/10.2/storage/perfschema/pfs.cc:1863
 
#21 0x00007f1394ab7494 in start_thread (arg=0x7f138c24f700) at pthread_create.c:333
 
#22 0x00007f1392e9d93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

10.2 0c4d11e8199f4c non-debug

 
#2  <signal handler called>
 
#3  default_column_bitmaps (this=0x0) at /data/src/10.2/sql/table.h:1374
 
#4  handler::ha_reset (this=0x7fd404093dc0) at /data/src/10.2/sql/handler.cc:5952
 
#5  0x0000561598ed3428 in THD::mark_tmp_table_as_free_for_reuse (this=this@entry=0x7fd4040009a8, table=0x7fd404093228) at /data/src/10.2/sql/temporary_tables.cc:766
 
#6  0x0000561598ed479d in THD::mark_tmp_tables_as_free_for_reuse (this=this@entry=0x7fd4040009a8) at /data/src/10.2/sql/temporary_tables.cc:727
 
#7  0x0000561598d4f667 in close_thread_tables (thd=thd@entry=0x7fd4040009a8) at /data/src/10.2/sql/sql_base.cc:792
 
#8  0x0000561598d502e0 in Locked_tables_list::unlock_locked_tables (this=0x7fd404004200, thd=0x7fd4040009a8) at /data/src/10.2/sql/sql_base.cc:2154
 
#9  0x0000561598d51b67 in Locked_tables_list::reopen_tables (this=this@entry=0x7fd404004200, thd=thd@entry=0x7fd4040009a8) at /data/src/10.2/sql/sql_base.cc:2364
 
#10 0x0000561598e204cd in mysql_inplace_alter_table (target_mdl_request=0x7fd45c4b7cf0, alter_ctx=0x7fd45c4b88b0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, ha_alter_info=0x7fd45c4b7c60, altered_table=0x7fd404093228, table=0x7fd4040b6348, table_list=0x7fd40400f0f8, thd=0x7fd4040009a8) at /data/src/10.2/sql/sql_table.cc:7458
 
#11 mysql_alter_table (thd=0x7fd4040009a8, new_db=<optimized out>, new_name=<optimized out>, create_info=<optimized out>, table_list=0x7fd40400f0f8, alter_info=<optimized out>, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9324
 
#12 0x0000561598e67ee5 in Sql_cmd_alter_table::execute (this=0x7fd404093dc0, thd=0x7fd4040009a8) at /data/src/10.2/sql/sql_alter.cc:324
 
#13 0x0000561598d93ad9 in mysql_execute_command (thd=0x7fd4040009a8) at /data/src/10.2/sql/sql_parse.cc:6197
 
#14 0x0000561598d9a7e9 in mysql_parse (thd=0x7fd4040009a8, rawbuf=<optimized out>, length=28, parser_state=0x7fd45c4bb240, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:7869
 
#15 0x0000561598d9d244 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fd4040009a8, packet=packet@entry=0x7fd404006c69 "ALTER TABLE t1 ADD UNIQUE(i)", packet_length=packet_length@entry=28, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1805
 
#16 0x0000561598d9dae3 in do_command (thd=0x7fd4040009a8) at /data/src/10.2/sql/sql_parse.cc:1360
 
#17 0x0000561598e65224 in do_handle_one_connection (connect=connect@entry=0x56159afba698) at /data/src/10.2/sql/sql_connect.cc:1354
 
#18 0x0000561598e653c4 in handle_one_connection (arg=arg@entry=0x56159afba698) at /data/src/10.2/sql/sql_connect.cc:1260
 
#19 0x0000561599124964 in pfs_spawn_thread (arg=0x56159af6eee8) at /data/src/10.2/storage/perfschema/pfs.cc:1863
 
#20 0x00007fd465423494 in start_thread (arg=0x7fd45c4bc700) at pthread_create.c:333
 
#21 0x00007fd46380993f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Comment by Elena Stepanova [ 2017-11-17 ]

Raised the priority because there is a basic scenario which crashes on a non-debug build, and also because the failure causes major problems for testing, e.g. MDEV-13900.

Comment by Sergey Vojtovich [ 2017-11-22 ]

Most probably CREATE OR REPLACE issue. I hopefully should be able to find out what's going on since I already fixed something similar a while ago. Very unlikely to relate to MDEV-10813.

Comment by Sergey Vojtovich [ 2017-12-25 ]

Caused by MDEV-5619.

Comment by Sergey Vojtovich [ 2017-12-26 ]

serg, please review fix for this bug.

Comment by Sergey Vojtovich [ 2017-12-29 ]

Fix for the first issue pushed to 10.2.12.

Second issue: ALTER TABLE fails due to duplicate key error. Then we try to reopen table and do parse_vcol_defs(), which constructs string like "PARSE_VCOL_EXPR current_timestamp(0)" and then it errors our because field->default_value->expr is not set.

Comment by Sergey Vojtovich [ 2018-03-09 ]

The second bug is triggered with the following test case:

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (d DATETIME DEFAULT CURRENT_TIMESTAMP, i INT) ENGINE=InnoDB;
 
INSERT INTO t1 (i) VALUES (1),(1);
 
LOCK TABLE t1 WRITE;
 
--error 1062
 
ALTER TABLE t1 ADD UNIQUE(i);
 
 
 
# Cleanup
 
UNLOCK TABLES;
 
DROP TABLE t1;

ALTER TABLE fails due to "duplicate keys" error. Since we're under LOCK TABLES, we need to reopen tables after failing ALTER TABLE. Then eventually we call Item_func::fix_fields() with thd->is_error() set (duplicate keys). The following code cannot handle this situation:

Item_func::fix_fields()
 
{
 
...
 
  fix_length_and_dec();
 
  if (thd->is_error()) // An error inside fix_length_and_dec occurred
 
    return TRUE;
 
...
 
}

It appears to be introduced by 691b7584.

Stack trace to that code:

#0  Item_func::fix_fields (this=0x7fffa402b9e0, thd=0x7fffa4000b00, ref=0x7fffa402bae8) at /home/svoj/devel/maria/mariadb/sql/item_func.cc:202
 
#1  0x0000555555e67481 in Item_func_now::fix_fields (this=0x7fffa402b9e0, thd=0x7fffa4000b00, items=0x7fffa402bae8) at /home/svoj/devel/maria/mariadb/sql/item_timefunc.cc:1725
 
#2  0x0000555555c0a34d in fix_vcol_expr (thd=0x7fffa4000b00, vcol=0x7fffa402bad8) at /home/svoj/devel/maria/mariadb/sql/table.cc:2745
 
#3  0x0000555555c0a74a in fix_and_check_vcol_expr (thd=0x7fffa4000b00, table=0x7fffa403b6a0, vcol=0x7fffa402bad8) at /home/svoj/devel/maria/mariadb/sql/table.cc:2830
 
#4  0x0000555555c0aba9 in unpack_vcol_info_from_frm (thd=0x7fffa4000b00, mem_root=0x7fffa403c158, table=0x7fffa403b6a0, expr_str=0x7ffff0093a70, vcol_ptr=0x7fffa402b850, error_reported=0x7ffff0093df9) at /home/svoj/devel/maria/mariadb/sql/table.cc:2949
 
#5  0x0000555555c045e3 in parse_vcol_defs (thd=0x7fffa4000b00, mem_root=0x7fffa403c158, table=0x7fffa403b6a0, error_reported=0x7ffff0093df9) at /home/svoj/devel/maria/mariadb/sql/table.cc:1109
 
#6  0x0000555555c0b85a in open_table_from_share (thd=0x7fffa4000b00, share=0x7fffa401e9c8, alias=0x7fffa402c448 "t1", db_stat=33, prgflag=8, ha_open_flags=16, outparam=0x7fffa403b6a0, is_create_table=false) at /home/svoj/devel/maria/mariadb/sql/table.cc:3183
 
#7  0x0000555555a96ab6 in open_table (thd=0x7fffa4000b00, table_list=0x7fffa402be28, ot_ctx=0x7ffff0094240) at /home/svoj/devel/maria/mariadb/sql/sql_base.cc:1877
 
#8  0x0000555555a978f1 in Locked_tables_list::reopen_tables (this=0x7fffa4004518, thd=0x7fffa4000b00) at /home/svoj/devel/maria/mariadb/sql/sql_base.cc:2362
 
#9  0x0000555555bd8357 in mysql_inplace_alter_table (thd=0x7fffa4000b00, table_list=0x7fffa4012680, table=0x7fffa4027ed0, altered_table=0x7fffa402f560, ha_alter_info=0x7ffff0094490, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE,
 
    target_mdl_request=0x7ffff0094500, alter_ctx=0x7ffff00950c0) at /home/svoj/devel/maria/mariadb/sql/sql_table.cc:7458
 
#10 0x0000555555bdd4a5 in mysql_alter_table (thd=0x7fffa4000b00, new_db=0x7fffa4012c90 "test", new_name=0x0, create_info=0x7ffff0095cd0, table_list=0x7fffa4012680, alter_info=0x7ffff0095c20, order_num=0, order=0x0, ignore=false)
 
    at /home/svoj/devel/maria/mariadb/sql/sql_table.cc:9351
 
#11 0x0000555555c56f0b in Sql_cmd_alter_table::execute (this=0x7fffa4012d58, thd=0x7fffa4000b00) at /home/svoj/devel/maria/mariadb/sql/sql_alter.cc:324
 
#12 0x0000555555b12543 in mysql_execute_command (thd=0x7fffa4000b00) at /home/svoj/devel/maria/mariadb/sql/sql_parse.cc:6208
 
#13 0x0000555555b171c6 in mysql_parse (thd=0x7fffa4000b00, rawbuf=0x7fffa4012598 "ALTER TABLE t1 ADD UNIQUE(i)", length=28, parser_state=0x7ffff0097080, is_com_multi=false, is_next_command=false) at /home/svoj/devel/maria/mariadb/sql/sql_parse.cc:7902
 
#14 0x0000555555b04c09 in dispatch_command (command=COM_QUERY, thd=0x7fffa4000b00, packet=0x7fffa4008951 "ALTER TABLE t1 ADD UNIQUE(i)", packet_length=28, is_com_multi=false, is_next_command=false) at /home/svoj/devel/maria/mariadb/sql/sql_parse.cc:1806
 
#15 0x0000555555b034bd in do_command (thd=0x7fffa4000b00) at /home/svoj/devel/maria/mariadb/sql/sql_parse.cc:1360
 
#16 0x0000555555c51c3e in do_handle_one_connection (connect=0x5555580934b0) at /home/svoj/devel/maria/mariadb/sql/sql_connect.cc:1335
 
#17 0x0000555555c51991 in handle_one_connection (arg=0x5555580934b0) at /home/svoj/devel/maria/mariadb/sql/sql_connect.cc:1241
 
#18 0x0000555555f9e1e0 in pfs_spawn_thread (arg=0x555557ff7110) at /home/svoj/devel/maria/mariadb/storage/perfschema/pfs.cc:1862
 
#19 0x00007ffff68a96ba in start_thread (arg=0x7ffff0098700) at pthread_create.c:333
 
#20 0x00007ffff5d3e41d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Comment by Oleksandr Byelkin [ 2018-03-09 ]

agg_arg_charsets_for_string_result never should be called from fix_length_and_dec because it return operation result
I see 3 ways to fix it:

1) add result to fix_length_and_dec
2) make new virtual method like fix_collations call it before fix_length_and_dec and check return code.
3) add fix_fieldds for items which now use agg_arg_charsets_for_string_result (the fix_fields will call old_fix_fields this function and fix_length_and_dec again...

Comment by Oleksandr Byelkin [ 2018-05-08 ]

revision-id: 46e0c8a921978e7b95adf3f17f3c85b18d9f9ef6 (mariadb-10.2.14-78-g46e0c8a9219)
parent(s): 9bcd0f5fea8ca26742b10d37b95a966c69909ff1
author: Oleksandr Byelkin
committer: Oleksandr Byelkin
timestamp: 2018-05-08 15:26:26 +0200
message:

MDEV-11071: Assertion `thd->transaction.stmt.is_empty()' failed in Locked_tables_list::unlock_locked_table

fix_length_and_dec now return result (error/OK)

—

Comment by Oleksandr Byelkin [ 2018-06-14 ]

revision-id: 71c318372e919e21ccf73e54553fffecb1040f75 (mariadb-10.2.15-56-g71c318372e9)
parent(s): a79b033b359b882f2fe88051781c6e850bd71780
author: Oleksandr Byelkin
committer: Oleksandr Byelkin
timestamp: 2018-06-14 17:58:33 +0200
message:

MDEV-11071: Assertion `thd->transaction.stmt.is_empty()' failed in Locked_tables_list::unlock_locked_table

fix_length_and_dec now return result (error/OK)

Generated at Thu Feb 08 07:47:05 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.