[MDEV-21994] Assertion `!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BACKUP_FINISHED' failed in reload_acl_and_cache Created: 2020-03-22  Updated: 2022-04-26  Resolved: 2022-04-26

Status: Closed
Project: MariaDB Server
Component/s: Backup, Locking
Affects Version/s: 10.4, 10.5
Fix Version/s: 10.4.16, 10.5.7

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

Issue Links:
Duplicate
is duplicated by MDEV-20945 BACKUP UNLOCK + FTWRL assertion failu... Closed
Relates
relates to MDEV-25589 Assertion `!thd || thd->locked_tables... Confirmed

 Description    

BACKUP LOCK x;
 
RESET QUERY CACHE;

10.4 debug bd3c8f47

 
mysqld: /data/src/10.4/sql/sql_reload.cc:219: bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*): Assertion `!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BACKUP_FINISHED' failed.
 
200322  2:28:51 [ERROR] mysqld got signal 6 ;
 
 
 
#6  0x00007fdb455e9e67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x5634d95cde38 "!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BAC"..., file=file@entry=0x5634d95cde10 "/data/src/10.4/sql/sql_reload.cc", line=line@entry=219, function=function@entry=0x5634d95cdfa0 <reload_acl_and_cache(THD*, unsigned long long, TABLE_LIST*, int*)::__PRETTY_FUNCTION__> "bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*)") at assert.c:92
 
#7  0x00007fdb455e9f12 in __GI___assert_fail (assertion=0x5634d95cde38 "!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BAC"..., file=0x5634d95cde10 "/data/src/10.4/sql/sql_reload.cc", line=219, function=0x5634d95cdfa0 <reload_acl_and_cache(THD*, unsigned long long, TABLE_LIST*, int*)::__PRETTY_FUNCTION__> "bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*)") at assert.c:101
 
#8  0x00005634d8a2fcbb in reload_acl_and_cache (thd=0x7fdb24000af0, options=65536, tables=0x0, write_to_binlog=0x7fdb3b766900) at /data/src/10.4/sql/sql_reload.cc:213
 
#9  0x00005634d887600d in mysql_execute_command (thd=0x7fdb24000af0) at /data/src/10.4/sql/sql_parse.cc:5460
 
#10 0x00005634d887e287 in mysql_parse (thd=0x7fdb24000af0, rawbuf=0x7fdb24013198 "RESET QUERY CACHE", length=17, parser_state=0x7fdb3b767160, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7900
 
#11 0x00005634d886946a in dispatch_command (command=COM_QUERY, thd=0x7fdb24000af0, packet=0x7fdb24136341 "RESET QUERY CACHE", packet_length=17, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1842
 
#12 0x00005634d8867af7 in do_command (thd=0x7fdb24000af0) at /data/src/10.4/sql/sql_parse.cc:1360
 
#13 0x00005634d89f0f7d in do_handle_one_connection (connect=0x5634dcba88d0) at /data/src/10.4/sql/sql_connect.cc:1412
 
#14 0x00005634d89f0ccc in handle_one_connection (arg=0x5634dcba88d0) at /data/src/10.4/sql/sql_connect.cc:1316
 
#15 0x00005634d93f93df in pfs_spawn_thread (arg=0x5634dcabc250) at /data/src/10.4/storage/perfschema/pfs.cc:1869
 
#16 0x00007fdb475724a4 in start_thread (arg=0x7fdb3b768700) at pthread_create.c:456
 
#17 0x00007fdb456a6d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Reproducible on 10.4, 10.5.
No obvious effect on a non-debug build.
The table for which BACKUP LOCK is executed can exist or not, the result is the same.
RESET command can vary, for example, RESET MASTER causes the same effect, even with the disabled binlog.

 Comments   
Comment by Roel Van de Paar [ 2020-04-25 ]

Additional testcase

SET STATEMENT max_statement_time=180 FOR BACKUP LOCK t;
 
RESET SLAVE ALL;

Leads to:

10.5.3 98003440c2f8d20164a191ced1b7d92b283bb68f

 
mysqld: /test/10.5_dbg/sql/sql_reload.cc:219: bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*): Assertion `!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BACKUP_FINISHED' failed.

10.5.3 98003440c2f8d20164a191ced1b7d92b283bb68f

 
Core was generated by `/test/MD210420-mariadb-10.5.3-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:57
 
[Current thread is 1 (Thread 0x7fc3743dc700 (LWP 9788))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055676b1c203d in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x000055676a967d7b in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:329
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00007fc372b20801 in __GI_abort () at abort.c:79
 
#6  0x00007fc372b1039a in __assert_fail_base (fmt=0x7fc372c977d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55676b387960 "!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BAC"..., file=file@entry=0x55676b387938 "/test/10.5_dbg/sql/sql_reload.cc", line=line@entry=219, function=function@entry=0x55676b387b60 <reload_acl_and_cache(THD*, unsigned long long, TABLE_LIST*, int*)::__PRETTY_FUNCTION__> "bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*)") at assert.c:92
 
#7  0x00007fc372b10412 in __GI___assert_fail (assertion=assertion@entry=0x55676b387960 "!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BAC"..., file=file@entry=0x55676b387938 "/test/10.5_dbg/sql/sql_reload.cc", line=line@entry=219, function=function@entry=0x55676b387b60 <reload_acl_and_cache(THD*, unsigned long long, TABLE_LIST*, int*)::__PRETTY_FUNCTION__> "bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*)") at assert.c:101
 
#8  0x000055676a843c5e in reload_acl_and_cache (thd=thd@entry=0x7fc34a415088, options=64, tables=tables@entry=0x0, write_to_binlog=write_to_binlog@entry=0x7fc3743dae00) at /test/10.5_dbg/sql/sql_reload.cc:213
 
#9  0x000055676a6c1cb8 in mysql_execute_command (thd=thd@entry=0x7fc34a415088) at /test/10.5_dbg/sql/sql_parse.cc:5384
 
#10 0x000055676a6caf2b in mysql_parse (thd=thd@entry=0x7fc34a415088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7fc3743db450, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7957
 
#11 0x000055676a6b6c45 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fc34a415088, packet=packet@entry=0x7fc34a467089 "RESET SLAVE ALL", packet_length=packet_length@entry=15, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1839
 
#12 0x000055676a6b549b in do_command (thd=0x7fc34a415088) at /test/10.5_dbg/sql/sql_parse.cc:1358
 
#13 0x000055676a810415 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x7fc3527c53a8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1422
 
#14 0x000055676a810744 in handle_one_connection (arg=arg@entry=0x7fc3527c53a8) at /test/10.5_dbg/sql/sql_connect.cc:1319
 
#15 0x000055676ac70fb0 in pfs_spawn_thread (arg=0x7fc372045b08) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#16 0x00007fc3738036db in start_thread (arg=0x7fc3743dc700) at pthread_create.c:463
 
#17 0x00007fc372c0188f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.13 (dbg), 10.5.2 (dbg), 10.5.3 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.45 (dbg), 10.1.45 (opt), 10.2.32 (dbg), 10.2.32 (opt), 10.3.23 (dbg), 10.3.23 (opt), 10.4.13 (opt), 10.5.2 (opt), 10.5.3 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

Comment by Roel Van de Paar [ 2020-04-25 ]

vlad.lesin Would you be able to check how serious this issue is please? Is it just a faulty assert, or could this affect production backups/optimized binaries? Updated prio to critical for the time being given the varied SQL's this can be produced with.

Comment by Roel Van de Paar [ 2020-09-22 ] 

USE test;
 
BACKUP LOCK t;
 
FLUSH LOCAL ERROR LOGS;

Leads to:

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

 
mysqld: /test/10.5_dbg/sql/sql_reload.cc:222: bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*): Assertion `!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BACKUP_FINISHED' failed.

10.5.6 2bac9782aa81ad386beaf00eb126ccf2d15031a1 (Debug)

 
Core was generated by `/test/MD150920-mariadb-10.5.6-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:57
 
[Current thread is 1 (Thread 0x1480e1f74700 (LWP 4110324))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x00005556bb62685a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:424
 
#2  0x00005556baded3a9 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00001480e020a8b1 in __GI_abort () at abort.c:79
 
#6  0x00001480e01fa42a in __assert_fail_base (fmt=0x1480e0381a38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5556bb7f52c0 "!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BAC"..., file=file@entry=0x5556bb7f5298 "/test/10.5_dbg/sql/sql_reload.cc", line=line@entry=222, function=function@entry=0x5556bb7f54c0 <reload_acl_and_cache(THD*, unsigned long long, TABLE_LIST*, int*)::__PRETTY_FUNCTION__> "bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*)") at assert.c:92
 
#7  0x00001480e01fa4a2 in __GI___assert_fail (assertion=assertion@entry=0x5556bb7f52c0 "!thd || thd->locked_tables_mode || !thd->mdl_context.has_locks() || thd->handler_tables_hash.records || thd->ull_hash.records || thd->global_read_lock.is_acquired() || thd->current_backup_stage != BAC"..., file=file@entry=0x5556bb7f5298 "/test/10.5_dbg/sql/sql_reload.cc", line=line@entry=222, function=function@entry=0x5556bb7f54c0 <reload_acl_and_cache(THD*, unsigned long long, TABLE_LIST*, int*)::__PRETTY_FUNCTION__> "bool reload_acl_and_cache(THD*, long long unsigned int, TABLE_LIST*, int*)") at assert.c:101
 
#8  0x00005556bacc695e in reload_acl_and_cache (thd=thd@entry=0x1480bdc15088, options=256, tables=tables@entry=0x0, write_to_binlog=write_to_binlog@entry=0x1480e1f72d70) at /test/10.5_dbg/sql/sql_reload.cc:216
 
#9  0x00005556bab3e3c2 in mysql_execute_command (thd=thd@entry=0x1480bdc15088) at /test/10.5_dbg/sql/sql_parse.cc:5424
 
#10 0x00005556bab47324 in mysql_parse (thd=thd@entry=0x1480bdc15088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1480e1f73350, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7994
 
#11 0x00005556bab33d54 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1480bdc15088, packet=packet@entry=0x1480bdc67089 "FLUSH LOCAL ERROR LOGS", packet_length=packet_length@entry=22, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1867
 
#12 0x00005556bab3253e in do_command (thd=0x1480bdc15088) at /test/10.5_dbg/sql/sql_parse.cc:1348
 
#13 0x00005556bac91893 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x1480c10d4808, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1410
 
#14 0x00005556bac91fb7 in handle_one_connection (arg=arg@entry=0x1480c10d4808) at /test/10.5_dbg/sql/sql_connect.cc:1312
 
#15 0x00005556bb0fc5c2 in pfs_spawn_thread (arg=0x1480dec46508) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#16 0x00001480e0eed6db in start_thread (arg=0x1480e1f74700) at pthread_create.c:463
 
#17 0x00001480e02eba3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.15 (dbg), 10.5.6 (dbg), 10.6.0 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.47 (dbg), 10.1.47 (opt), 10.2.34 (dbg), 10.2.34 (opt), 10.3.25 (dbg), 10.3.25 (opt), 10.4.15 (opt), 10.5.6 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.49 (dbg), 5.6.49 (opt), 5.7.31 (dbg), 5.7.31 (opt), 8.0.21 (dbg), 8.0.21 (opt)

Comment by Roel Van de Paar [ 2020-09-22 ]

vlad.lesin Hi! Would you mind having a look at this one please?

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

Also see MDEV-25589.

Comment by Nayuta Yanagisawa (Inactive) [ 2022-04-26 ]

This doesn't reproduce on 10.4 HEAD.

Comment by Elena Stepanova [ 2022-04-26 ]

The failure stopped happening after this commit:

commit 709ba7dcae871e365697f67677c908b55ad4a964
 
Author: Rinat Ibragimov
 
Date:   Wed Oct 21 23:34:36 2020 +0300
 
 
 
    MDEV-20945: BACKUP UNLOCK + FTWRL assertion failure

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