[MDEV-30176] Assertion `info->end_of_file - (info->append_read_pos-info->write_buffer) == (res= inline_mysql_file_tell(info->file, (myf) (0)))' failed in my_b_append_tell Created: 2022-12-08  Updated: 2024-01-23

Status: Confirmed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11
Fix Version/s: 10.4, 10.5, 10.6, 10.11

Type: Bug Priority: Major
Reporter: Ramesh Sivaraman Assignee: Brandon Nesterenko
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-33048 Assertion `info->end_of_file - (info-... Closed

 Description    

SET NAMES utf8,collation_connection=utf16le_general_ci;
 
SET default_master_connection='MASTER1';
 
CHANGE MASTER TO master_use_gtid=slave_pos;
 
SET default_master_connection='MASTER 2';
 
CHANGE MASTER TO master_use_gtid=current_pos;
 
FLUSH LOGS;
 
FLUSH LOGS;

Leads to:

10.11.2 922f7ba75c864a9ae4d0e55fa66860dae306136f (Debug)

 
mysqld: /test/10.11_dbg/mysys/mf_iocache2.c:115: my_b_append_tell: Assertion `info->end_of_file - (info->append_read_pos-info->write_buffer) == (res= inline_mysql_file_tell(info->file, (myf) (0)))' failed.

10.11.2 922f7ba75c864a9ae4d0e55fa66860dae306136f (Debug)

 
Core was generated by `/test/MD071222-mariadb-10.11.2-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x150a5c155700 (LWP 1600992))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x0000150a748df859 in __GI_abort () at abort.c:79
 
#2  0x0000150a748df729 in __assert_fail_base (fmt=0x150a74a75588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5556e43d2650 "info->end_of_file - (info->append_read_pos-info->write_buffer) == (res= inline_mysql_file_tell(info->file, (myf) (0)))", file=0x5556e43d25b8 "/test/10.11_dbg/mysys/mf_iocache2.c", line=115, function=<optimized out>) at assert.c:92
 
#3  0x0000150a748f0fd6 in __GI___assert_fail (assertion=assertion@entry=0x5556e43d2650 "info->end_of_file - (info->append_read_pos-info->write_buffer) == (res= inline_mysql_file_tell(info->file, (myf) (0)))", file=file@entry=0x5556e43d25b8 "/test/10.11_dbg/mysys/mf_iocache2.c", line=line@entry=115, function=function@entry=0x5556e43d2740 <__PRETTY_FUNCTION__.18127> "my_b_append_tell") at assert.c:101
 
#4  0x00005556e3f65219 in my_b_append_tell (info=0x150a24038738) at /test/10.11_dbg/mysys/mf_iocache2.c:115
 
#5  0x00005556e3f65242 in my_b_safe_tell (info=<optimized out>) at /test/10.11_dbg/mysys/mf_iocache2.c:128
 
#6  0x00005556e39d823b in Log_event_writer::pos (this=<optimized out>) at /test/10.11_dbg/sql/log_event.h:999
 
#7  Log_event::write_header (this=this@entry=0x150a5c1539b0, event_data_length=33) at /test/10.11_dbg/sql/log_event_server.cc:974
 
#8  0x00005556e39d9091 in Rotate_log_event::write (this=0x150a5c1539b0) at /test/10.11_dbg/sql/log_event_server.cc:3406
 
#9  0x00005556e39a9a60 in Log_event_writer::write (ev=0x150a5c1539b0, this=0x150a5c153900) at /test/10.11_dbg/sql/log_event.h:5831
 
#10 MYSQL_BIN_LOG::write_event (this=this@entry=0x150a24038398, ev=ev@entry=0x150a5c1539b0, cache_data=cache_data@entry=0x0, file=file@entry=0x150a24038738) at /test/10.11_dbg/sql/log.cc:5613
 
#11 0x00005556e39b9f73 in MYSQL_BIN_LOG::write_event (ev=0x150a5c1539b0, this=0x150a24038398) at /test/10.11_dbg/sql/log.h:833
 
#12 MYSQL_BIN_LOG::new_file_impl (this=this@entry=0x150a24038398) at /test/10.11_dbg/sql/log.cc:5485
 
#13 0x00005556e39ba71b in MYSQL_BIN_LOG::new_file (this=this@entry=0x150a24038398) at /test/10.11_dbg/sql/log.cc:5404
 
#14 0x00005556e34a5e80 in rotate_relay_log (mi=mi@entry=0x150a24035db0) at /test/10.11_dbg/sql/slave.cc:8191
 
#15 0x00005556e36cd598 in Master_info_index::flush_all_relay_logs (this=0x5556e6cf0dd0) at /test/10.11_dbg/sql/rpl_mi.cc:2059
 
#16 0x00005556e3703896 in reload_acl_and_cache (thd=thd@entry=0x150a24000d48, options=16130, tables=tables@entry=0x0, write_to_binlog=write_to_binlog@entry=0x150a5c153ed0) at /test/10.11_dbg/sql/sql_reload.cc:190
 
#17 0x00005556e357f317 in mysql_execute_command (thd=thd@entry=0x150a24000d48, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.11_dbg/sql/sql_parse.cc:5466
 
#18 0x00005556e35694aa in mysql_parse (thd=thd@entry=0x150a24000d48, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x150a5c154300) at /test/10.11_dbg/sql/sql_parse.cc:7998
 
#19 0x00005556e35769e9 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x150a24000d48, packet=packet@entry=0x150a2400adf9 "FLUSH LOGS", packet_length=packet_length@entry=10, blocking=blocking@entry=true) at /test/10.11_dbg/sql/sql_class.h:1346
 
#20 0x00005556e3578e22 in do_command (thd=0x150a24000d48, blocking=blocking@entry=true) at /test/10.11_dbg/sql/sql_parse.cc:1407
 
#21 0x00005556e36d365f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5556e6de56e8, put_in_cache=put_in_cache@entry=true) at /test/10.11_dbg/sql/sql_connect.cc:1415
 
#22 0x00005556e36d3b2e in handle_one_connection (arg=0x5556e6de56e8) at /test/10.11_dbg/sql/sql_connect.cc:1317
 
#23 0x0000150a74df0609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#24 0x0000150a749dc133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.28 (dbg), 10.5.19 (dbg), 10.6.12 (dbg), 10.7.8 (dbg), 10.8.7 (dbg), 10.9.5 (dbg), 10.10.3 (dbg), 10.11.2 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.3.38 (dbg), 10.3.38 (opt), 10.4.28 (opt), 10.5.19 (opt), 10.6.12 (opt), 10.7.8 (opt), 10.8.7 (opt), 10.9.5 (opt), 10.10.3 (opt), 10.11.2 (opt)

 Comments   
Comment by Andrei Elkin [ 2022-12-08 ]

bnestere, the problem description can be actually reduced to 

SET NAMES utf8,collation_connection=utf16le_general_ci;
 
SET default_master_connection='master1';
 
CHANGE MASTER TO master_use_gtid=slave_pos, master_host='master1-dummy-host'; # the last param is needed for sss
 
--error ERROR 1617 (HY000): There is no master connection 'master1'
 
show slave 'master1' status\G

That is SET NAMES does some weird things to the source name and its files (ls @@datadir/*slave*relay*).

I think we should limit the source name to the system charset.

Comment by Brandon Nesterenko [ 2024-01-16 ]

The problem is that string value set for default_master_connection ends up being translated into just "M" at parse time for both master connections, which causes the two master connections to invalidly use the same relay log file on disk.

Note that the parsing problem is fixed starting in 11.3; however, the underlying bug which allows different master connections to use the same name is still present, and should be fixed.

Comment by Roel Van de Paar [ 2024-01-16 ]

Additional t/c in MDEV-33048 to be checked upon fix (and preferably added to MTR).

Comment by Alexander Barkov [ 2024-01-17 ]

This shorter script also demonstrates the same problem:

SET NAMES utf8,collation_connection=utf16le_general_ci;
 
SET default_master_connection='MASTER1';
 
SHOW VARIABLES LIKE 'default_master_connection';


+---------------------------+----------------+
 
| Variable_name             | Value          |
 
+---------------------------+----------------+
 
| default_master_connection | M ???????????? |
 
+---------------------------+----------------+

Checking the 10.6 code revealed that the utf16 string gets directly assigned to the system variable, without conversion to utf8.

Note, in 11.4 the conversion to utf8 happens as expected, in Sys_var_charptr::do_string_check().

The patch which likely fixed the problem (in 11.3?) :

commit 6151bde48c8edac078300af0827c026b7b8d4894
 
Author: Yuchen Pei <ycp@mariadb.com>
 
Date:   Thu Sep 14 10:32:42 2023 +1000
 
 
 
    cleanup: string sys_var types

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