[MDEV-29894] Calling a function from a different database in a slave side trigger crashes Created: 2022-10-27  Updated: 2023-10-04  Resolved: 2023-06-21

Status: Closed
Project: MariaDB Server
Component/s: Replication, Stored routines, Triggers
Affects Version/s: 10.10.1, 10.6.10, 10.7.6, 10.8.5, 10.9.3, 10.6, 10.7, 10.8, 10.9
Fix Version/s: 10.6.15, 10.9.8, 10.10.6, 10.11.5, 11.0.3, 11.1.2

Type: Bug Priority: Critical
Reporter: Hartmut Holzgraefe Assignee: Brandon Nesterenko
Resolution: Fixed Votes: 4
Labels: None

Attachments: HTML File gdb-bt-all     HTML File gdb-bt-all-full    
Issue Links:
Duplicate
is duplicated by MDEV-29939 free(): invalid pointer st_mysql_lex_... Closed
Relates

 Description   

Using slave_run_triggers_for_rbr=ON and row based replication a slave side trigger on a table that itself calls a function from a different database than the one the table with the trigger is in makes the slave server crash.

How to reproduce:

  • on the master have binlog-format=ROW
  • on the slave have slave_run_triggers_for_rbr=1
  • set up replication between master and slave
  • on the master create a table without trigger, e.g. 

    USE db1;
    		 
     
    		 
    CREATE TABLE IF NOT EXISTS `t1` (
    		 
    `i` int(11) NOT NULL,
    		 
    PRIMARY KEY (`i`)
    		 
    );

  • on the slave create a function in a different database, e.g db2 instead of db1

USE db2;
 
  
DELIMITER //
 
 
 
CREATE FUNCTION `get_value`(`id` INT) RETURNS int(2)
 
BEGIN
 
  RETURN 0;
 
END//
 
 
 
DELIMITER ;

  • on the slave create a trigger on the table originally created on the master, calling the function in the other database:

USE db1;
 
 
 
DELIMITER //
 
 
 
CREATE TRIGGER `tr_s1` BEFORE INSERT ON `t1` FOR EACH ROW BEGIN
 
DECLARE id INT;
 
SET id = `db2`.get_value(1);
 
END//
 
 
 
DELIMITER ;

  • now back on the master insert a row into the test table:

USE db1;
 
 
 
INSERT INTO `t1` (`i`) VALUES (4);

This did not cause problems up to MariaDB 10.4, but starting with 10.5 up to 10.10 it crashes the server, and as it tries to replicate the same event again and again after crash recovery as first thing when replication restarts it puts the slave into a crashing loop.

Error log output from syslog:

Oct 27 08:25:54 slave-1 mariadbd[1765]: free(): invalid pointer
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: 221027  8:25:54 [ERROR] mysqld got signal 6 ;
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: This could be because you hit a bug. It is also possible that this binary
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: or one of the libraries it was linked against is corrupt, improperly built,
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: We will try our best to scrape up some info that will hopefully help
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: diagnose the problem, but since we have already crashed,
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: something is definitely wrong and this may fail.
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Server version: 10.10.1-MariaDB-1:10.10.1+maria~ubu2204
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: key_buffer_size=134217728
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: read_buffer_size=131072
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: max_used_connections=2
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: max_threads=153
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: thread_count=4
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: It is possible that mysqld could use up to
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 468010 K  bytes of memory
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Hope that's ok; if not, decrease some variables in the equation.
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Thread pointer: 0x7f89b80015a8
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Attempting backtrace. You can use the following information to find out
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: where mysqld died. If you see no messages after this, something went
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: terribly wrong...
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: stack_bottom = 0x7f8a000924e0 thread_stack 0x49000
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(my_print_stacktrace)[0x563bad89a3a2]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(handle_fatal_signal)[0x563bad36d1e8]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(__sigaction)[0x7f8a19377520]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(pthread_kill)[0x7f8a193cba7c]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(raise)[0x7f8a19377476]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(abort)[0x7f8a1935d7f3]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(__fsetlocking)[0x7f8a193be6f6]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(timer_settime)[0x7f8a193d5d7c]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(__default_morecore)[0x7f8a193d7ac4]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(free)[0x7f8a193da4d3]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(THD::set_db(st_mysql_const_lex_string const*))[0x563bad0b89fe]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(mysql_change_db(THD*, st_mysql_const_lex_string const*, bool))[0x563bad0c86e8]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(mysql_opt_change_db(THD*, st_mysql_const_lex_string const*, st_mysql_lex_string*, bool, bool*))[0x563bad0c8a10]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(sp_head::execute(THD*, bool))[0x563bad0644c6]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(sp_head::execute_function(THD*, Item**, unsigned int, Field*, sp_rcontext**, Query_arena*))[0x563bad067153]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Item_sp::execute_impl(THD*, Item**, unsigned int))[0x563bad38f74f]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Item_sp::execute(THD*, bool*, Item**, unsigned int))[0x563bad38f8e3]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Item_func_sp::val_int())[0x563bad3fa4d5]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Item::save_int_in_field(Field*, bool))[0x563bad3950e3]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Item::save_in_field(Field*, bool))[0x563bad384987]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Field::sp_prepare_and_store_item(THD*, Item**))[0x563bad34a4f3]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(THD::sp_eval_expr(Field*, Item**))[0x563bad062fbc]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(sp_rcontext::set_variable(THD*, unsigned int, Item**))[0x563bad071948]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(sp_instr_set::exec_core(THD*, unsigned int*))[0x563bad06b65f]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*))[0x563bad06a8a4]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(sp_head::execute(THD*, bool))[0x563bad064c1a]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(sp_head::execute_trigger(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, st_grant_info*))[0x563bad065ccd]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Table_triggers_list::process_triggers(THD*, trg_event_type, trg_action_time_type, bool))[0x563bad1dce74]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Rows_log_event::write_row(rpl_group_info*, bool))[0x563bad4b1e01]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Write_rows_log_event::do_exec_row(rpl_group_info*))[0x563bad4b23c4]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Rows_log_event::do_apply_event(rpl_group_info*))[0x563bad4a585c]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(Log_event::apply_event(rpl_group_info*))[0x563bad49db01]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(apply_event_and_update_pos(Log_event*, THD*, rpl_group_info*))[0x563bad057bfb]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(handle_slave_sql)[0x563bad0592b2]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(MyCTX_nopad::finish(unsigned char*, unsigned int*))[0x563bad599026]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(pthread_condattr_setpshared)[0x7f8a193c9b43]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: ??:0(__xmknodat)[0x7f8a1945ba00]
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Trying to get some variables.
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Some pointers may be invalid and cause the dump to abort.
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Query (0x0): (null)
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Connection ID (thread ID): 5
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Status: NOT_KILLED
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on,not_null_range_scan=off
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: information that should help you find out what is causing the crash.
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: We think the query pointer is invalid, but we will try to print it anyway.
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Query:
 
Oct 27 08:25:54 slave-1 mariadbd[1765]: Writing a core file...



 Comments   
Comment by Alice Sherepa [ 2022-10-27 ]

Thanks! I repeated as described on 10.6-10.10, 10.5 seems to be ok

--source include/have_binlog_format_row.inc
 
--source include/master-slave.inc
 
 
 
--connection slave
 
set global slave_run_triggers_for_rbr=1;
 
 
 
 
 
--connection master
 
CREATE TABLE t1 (i int);
 
--sync_slave_with_master
 
 
 
--connection slave
 
create database db2;
 
   
CREATE FUNCTION db2.get_value(id INT) RETURNS int(2)  RETURN 0;
 
 
DELIMITER //;
 
 
CREATE TRIGGER tr_s1 BEFORE INSERT ON t1 FOR EACH ROW BEGIN
 
DECLARE id INT;
 
SET id = db2.get_value(1);
 
END//
 
 
DELIMITER ;//
 
 
 
--connection master
 
 
 
INSERT INTO t1 (i) VALUES (4);
 
--sync_slave_with_master

10.6 18a0f0c17839e3662ac8 - debug+asan

 
Error: Freeing unallocated data or underrun buffer 0x61b000050ea8 at mysys/safemalloc.c:341, mysys/safemalloc.c:200, mysys/my_malloc.c:212, sql/sql_class.cc:1497, sql/sql_db.cc:1587, sql/sql_db.cc:1854, sql/sql_db.cc:1893, sql/sp_head.cc:1271

non-debug 10.6 18a0f0c17839e3662ac8:

free(): invalid pointer
 
221027 17:35:58 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.6.11-MariaDB-log
 
 
 
??:0(abort)[0x7f116ab2f859]
 
??:0(__fsetlocking)[0x7f116ab9a26e]
 
??:0(pthread_attr_setschedparam)[0x7f116aba3b2c]
 
sql/sql_class.cc:1497(THD::set_db(st_mysql_const_lex_string const*))[0x557e906ef99e]
 
sql/sql_db.cc:1587(mysql_change_db(THD*, st_mysql_const_lex_string const*, bool))[0x557e906ffbf7]
 
sql/sql_db.cc:1893(mysql_opt_change_db(THD*, st_mysql_const_lex_string const*, st_mysql_lex_string*, bool, bool*))[0x557e906fff40]
 
sql/sp_head.cc:1270(sp_head::execute(THD*, bool))[0x557e9069991e]
 
sql/sp_head.cc:2169(sp_head::execute_function(THD*, Item**, unsigned int, Field*, sp_rcontext**, Query_arena*))[0x557e9069c2da]
 
sql/item.cc:2922(Item_sp::execute_impl(THD*, Item**, unsigned int))[0x557e909a027f]
 
sql/item.cc:2836(Item_sp::execute(THD*, bool*, Item**, unsigned int))[0x557e909a0413]
 
sql/item_func.h:3874(Item_func_sp::val_int())[0x557e90a0b095]
 
sql/item.cc:6810(Item::save_int_in_field(Field*, bool))[0x557e909a5c13]
 
sql/item.cc:6820(Item::save_in_field(Field*, bool))[0x557e90995a07]
 
sql/sql_class.h:4381(THD::is_error() const)[0x557e9095b268]
 
sql/sql_class.h:7797(Sp_eval_expr_state::stop())[0x557e9069842c]
 
sql/sp_rcontext.cc:640(sp_rcontext::set_variable(THD*, unsigned int, Item**))[0x557e906a6738]
 
sql/sp_head.cc:3813(sp_instr_set::exec_core(THD*, unsigned int*))[0x557e906a075f]
 
sql/sp_head.cc:3512(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*))[0x557e9069f9ca]
 
sql/sp_head.cc:1438(sp_head::execute(THD*, bool))[0x557e9069a099]
 
psi/mysql_sp.h:79(sp_head::execute_trigger(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, st_grant_info*))[0x557e9069b026]
 
sql/sql_trigger.cc:2491(Table_triggers_list::process_triggers(THD*, trg_event_type, trg_action_time_type, bool))[0x557e907fd954]
 
sql/log_event_server.cc:7316(Rows_log_event::write_row(rpl_group_info*, bool))[0x557e90aa7921]
 
sql/log_event_server.cc:7572(Write_rows_log_event::do_exec_row(rpl_group_info*))[0x557e90aa7ef1]
 
sql/log_event_server.cc:5739(Rows_log_event::do_apply_event(rpl_group_info*))[0x557e90a9bc7f]
 
sql/log_event.h:1500(Log_event::apply_event(rpl_group_info*))[0x557e9068572a]
 
sql/slave.cc:4366(handle_slave_sql)[0x557e9068eae2]
 
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x557e90bf00f6]
 
nptl/pthread_create.c:478(start_thread)[0x7f116b040609]
 
??:0(clone)[0x7f116ac2c133]
 
 
 
Query (0x7f112001b31b): INSERT INTO t1 (i) VALUES (4)

Comment by Claudio Nanni [ 2023-04-19 ]

Another case, Replica with slave_run_triggers_for_rbr=LOGGING and RBR.

The table in this case has a trigger that calls a SP in the same schema but the SP operates on tables on different schemas.

/usr/sbin/mariadbd(THD::set_db(st_mysql_const_lex_string
 
/usr/sbin/mariadbd(mysql_change_db(THD*,
 
/usr/sbin/mariadbd(mysql_opt_change_db(THD*,
 
/usr/sbin/mariadbd(sp_head::execute(THD*,
 
/usr/sbin/mariadbd(sp_head::execute_procedure(THD*,
 
/usr/sbin/mariadbd(+0x7cfb27)[0x55a77d2bfb27]
 
/usr/sbin/mariadbd(+0x7d3978)[0x55a77d2c3978]
 
/usr/sbin/mariadbd(mysql_execute_command(THD*,
 
/usr/sbin/mariadbd(sp_instr_stmt::exec_core(THD*,
 
/usr/sbin/mariadbd(sp_lex_keeper::reset_lex_and_exec_core(THD*,
 
/usr/sbin/mariadbd(sp_instr_stmt::execute(THD*,
 
/usr/sbin/mariadbd(sp_head::execute(THD*,
 
/usr/sbin/mariadbd(sp_head::execute_trigger(THD*,
 
/usr/sbin/mariadbd(Table_triggers_list::process_triggers(THD*,

Comment by Brandon Nesterenko [ 2023-05-31 ]

Hi Andrei!

This is ready for review: PR-2655.

Comment by Brandon Nesterenko [ 2023-06-19 ]

Review notes addressed in fe03316

Comment by Andrei Elkin [ 2023-06-21 ]

Looks really nice. Thanks for "decoration" efforts as well!

Comment by Brandon Nesterenko [ 2023-06-21 ]

Pushed in 10.6 as c2d44ec. Manually cherry-picking through 11.2 resulted in no merge conflicts.

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