[MDEV-14472] Assertion `is_current_stmt_binlog_format_row()' failed in THD::binlog_write_table_map Created: 2017-11-22  Updated: 2023-12-05

Status: Stalled
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Andrei Elkin
Resolution: Unresolved Votes: 1
Labels: None

Issue Links:
Blocks
blocks MDEV-21307 Assertion `cache_mngr->trx_cache.empt... Stalled
Relates
relates to MDEV-21307 Assertion `cache_mngr->trx_cache.empt... Stalled
relates to MDEV-24534 Assertion `!is_current_stmt_binlog_fo... Open

 Description   

--source include/have_log_bin.inc
--source include/have_binlog_format_mixed.inc
 
# Reproducible with MyISAM, InnoDB, Aria
 
CREATE TABLE t1 (f1 INT);
CREATE TABLE t2 (f2 INT);
CREATE TABLE t3 (f3 INT);
CREATE TABLE t4 (pk INT AUTO_INCREMENT PRIMARY KEY);
 
CREATE TRIGGER tr1 BEFORE INSERT ON t1 FOR EACH ROW INSERT INTO t2 VALUES ();
CREATE TRIGGER tr2 AFTER INSERT ON t1 FOR EACH ROW INSERT INTO t3 VALUES ();
CREATE TRIGGER tr3 BEFORE INSERT ON t2 FOR EACH ROW INSERT INTO t4 VALUES ();
 
LOCK TABLE t1 WRITE;
INSERT INTO t2 () VALUES ();
INSERT INTO t3 VALUES ();
 
# Cleanup
 
UNLOCK TABLES;
DROP TABLE t1, t2, t3, t4;

10.2 0c4d11e8199f

mysqld: /data/src/10.2/sql/log.cc:5623: int THD::binlog_write_table_map(TABLE*, bool, my_bool*): Assertion `is_current_stmt_binlog_format_row()' failed.
171122 19:19:47 [ERROR] mysqld got signal 6 ;
 
#7  0x00007fe2c3215ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8  0x00005616a0bab007 in THD::binlog_write_table_map (this=0x7fe2a0000b00, table=0x7fe2a006b0c0, is_transactional=false, with_annotate=0x7fe2bd4a60f6 "\001") at /data/src/10.2/sql/log.cc:5623
#9  0x00005616a0aaf652 in write_locked_table_maps (thd=0x7fe2a0000b00) at /data/src/10.2/sql/handler.cc:5794
#10 0x00005616a0aaf71b in binlog_log_row_internal (table=0x7fe2a007cd30, before_record=0x0, after_record=0x7fe2a007e0b8 "\377", log_func=0x5616a0ab23aa <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, bool, unsigned char const*, unsigned char const*)>) at /data/src/10.2/sql/handler.cc:5825
#11 0x00005616a0aaf811 in binlog_log_row (table=0x7fe2a007cd30, before_record=0x0, after_record=0x7fe2a007e0b8 "\377", log_func=0x5616a0ab23aa <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, bool, unsigned char const*, unsigned char const*)>) at /data/src/10.2/sql/handler.cc:5857
#12 0x00005616a0ab0031 in handler::ha_write_row (this=0x7fe2a007d938, buf=0x7fe2a007e0b8 "\377") at /data/src/10.2/sql/handler.cc:6008
#13 0x00005616a080fad0 in write_record (thd=0x7fe2a0000b00, table=0x7fe2a007cd30, info=0x7fe2bd4a64a0) at /data/src/10.2/sql/sql_insert.cc:1929
#14 0x00005616a080d587 in mysql_insert (thd=0x7fe2a0000b00, table_list=0x7fe2a0012628, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /data/src/10.2/sql/sql_insert.cc:1057
#15 0x00005616a0834bc0 in mysql_execute_command (thd=0x7fe2a0000b00) at /data/src/10.2/sql/sql_parse.cc:4414
#16 0x00005616a083fabe in mysql_parse (thd=0x7fe2a0000b00, rawbuf=0x7fe2a0012548 "INSERT INTO t3 VALUES ()", length=24, parser_state=0x7fe2bd4a7200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7869
#17 0x00005616a082da4a in dispatch_command (command=COM_QUERY, thd=0x7fe2a0000b00, packet=0x7fe2a01057f1 "INSERT INTO t3 VALUES ()", packet_length=24, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1805
#18 0x00005616a082c3a8 in do_command (thd=0x7fe2a0000b00) at /data/src/10.2/sql/sql_parse.cc:1360
#19 0x00005616a097998d in do_handle_one_connection (connect=0x5616a4085390) at /data/src/10.2/sql/sql_connect.cc:1354
#20 0x00005616a097971a in handle_one_connection (arg=0x5616a4085390) at /data/src/10.2/sql/sql_connect.cc:1260
#21 0x00005616a0d96e1a in pfs_spawn_thread (arg=0x5616a4127080) at /data/src/10.2/storage/perfschema/pfs.cc:1863
#22 0x00007fe2c4eec494 in start_thread (arg=0x7fe2bd4a8700) at pthread_create.c:333
#23 0x00007fe2c32d293f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Also reproducible on 10.3.
Couldn't reproduce on 10.1, MySQL 5.6, 5.7.
No visible effect on non-debug builds.



 Comments   
Comment by Sachin Setiya (Inactive) [ 2018-05-03 ]

If we remove this insert "INSERT INTO t2 () VALUES ();" , then test case passes, This insert is doing something fishy

Comment by Sachin Setiya (Inactive) [ 2018-05-03 ]

This error is because we cache the result of check_table_binlog_row_based_internal(binlog_row) into check_table_binlog_row_based_result. In query

INSERT INTO t2 () VALUES ();

Seeing at binlog of this command

#Q> INSERT INTO t4 VALUES ()
#180503 17:45:59 server id 1  end_log_pos 1717 CRC32 0xc7ea5bed         Table_map: `test`.`t1` mapped to number 33 (has triggers)
# at 1717
#180503 17:45:59 server id 1  end_log_pos 1762 CRC32 0x0a2fe1c0         Table_map: `test`.`t2` mapped to number 34 (has triggers)
# at 1762
#180503 17:45:59 server id 1  end_log_pos 1807 CRC32 0xf9dfbd78         Table_map: `test`.`t3` mapped to number 35
# at 1807
#180503 17:45:59 server id 1  end_log_pos 1852 CRC32 0xd93af641         Table_map: `test`.`t4` mapped to number 36
# at 1852
# at 1890
#180503 17:45:59 server id 1  end_log_pos 1890 CRC32 0xc1319126         Write_rows: table id 36
#180503 17:45:59 server id 1  end_log_pos 1924 CRC32 0xf543e890         Write_rows: table id 34 flags: STMT_END_F

we lock all the 4 tables and set all table->file->check_table_binlog_row_based_result to true, (we do this because this is trigger stmt)
since we cache the result the next table query tries to write logs in row binlog format , while thd->current_stmt_binlog_format is still BINLOG_FORMAT_STMT
and hence we get the debug_assert.
In non debug build we are not seeing any erro because instead of stmt format it uses row binlog format

Comment by Sachin Setiya (Inactive) [ 2018-05-05 ]

http://lists.askmonty.org/pipermail/commits/2018-May/012479.html
http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-mdev-14472

Comment by Alice Sherepa [ 2021-02-19 ]

not reproducible with the test from the description on the current 10.2-10.5

Comment by Andrei Elkin [ 2022-09-09 ]

Needs understanding/fixing specifically an observed execution detail about the before trigger error loss.

Generated at Thu Feb 08 08:13:49 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.