[MDEV-20474] Assertion `!recv_no_log_write' failed in log_pad_current_log_block upon server startup on a clean datadir Created: 2019-09-03  Updated: 2021-09-01  Resolved: 2021-09-01

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.5.2, 10.6.0

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Won't Fix Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-18370 InnoDB: Failing assertion: lsn % OS_F... Closed
relates to MDEV-14425 Change the InnoDB redo log format to ... Closed
relates to MDEV-20475 Assertion `flushed_lsn == log_get_lsn... Closed

 Description   

10.2 9bf424bc

2019-09-02 23:38:20 140019074221888 [Note] InnoDB: Highest supported file format is Barracuda.
2019-09-02 23:38:21 140019074221888 [Note] InnoDB: Encrypting redo log: 1*524288000 bytes; LSN=1656361
mysqld: /data/src/10.2/storage/innobase/log/log0log.cc:2212: void log_pad_current_log_block(): Assertion `!recv_no_log_write' failed.
190902 23:38:24 [ERROR] mysqld got signal 6 ;
 
rogram terminated with signal SIGSEGV, Segmentation fault.
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x00007f58b935f42a in __GI_abort () at abort.c:89
#6  0x00007f58b9356e67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55d9e8904d94 "!recv_no_log_write", file=file@entry=0x55d9e89049b0 "/data/src/10.2/storage/innobase/log/log0log.cc", line=line@entry=2212, function=function@entry=0x55d9e8906780 <log_pad_current_log_block()::__PRETTY_FUNCTION__> "void log_pad_current_log_block()") at assert.c:92
#7  0x00007f58b9356f12 in __GI___assert_fail (assertion=0x55d9e8904d94 "!recv_no_log_write", file=0x55d9e89049b0 "/data/src/10.2/storage/innobase/log/log0log.cc", line=2212, function=0x55d9e8906780 <log_pad_current_log_block()::__PRETTY_FUNCTION__> "void log_pad_current_log_block()") at assert.c:101
#8  0x000055d9e8251b83 in log_pad_current_log_block () at /data/src/10.2/storage/innobase/log/log0log.cc:2212
#9  0x000055d9e8251cb5 in log_scrub () at /data/src/10.2/storage/innobase/log/log0log.cc:2254
#10 0x000055d9e8251d66 in log_scrub_thread () at /data/src/10.2/storage/innobase/log/log0log.cc:2281
#11 0x00007f58baecb4a4 in start_thread (arg=0x7f58a19cd700) at pthread_create.c:456
#12 0x00007f58b9413d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Reproducing doesn't require any inflow on the server. It happens randomly, quite rarely, upon server startup right after bootstrap, it's enough to run bootstrap-startup in a loop with given options for a long enough time (hours). I use this crude script for that, but it can really be anything, as long as the server started with the right options. Scrubbing is important, but also on some reason innodb_log_files_in_group (or possibly some other InnoDB log options) – maybe resizing redo log is essential for the scenario.

Unfortunately, I don't know how to make it any faster / more probable.

if [ -n "$1" ] ; then
    port=$1
else
    port=8307
fi
 
while [ true ] ; do
    rm -rf data data.bootstrap tmp
    mkdir data
    mkdir tmp
 
    echo `date` "Running bootstrap..."
    scripts/mysql_install_db --no-defaults --basedir=`pwd` --lc-messages-dir=`pwd`/share --character-sets-dir=`pwd`/share/charsets --tmpdir=`pwd`/tmp --datadir=`pwd`/data --innodb_log_files_in_group=1 > `pwd`/boot.log 2>&1
 
    cp -r data data.bootstrap
 
    echo `date` "Starting server on port $port..."
    `pwd`/bin/mysqld --no-defaults --basedir=`pwd` --lc-messages-dir=`pwd`/share --character-sets-dir=`pwd`/share/charsets --tmpdir=`pwd`/tmp --core-file --datadir=`pwd`/data --port=$port --socket=`pwd`/mysql.sock --pid-file=`pwd`/mysql.pid --innodb-encryption-threads=4 --loose-innodb_scrub_log=ON --log-error=`pwd`/mysql.err &
 
    res=1;
    echo `date` "Waiting for the server to start..."
    for i in 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 ; do
        sleep 1
        `pwd`/bin/mysqladmin -uroot --socket=`pwd`/mysql.sock ping 2>/dev/null
#        `pwd`/bin/mysqladmin --socket=`pwd`/mysql.sock ping 2>/dev/null
        if [ $? == 0 ] ; then
            echo "Success"
            res=0
            break
        fi
    done
    if [ $res == 1 ] ; then
        echo `date` "Failed to start the server"
        break
    fi
    echo `date` "Trying to shut down the server..."
    `pwd`/bin/mysql -uroot --socket=`pwd`/mysql.sock -e shutdown 2>/dev/null
#    `pwd`/bin/mysql --socket=`pwd`/mysql.sock -e shutdown 2>/dev/null
    if [ $? != 0 ] ; then
        echo `date` "Shut down failed on some reason"
        break
    else
        echo `date` "Success"
    fi
    fg
done

The problem happens interchangeably with MDEV-18370 and MDEV-20475, they're likely to be related.



 Comments   
Comment by Marko Mäkelä [ 2021-09-01 ]

Starting with MDEV-21870, the parameter innodb_scrub_log has no effect.

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