[MDEV-17977] FLUSH MASTER fails with ER_NO_UNIQUE_LOGFILE and causes subsequent assertion failure `Count >= rest_length' in _my_b_write Created: 2018-12-11  Updated: 2023-04-27

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

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

Issue Links:
Duplicate
is duplicated by MDEV-22451 SIGSEGV in __memmove_avx_unaligned_er... Closed
Relates
relates to MDEV-22451 SIGSEGV in __memmove_avx_unaligned_er... Closed
relates to MDEV-23045 Assertion `is_open()' failed in MYSQL... Stalled
relates to MDEV-30409 SIGSEGV in __memmove_avx_unaligned_er... Open

 Description   

FLUSH MASTER syntax is documented as deprecated, but it still exists and causes the problems as below.

--source include/have_log_bin.inc
 
 
 
--error 0,ER_NO_UNIQUE_LOGFILE
 
FLUSH MASTER;
 
CREATE DATABASE db;
 
 
 
# Cleanup
 
DROP DATABASE db;

The first statement fails with ER_NO_UNIQUE_LOGFILE:

10.1 ecd3a7e00de debug

 
query 'FLUSH MASTER' failed: 1098: Can't generate a unique log-filename master-bin.(1-999)

The second statement causes the assertion failure:

10.1 ecd3a7e00de debug

 
2018-12-11 23:59:26 140476796680960 [ERROR] Log filename extension number exhausted: 11936128518282651044. Please fix this by archiving old logs and updating the index files.
 
2018-12-11 23:59:26 140476796680960 [ERROR] Can't generate a unique log-filename master-bin.(1-999)
 
 
 
2018-12-11 23:59:26 140476796680960 [ERROR] MYSQL_BIN_LOG::open failed to generate new file name.
 
mysqld: /data/src/10.1/mysys/mf_iocache.c:511: _my_b_write: Assertion `Count >= rest_length' failed.
 
181211 23:59:26 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fc34baebee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x00005555ec4c45bd in _my_b_write (info=0x5555ecf6a118 <mysql_bin_log+920>, Buffer=0x7fc34d9090f0 ">3\020\\\242\001", Count=19) at /data/src/10.1/mysys/mf_iocache.c:511
 
#9  0x00005555ec4c31f2 in my_b_write (info=0x5555ecf6a118 <mysql_bin_log+920>, Buffer=0x7fc34d9090f0 ">3\020\\\242\001", Count=19) at /data/src/10.1/include/my_sys.h:538
 
#10 0x00005555ec4c6483 in my_b_safe_write (info=0x5555ecf6a118 <mysql_bin_log+920>, Buffer=0x7fc34d9090f0 ">3\020\\\242\001", Count=19) at /data/src/10.1/mysys/mf_iocache.c:1745
 
#11 0x00005555ebf79e97 in Log_event_writer::write_internal (this=0x7fc34d9091e0, pos=0x7fc34d9090f0 ">3\020\\\242\001", len=19) at /data/src/10.1/sql/log_event.cc:1176
 
#12 0x00005555ebf7a0d1 in Log_event_writer::encrypt_and_write (this=0x7fc34d9091e0, pos=0x7fc34d9090f0 ">3\020\\\242\001", len=19) at /data/src/10.1/sql/log_event.cc:1219
 
#13 0x00005555ebf7a312 in Log_event_writer::write_header (this=0x7fc34d9091e0, pos=0x7fc34d9090f0 ">3\020\\\242\001", len=19) at /data/src/10.1/sql/log_event.cc:1262
 
#14 0x00005555ebf7a7b1 in Log_event::write_header (this=0x7fc34d9092c0, event_data_length=19) at /data/src/10.1/sql/log_event.cc:1355
 
#15 0x00005555ebf85698 in Gtid_log_event::write (this=0x7fc34d9092c0) at /data/src/10.1/sql/log_event.cc:6766
 
#16 0x00005555ebdfb765 in Log_event_writer::write (this=0x7fc34d9091e0, ev=0x7fc34d9092c0) at /data/src/10.1/sql/log_event.h:4941
 
#17 0x00005555ebf6619b in MYSQL_BIN_LOG::write_event (this=0x5555ecf69d80 <mysql_bin_log>, ev=0x7fc34d9092c0, file=0x5555ecf6a118 <mysql_bin_log+920>) at /data/src/10.1/sql/log.cc:5251
 
#18 0x00005555ebbad9b8 in MYSQL_BIN_LOG::write_event (this=0x5555ecf69d80 <mysql_bin_log>, ev=0x7fc34d9092c0) at /data/src/10.1/sql/log.h:750
 
#19 0x00005555ebf67f31 in MYSQL_BIN_LOG::write_gtid_event (this=0x5555ecf69d80 <mysql_bin_log>, thd=0x7fc3448da070, standalone=true, is_transactional=false, commit_id=0) at /data/src/10.1/sql/log.cc:5965
 
#20 0x00005555ebf68a4c in MYSQL_BIN_LOG::write (this=0x5555ecf69d80 <mysql_bin_log>, event_info=0x7fc34d9096b0, with_annotate=0x0) at /data/src/10.1/sql/log.cc:6271
 
#21 0x00005555ebc16006 in mysql_create_db_internal (thd=0x7fc3448da070, db=0x7fc343043128 "db", options=..., create_info=0x7fc34d909a30, silent=false) at /data/src/10.1/sql/sql_db.cc:704
 
#22 0x00005555ebc163ca in mysql_create_db (thd=0x7fc3448da070, db=0x7fc343043128 "db", options=..., create_info=0x7fc3448deb38) at /data/src/10.1/sql/sql_db.cc:783
 
#23 0x00005555ebc4a43c in mysql_execute_command (thd=0x7fc3448da070) at /data/src/10.1/sql/sql_parse.cc:4447
 
#24 0x00005555ebc535eb in mysql_parse (thd=0x7fc3448da070, rawbuf=0x7fc343043088 "CREATE DATABASE db", length=18, parser_state=0x7fc34d90a5e0) at /data/src/10.1/sql/sql_parse.cc:7467
 
#25 0x00005555ebc41e3c in dispatch_command (command=COM_QUERY, thd=0x7fc3448da070, packet=0x7fc346554071 "CREATE DATABASE db", packet_length=18) at /data/src/10.1/sql/sql_parse.cc:1495
 
#26 0x00005555ebc40bc1 in do_command (thd=0x7fc3448da070) at /data/src/10.1/sql/sql_parse.cc:1124
 
#27 0x00005555ebd7b720 in do_handle_one_connection (thd_arg=0x7fc3448da070) at /data/src/10.1/sql/sql_connect.cc:1330
 
#28 0x00005555ebd7b484 in handle_one_connection (arg=0x7fc3448da070) at /data/src/10.1/sql/sql_connect.cc:1242
 
#29 0x00005555ec1397c6 in pfs_spawn_thread (arg=0x7fc34b03a170) at /data/src/10.1/storage/perfschema/pfs.cc:1861
 
#30 0x00007fc34d5d4494 in start_thread (arg=0x7fc34d90bb00) at pthread_create.c:333
 
#31 0x00007fc34bba893f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Not reproducible on 10.0.
Not reproducible on a non-debug build (not even the SQL error).

Note: If the syntax has long been deprecated and no longer supported, maybe it should be removed in 10.4 until it's too late. I leave it to whoever works on it to decide whether to fix the failure in previous versions or not.

 Comments   
Comment by Alice Sherepa [ 2019-02-28 ]

Got the same assertion with DROP EVENT on 10.4

10.4 b10340998f33a0445

 
2019-02-28 17:03:01 6724 [ERROR] Could not use mysql-bin for logging (error 24). Turning logging off for the whole duration of the MariaDB server process. To turn it on again: fix the cause, shutdown the MariaDB server and restart it.
 
mysqld: /10.4/mysys/mf_iocache.c:588: _my_b_write: Assertion `Count >= rest_length' failed.
 
190228 17:03:01 [ERROR] mysqld got signal 6 ;
 
 
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fa53661702a]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x2dbd7)[0x7fa53660dbd7]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7fa53660dc82]
 
/10.4/sql/mysqld(_my_b_write+0x2b2)[0x55abfbb4bf16]
 
/10.4/sql/mysqld(+0x2975c1e)[0x55abfbb47c1e]
 
/10.4/sql/mysqld(my_b_safe_write+0x88)[0x55abfbb51080]
 
/10.4/sql/mysqld(_ZN16Log_event_writer14write_internalEPKhm+0x54)[0x55abfad9d736]
 
/10.4/sql/mysqld(_ZN16Log_event_writer17encrypt_and_writeEPKhm+0x33d)[0x55abfad9dc1f]
 
/10.4/sql/mysqld(_ZN16Log_event_writer12write_headerEPhm+0x742)[0x55abfad9e418]
 
/10.4/sql/mysqld(_ZN9Log_event12write_headerEm+0x7d3)[0x55abfad9f301]
 
/10.4/sql/mysqld(_ZN14Gtid_log_event5writeEv+0x2b3)[0x55abfadbead3]
 
/10.4/sql/mysqld(_ZN16Log_event_writer5writeEP9Log_event+0x99)[0x55abfa89588d]
 
/10.4/sql/mysqld(_ZN13MYSQL_BIN_LOG11write_eventEP9Log_eventP17binlog_cache_dataP11st_io_cache+0x25f)[0x55abfad6b3d7]
 
/10.4/sql/mysqld(_ZN13MYSQL_BIN_LOG11write_eventEP9Log_event+0x33)[0x55abfa14e1eb]
 
/10.4/sql/mysqld(_ZN13MYSQL_BIN_LOG16write_gtid_eventEP3THDbby+0x7c0)[0x55abfad6fb5e]
 
/10.4/sql/mysqld(_ZN13MYSQL_BIN_LOG5writeEP9Log_eventPc+0xc96)[0x55abfad71478]
 
/10.4/sql/mysqld(_ZN3THD12binlog_queryENS_22enum_binlog_query_typeEPKcmbbbi+0x849)[0x55abfa288ac5]
 
/10.4/sql/mysqld(_Z13write_bin_logP3THDbPKcmb+0xc5)[0x55abfa5622e1]
 
/10.4/sql/mysqld(_ZN6Events10drop_eventEP3THDPK25st_mysql_const_lex_stringS4_b+0x4bd)[0x55abfa677811]
 
/10.4/sql/mysqld(_ZN14Event_job_data7executeEP3THDb+0xdf5)[0x55abfa6736c9]
 
/10.4/sql/mysqld(_ZN19Event_worker_thread3runEP3THDP28Event_queue_element_for_exec+0x40b)[0x55abfaf2512d]
 
/10.4/sql/mysqld(event_worker_thread+0x12d)[0x55abfaf24cc6]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fa5374566ba]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fa5366e741d]
 
 
 
Query (0x6120004365b0): DROP EVENT `test`.`ev_5334_28`

with FLUSH LOGS:

10.3 e1e142e7fca77f24a26

 
2019-08-01 15:33:03 13069 [ERROR] MYSQL_BIN_LOG::open_purge_index_file failed to open register  file.
 
2019-08-01 15:33:03 13069 [ERROR] MYSQL_BIN_LOG::open_index_file failed to sync the index file.
 
2019-08-01 15:33:03 13069 [ERROR] Could not use ./mysql-bin.002226 for logging (error 24). Turning logging off for the 
mysqld: /10.3/mysys/mf_iocache.c:588: _my_b_write: Assertion `Count >= rest_length' failed.
 
 
 
Query (0x7fdbf7fc1978): FLUSH LOGS
 
 
 
Thread 1 (Thread 0x7fdc60ae6700 (LWP 6040)):
 
#3  <signal handler called>
 
#4  0x00007fdc64276428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
 
#5  0x00007fdc6427802a in __GI_abort () at abort.c:89
 
#6  0x00007fdc6426ebd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55a6308829e7 "Count >= rest_length", file=file@entry=0x55a6308827b8 "/10.3/mysys/mf_iocache.c", line=line@entry=588, function=function@entry=0x55a630882ee0 <__PRETTY_FUNCTION__.11941> "_my_b_write") at assert.c:92
 
#7  0x00007fdc6426ec82 in __GI___assert_fail (assertion=0x55a6308829e7 "Count >= rest_length", file=0x55a6308827b8 "/10.3/mysys/mf_iocache.c", line=588, function=0x55a630882ee0 <__PRETTY_FUNCTION__.11941> "_my_b_write") at assert.c:101
 
#8  0x000055a63043871c in _my_b_write (info=0x55a63114daf8 <mysql_bin_log+920>, Buffer=0x7fdc60ae3ed0 "\017\352B]\241\001", Count=19) at /10.3/mysys/mf_iocache.c:588
 
#9  0x000055a630436e6d in my_b_write (info=0x55a63114daf8 <mysql_bin_log+920>, Buffer=0x7fdc60ae3ed0 "\017\352B]\241\001", Count=19) at /10.3/include/my_sys.h:543
 
#10 0x000055a63043a7ef in my_b_safe_write (info=0x55a63114daf8 <mysql_bin_log+920>, Buffer=0x7fdc60ae3ed0 "\017\352B]\241\001", Count=19) at /10.3/mysys/mf_iocache.c:1844
 
#11 0x000055a62fd9143b in Log_event_writer::write_internal (this=0x7fdc60ae3fa0, pos=0x7fdc60ae3ed0 "\017\352B]\241\001", len=19) at /10.3/sql/log_event.cc:1601
 
#12 0x000055a62fd91685 in Log_event_writer::encrypt_and_write (this=0x7fdc60ae3fa0, pos=0x7fdc60ae3ed0 "\017\352B]\241\001", len=19) at /10.3/sql/log_event.cc:1644
 
#13 0x000055a62fd918dc in Log_event_writer::write_header (this=0x7fdc60ae3fa0, pos=0x7fdc60ae3ed0 "\017\352B]\241\001", len=19) at /10.3/sql/log_event.cc:1687
 
#14 0x000055a62fd91dd8 in Log_event::write_header (this=0x7fdc60ae4050, event_data_length=20) at /10.3/sql/log_event.cc:1780
 
#15 0x000055a62fd9db7d in Binlog_checkpoint_log_event::write (this=0x7fdc60ae4050) at /10.3/sql/log_event.cc:7873
 
#16 0x000055a62fb7bcd9 in Log_event_writer::write (this=0x7fdc60ae3fa0, ev=0x7fdc60ae4050) at /10.3/sql/log_event.h:5195
 
#17 0x000055a62fd7ab4e in MYSQL_BIN_LOG::write_event (this=0x55a63114d760 <mysql_bin_log>, ev=0x7fdc60ae4050, cache_data=0x0, file=0x55a63114daf8 <mysql_bin_log+920>) at /10.3/sql/log.cc:5315
 
#18 0x000055a62f87dfdb in MYSQL_BIN_LOG::write_event (this=0x55a63114d760 <mysql_bin_log>, ev=0x7fdc60ae4050) at /10.3/sql/log.h:814
 
#19 0x000055a62fd801e8 in MYSQL_BIN_LOG::write_binlog_checkpoint_event_already_locked (this=0x55a63114d760 <mysql_bin_log>, name_arg=0x7fdbf7fc6b08 "mysql-bin.002225h4z\025", '\217' <repeats 12 times>, "e ", len=16) at /10.3/sql/log.cc:7276
 
#20 0x000055a62fd86d58 in MYSQL_BIN_LOG::mark_xid_done (this=0x55a63114d760 <mysql_bin_log>, binlog_id=2224, write_checkpoint=true) at /10.3/sql/log.cc:9841
 
#21 0x000055a62fd7ea4a in MYSQL_BIN_LOG::do_checkpoint_request (this=0x55a63114d760 <mysql_bin_log>, binlog_id=2224) at /10.3/sql/log.cc:6662
 
#22 0x000055a62fd7edc3 in MYSQL_BIN_LOG::checkpoint_and_purge (this=0x55a63114d760 <mysql_bin_log>, binlog_id=2224) at /10.3/sql/log.cc:6780
 
#23 0x000055a62fd7f401 in MYSQL_BIN_LOG::rotate_and_purge (this=0x55a63114d760 <mysql_bin_log>, force_rotate=true, domain_drop_lex=0x0) at /10.3/sql/log.cc:6933
 
#24 0x000055a62fafafb9 in reload_acl_and_cache (thd=0x7fdbf332fc40, options=16130, tables=0x0, write_to_binlog=0x7fdc60ae4820) at /10.3/sql/sql_reload.cc:153
 
#25 0x000055a62f96556c in mysql_execute_command (thd=0x7fdbf332fc40) at /10.3/sql/sql_parse.cc:5360
 
#26 0x000055a62f88a762 in sp_instr_stmt::exec_core (this=0x7fdbf7fabf10, thd=0x7fdbf332fc40, nextp=0x7fdc60ae4e74) at /10.3/sql/sp_head.cc:3596
 
#27 0x000055a62f889bd5 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fdbf7fabf58, thd=0x7fdbf332fc40, nextp=0x7fdc60ae4e74, open_tables=false, instr=0x7fdbf7fabf10) at /10.3/sql/sp_head.cc:3324
 
#28 0x000055a62f88a342 in sp_instr_stmt::execute (this=0x7fdbf7fabf10, thd=0x7fdbf332fc40, nextp=0x7fdc60ae4e74) at /10.3/sql/sp_head.cc:3502
 
#29 0x000055a62f8840d8 in sp_head::execute (this=0x7fdbf7fab2c8, thd=0x7fdbf332fc40, merge_da_on_success=true) at /10.3/sql/sp_head.cc:1356
 
#30 0x000055a62f886a90 in sp_head::execute_procedure (this=0x7fdbf7fab2c8, thd=0x7fdbf332fc40, args=0x7fdc60ae5500) at /10.3/sql/sp_head.cc:2296
 
#31 0x000055a62fa9b167 in Event_job_data::execute (this=0x7fdc60ae5c70, thd=0x7fdbf332fc40, drop=false) at /10.3/sql/event_data_objects.cc:1443
 
#32 0x000055a62fe2b50e in Event_worker_thread::run (this=0x7fdc60ae5d7f, thd=0x7fdbf332fc40, event=0x7fdbf03cb8a0) at /10.3/sql/event_scheduler.cc:312
 
#33 0x000055a62fe2b2e4 in event_worker_thread (arg=0x7fdbf03cb8a0) at /10.3/sql/event_scheduler.cc:266
 
#34 0x00007fdc64eb36ba in start_thread (arg=0x7fdc60ae6700) at pthread_create.c:333
 
#35 0x00007fdc6434841d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

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