[MDEV-22921] Assertion `binlog_checksum_options == value' failed in binlog_checksum_update, and [ERROR] Failed to open log (file '647', errno 2) Created: 2020-06-17  Updated: 2024-02-03

Status: Confirmed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3, 11.4
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Andrei Elkin
Resolution: Unresolved Votes: 0
Labels: affects-tests

Issue Links:
Relates

 Description   

# mysqld options required for replay: --log-bin 
RESET MASTER TO 0x7FFFFFFF;
SET @@GLOBAL.binlog_checksum=NONE;

Leads to:

10.5.4 4080e3acefd7e58d88c2f3539fb6a0fb359cf057

mysqld: /test/10.5_dbg/sql/log.cc:10744: void binlog_checksum_update(THD*, st_mysql_sys_var*, void*, const void*): Assertion `binlog_checksum_options == value' failed.

10.5.4 6877ef9a7c9c7ee55d67e4baaf4e8f7b874c9f89

Core was generated by `/test/MD060620-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld --no-defaults --max_a'.
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 0x146d204c5700 (LWP 2297775))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x00005571a29ff00d in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x00005571a21a8bbc 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  0x0000146d24939801 in __GI_abort () at abort.c:79
#6  0x0000146d2492939a in __assert_fail_base (
    fmt=0x146d24ab07d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x5571a2d3ba28 "binlog_checksum_options == value", 
    file=file@entry=0x5571a2d37a07 "/test/10.5_dbg/sql/log.cc", line=line@entry=10741, 
    function=function@entry=0x5571a2d3c600 <binlog_checksum_update(THD*, st_mysql_sys_var*, void*, void const*)::__PRETTY_FUNCTION__> "void binlog_checksum_update(THD*, st_mysql_sys_var*, void*, const void*)") at assert.c:92
#7  0x0000146d24929412 in __GI___assert_fail (
    assertion=assertion@entry=0x5571a2d3ba28 "binlog_checksum_options == value", 
    file=file@entry=0x5571a2d37a07 "/test/10.5_dbg/sql/log.cc", line=line@entry=10741, 
    function=function@entry=0x5571a2d3c600 <binlog_checksum_update(THD*, st_mysql_sys_var*, void*, void const*)::__PRETTY_FUNCTION__> "void binlog_checksum_update(THD*, st_mysql_sys_var*, void*, const void*)") at assert.c:101
#8  0x00005571a22ebde1 in binlog_checksum_update (thd=<optimized out>, var=<optimized out>, 
    var_ptr=<optimized out>, save=<optimized out>) at /test/10.5_dbg/sql/log.cc:10741
#9  0x00005571a1f17d2d in sys_var_pluginvar::global_update (this=0x5571a515d160, thd=
    0x146cdc000d78, var=0x146cdc952ce8) at /test/10.5_dbg/sql/sql_plugin.cc:3584
#10 0x00005571a1e16a26 in sys_var::update (this=0x5571a515d160, thd=0x146cdc000d78, 
    var=0x146cdc952ce8) at /test/10.5_dbg/sql/set_var.cc:207
#11 0x00005571a1e16f4f in set_var::update (this=<optimized out>, thd=<optimized out>)
    at /test/10.5_dbg/sql/set_var.cc:859
#12 0x00005571a1e18302 in sql_set_variables (thd=thd@entry=0x146cdc000d78, 
    var_list=var_list@entry=0x146cdc005ca8, free=free@entry=true)
    at /test/10.5_dbg/sql/set_var.cc:746
#13 0x00005571a1f01357 in mysql_execute_command (thd=thd@entry=0x146cdc000d78)
    at /test/10.5_dbg/sql/sql_parse.cc:5014
#14 0x00005571a1f0b322 in mysql_parse (thd=thd@entry=0x146cdc000d78, rawbuf=<optimized out>, 
    length=<optimized out>, parser_state=parser_state@entry=0x146d204c4390, 
    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:7992
#15 0x00005571a1ef7e1c in dispatch_command (command=command@entry=COM_QUERY, 
    thd=thd@entry=0x146cdc000d78, 
    packet=packet@entry=0x146cdc9113e9 "set @@global.binlog_checksum = NONE;", 
    packet_length=packet_length@entry=36, 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:1874
#16 0x00005571a1ef65f6 in do_command (thd=0x146cdc000d78) at /test/10.5_dbg/sql/sql_parse.cc:1355
#17 0x00005571a20519f9 in do_handle_one_connection (connect=<optimized out>, 
    connect@entry=0x5571a5d06a28, put_in_cache=put_in_cache@entry=true)
    at /test/10.5_dbg/sql/sql_connect.cc:1411
#18 0x00005571a2052115 in handle_one_connection (arg=arg@entry=0x5571a5d06a28)
    at /test/10.5_dbg/sql/sql_connect.cc:1313
#19 0x00005571a24b1104 in pfs_spawn_thread (arg=0x5571a5c62008)
    at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#20 0x0000146d2561c6db in start_thread (arg=0x146d204c5700) at pthread_create.c:463
#21 0x0000146d24a1a88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.46 (dbg), 10.2.33 (dbg), 10.3.24 (dbg), 10.4.14 (dbg), 10.5.4 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.46 (opt), 10.2.33 (opt), 10.3.24 (opt), 10.4.14 (opt), 10.5.4 (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)

MariaDB 10.5.4 optimized:

10.5.4 4080e3acefd7e58d88c2f3539fb6a0fb359cf057

10.5.4>SET @@GLOBAL.binlog_checksum=NONE;
ERROR 1098 (HY000): Can't generate a unique log-filename qa-roel-2-bin.(1-999)



 Comments   
Comment by Roel Van de Paar [ 2020-07-27 ]

Slightly different stack with this testcase

# mysqld options required for replay: --log-bin
SET GLOBAL binlog_checksum=NONE;
RESET MASTER TO 0x7FFFFFFF;
SET GLOBAL binlog_checksum=DEFAULT;

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

This issue affect tests as it results in trials being stopped short.

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

There is another closely related bug. Observed in 11.4 and 11.3 (in both opt+dbg), likely present in other versions also.

# Requires standard master/slave replication setup
RESET MASTER TO 0x7FFFFFFF;

Leads to (on master):

11.4.0 8bf9f21855606ddeb0fe90fb1e70165adbec6746 (Optimized, Master)

2024-01-22 14:01:15 7 [Warning] Next log extension: 2147483647. Remaining log filename extensions: 0. Please consider archiving some logs.
2024-01-22 14:01:15 6 [ERROR] Failed to open log (file '647', errno 2)

And on the slave:

11.4.0 8bf9f21855606ddeb0fe90fb1e70165adbec6746 (Optimized, Slave)

2024-01-22 14:01:15 5 [ERROR] Error reading packet from server: File '647' not found (Errcode: 2 "No such file or directory") (server_errno=29)
2024-01-22 14:01:15 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log '647' at position 4; GTID position '0-1-3'

The 647 is the end of 0x7FFFFFFF in 10-base.

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