rocksdb is not crash safe with binlog on

I've reproduced this on 10.3.13/14 and 10.2.21

I've manually compiled the binaries in Amazon Linux 2 and installed 10.3.14 from mariadb yum repositories.

Repro steps:
Create a mysql and install rocks db.

I've attached my.cnf and the sysbench commands run.

Start the server with the my.cnf. When the server is up and running, run the prepare sysbench command.

Once it completes, use the run command. In the middle of the load, issue a "kill -9 `pidof mysqld`"

It is worth mentioning that I was only able to make crash with the oltp "run" phase, when it was on "prepare" phase it was not happening.

The server will never recover from this. I've been able to capture at least 2 different traces.

RedHat stack (sadly, no debug symbols)

Program received signal SIGABRT, Aborted.
0x00007f5b6bccb207 in raise () from /lib64/libc.so.6
(gdb) bt
#0 0x00007f5b6bccb207 in raise () from /lib64/libc.so.6
#1 0x00007f5b6bccc8f8 in abort () from /lib64/libc.so.6
#2 0x00007f5b6bcc4026 in __assert_fail_base () from /lib64/libc.so.6
#3 0x00007f5b6bcc40d2 in __assert_fail () from /lib64/libc.so.6
#4 0x00007f5b62f6a939 in rocksdb::ColumnFamilySet::~ColumnFamilySet() () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#5 0x00007f5b62e47b7c in rocksdb::VersionSet::~VersionSet() () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#6 0x00007f5b62dabb2c in rocksdb::DBImpl::CloseHelper() () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#7 0x00007f5b62dba4c5 in rocksdb::DBImpl::~DBImpl() () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#8 0x00007f5b62dba6b1 in rocksdb::DBImpl::~DBImpl() () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#9 0x00007f5b62f2da70 in rocksdb::PessimisticTransactionDB::~PessimisticTransactionDB() () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#10 0x00007f5b62f32c6f in rocksdb::WriteCommittedTxnDB::~WriteCommittedTxnDB() () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#11 0x00007f5b62f2edb1 in rocksdb::TransactionDB::WrapDB(rocksdb::DB*, rocksdb::TransactionDBOptions const&, std::vector<unsigned long, std::allocator<unsigned long> > const&, std::vector<rocksdb::ColumnFamilyHandle*, std::allocator<rocksdb::ColumnFamilyHandle*> > const&, rocksdb::TransactionDB**) () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#12 0x00007f5b62f2fbef in rocksdb::TransactionDB::Open(rocksdb::DBOptions const&, rocksdb::TransactionDBOptions const&, std::string const&, std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFamilyDescriptor> > const&, std::vector<rocksdb::ColumnFamilyHandle*, std::allocator<rocksdb::ColumnFamilyHandle*> >, rocksdb::TransactionDB*) ()
from /usr/lib64/mysql/plugin/ha_rocksdb.so
#13 0x00007f5b62d51fc8 in myrocks::rocksdb_init_func(void*) () from /usr/lib64/mysql/plugin/ha_rocksdb.so
#14 0x00005583611483c4 in ha_initialize_handlerton(st_plugin_int*) ()
#15 0x0000558360f7b1e0 in plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) ()
#16 0x0000558360f7c35a in plugin_init(int*, char**, int) ()
#17 0x0000558360ead051 in init_server_components() ()
#18 0x0000558360eb330e in mysqld_main(int, char**) ()
#19 0x00007f5b6bcb73d5 in __libc_start_main () from /lib64/libc.so.6
#20 0x0000558360ea6aed in _start ()

Amazon linux 2 stack A (same as Redhat):

(gdb) bt
#0 0x00007f6323eae760 in raise () from /lib64/libc.so.6
#1 0x00007f6323eafd41 in abort () from /lib64/libc.so.6
#2 0x00007f6323ea707a in __assert_fail_base () from /lib64/libc.so.6
#3 0x00007f6323ea70f2 in __assert_fail () from /lib64/libc.so.6
#4 0x00007f6321ca61ee in rocksdb::ColumnFamilySet::~ColumnFamilySet (this=0x55737a1f5490, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/db/column_family.cc:1238
#5 0x00007f6321b4f1ac in std::default_delete<rocksdb::ColumnFamilySet>::operator() (this=<optimized out>, __ptr=0x55737a1f5490) at /usr/include/c++/7/bits/unique_ptr.h:78
#6 std::unique_ptr<rocksdb::ColumnFamilySet, std::default_delete<rocksdb::ColumnFamilySet> >::reset (__p=0x55737a1f5490, this=0x55737a4cd2b0) at /usr/include/c++/7/bits/unique_ptr.h:376
#7 rocksdb::VersionSet::~VersionSet (this=0x55737a4cd2b0, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/db/version_set.cc:2694
#8 0x00007f6321a88abc in std::default_delete<rocksdb::VersionSet>::operator() (this=<optimized out>, __ptr=0x55737a4cd2b0) at /usr/include/c++/7/bits/unique_ptr.h:78
#9 std::unique_ptr<rocksdb::VersionSet, std::default_delete<rocksdb::VersionSet> >::reset (__p=0x55737a4cd2b0, this=<optimized out>) at /usr/include/c++/7/bits/unique_ptr.h:376
#10 rocksdb::DBImpl::CloseHelper (this=this@entry=0x55737a4d1c00) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/db/db_impl.cc:435
#11 0x00007f6321a96e23 in rocksdb::DBImpl::~DBImpl (this=0x55737a4d1c00, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/db/db_impl.cc:458
#12 0x00007f6321a96ee1 in rocksdb::DBImpl::~DBImpl (this=0x55737a4d1c00, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/db/db_impl.cc:460
#13 0x00007f6321c5e3f3 in rocksdb::StackableDB::~StackableDB (this=0x55737a5d6bf0, __in_chrg=<optimized out>)
at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/include/rocksdb/utilities/stackable_db.h:31
#14 rocksdb::TransactionDB::~TransactionDB (this=0x55737a5d6bf0, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/include/rocksdb/utilities/transaction_db.h:233
#15 rocksdb::PessimisticTransactionDB::~PessimisticTransactionDB (this=0x55737a5d6bf0, __in_chrg=<optimized out>)
at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/utilities/transactions/pessimistic_transaction_db.cc:78
#16 0x00007f6321c6442f in rocksdb::WriteCommittedTxnDB::~WriteCommittedTxnDB (this=0x55737a5d6bf0, __in_chrg=<optimized out>)
at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/utilities/transactions/pessimistic_transaction_db.h:180
#17 rocksdb::WriteCommittedTxnDB::~WriteCommittedTxnDB (this=0x55737a5d6bf0, __in_chrg=<optimized out>)
at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/utilities/transactions/pessimistic_transaction_db.h:180
#18 0x00007f6321c5efa1 in std::default_delete<rocksdb::PessimisticTransactionDB>::operator() (this=<optimized out>, __ptr=0x55737a5d6bf0) at /usr/include/c++/7/bits/unique_ptr.h:78
#19 std::unique_ptr<rocksdb::PessimisticTransactionDB, std::default_delete<rocksdb::PessimisticTransactionDB> >::~unique_ptr (this=<synthetic pointer>, __in_chrg=<optimized out>)
at /usr/include/c++/7/bits/unique_ptr.h:268
#20 rocksdb::TransactionDB::WrapDB (db=<optimized out>, txn_db_options=..., compaction_enabled_cf_indices=std::vector of length 0, capacity 0, handles=std::vector of length 2, capacity 2 =

{...},
dbptr=dbptr@entry=0x7f632201d2a0 <myrocks::rdb>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/utilities/transactions/pessimistic_transaction_db.cc:272
#21 0x00007f6321c60b3b in rocksdb::TransactionDB::Open (db_options=..., txn_db_options=..., dbname="./#rocksdb", column_families=std::vector of length 2, capacity 2 = {...}

,
handles=handles@entry=0x7ffd345b09c0, dbptr=0x7f632201d2a0 <myrocks::rdb>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/utilities/transactions/pessimistic_transaction_db.cc:231
#22 0x00007f6321a2720e in myrocks::rocksdb_init_func (p=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/ha_rocksdb.cc:5130
#23 0x00005573773c6f02 in ha_initialize_handlerton (plugin=0x55737a22f738) at /home/ec2-user/mariadb-10.3.13/sql/handler.cc:523
#24 0x00005573771fd529 in plugin_initialize (tmp_root=tmp_root@entry=0x7ffd345b16c0, plugin=plugin@entry=0x55737a22f738, argc=argc@entry=0x5573782f9848 <remaining_argc>,
argv=argv@entry=0x55737a1a5428, options_only=options_only@entry=false) at /home/ec2-user/mariadb-10.3.13/sql/sql_plugin.cc:1432
#25 0x00005573771fe68a in plugin_init (argc=argc@entry=0x5573782f9848 <remaining_argc>, argv=0x55737a1a5428, flags=2) at /home/ec2-user/mariadb-10.3.13/sql/sql_plugin.cc:1714
#26 0x0000557377134361 in init_server_components () at /home/ec2-user/mariadb-10.3.13/sql/mysqld.cc:5385
#27 0x000055737713a5aa in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /home/ec2-user/mariadb-10.3.13/sql/mysqld.cc:5998
#28 0x00007f6323e9b02a in __libc_start_main () from /lib64/libc.so.6
#29 0x000055737712d67a in _start ()

Here seems to be failing in:

1232 ColumnFamilySet::~ColumnFamilySet() {
1233 while (column_family_data_.size() > 0)

{ 1234 // cfd destructor will delete itself from column_family_data_ 1235 auto cfd = column_family_data_.begin()->second; 1236 bool last_ref __attribute__((__unused__)); 1237 last_ref = cfd->Unref(); 1238 assert(last_ref); 1239 delete cfd; 1240 }

Here looks like the ColumnFamilySet is not properly built and when the destructor is invoked we are getting a null/0

Amazon Linux stack B (different):

Thread 1 (Thread 0x2b1f006298c0 (LWP 18771)):
#0 0x00002b1f01a245f7 in raise () from /lib64/libc.so.6
#1 0x00002b1f01a25ce8 in abort () from /lib64/libc.so.6
#2 0x00002b1f04586bf9 in rocksdb::port::PthreadCall (label=label@entry=0x2b1f04a2bebc "lock", result=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/port/port_posix.cc:33
#3 0x00002b1f048d4d85 in PthreadCall (result=<optimized out>, label=0x2b1f04a2bebc "lock") at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/port/port_posix.cc:65
#4 rocksdb::port::Mutex::Lock (this=this@entry=0x2b1f0248c6d0) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/port/port_posix.cc:61
#5 0x00002b1f0487df8b in MutexLock (mu=0x2b1f0248c6d0, this=<synthetic pointer>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/util/mutexlock.h:32
#6 rocksdb::GenericRateLimiter::~GenericRateLimiter (this=0x2b1f0248c6c0, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/util/rate_limiter.cc:77
#7 0x00002b1f0487e189 in rocksdb::GenericRateLimiter::~GenericRateLimiter (this=0x2b1f0248c6c0, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/util/rate_limiter.cc:90
#8 0x00002b1f04703e20 in operator() (this=<optimized out>, __ptr=<optimized out>) at /local/p4clients/pkgbuild/GCC/GCC-7.x.200464.0/AL2012/DEV.STD.PTHREAD/build/gcc-7.3.0/include/c++/7.3.0/bits/unique_ptr.h:78
#9 ~unique_ptr (this=0x2b1f050db6c8, __in_chrg=<optimized out>) at /local/p4clients/pkgbuilds/GCC/GCC-7.x.200464.0/AL2012/DEV.STD.PTHREAD/build/gcc-7.3.0/include/c++/7.3.0/bits/unique_ptr.h:268
#10 rocksdb::DBImpl::~DBImpl (this=0x2b1f050dae00, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/db/db_impl.cc:455
#11 0x00002b1f047041e9 in rocksdb::DBImpl::~DBImpl (this=0x2b1f050dae00, __in_chrg=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/db/db_impl.cc:460
#12 0x00002b1f048a93b8 in rocksdb::TransactionDB::Open (db_options=..., txn_db_options=..., dbname=..., column_families=..., handles=handles@entry=0x7ffd071b37f0, dbptr=0x2b1f04cf9420 <myrocks::rdb>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/rocksdb/utilities/transactions/pessimistic_transaction_db.cc:236
#13 0x00002b1f0469824d in myrocks::rocksdb_init_func (p=<optimized out>) at /home/ec2-user/mariadb-10.3.13/storage/rocksdb/ha_rocksdb.cc:5130
#14 0x000055c7e3e464f7 in ha_initialize_handlerton (plugin=0x2b1f0431d0b8) at /home/ec2-user/mariadb-10.3.13/sql/handler.cc:523
#15 0x000055c7e3c87beb in plugin_initialize (tmp_root=tmp_root@entry=0x7ffd071b44f0, plugin=plugin@entry=0x2b1f0431d0b8, argc=argc@entry=0x55c7e5008248 <remaining_argc>, argv=argv@entry=0x2b1f0244d868, options_only=options_only@entry=false) at /home/ec2-user/mariadb-10.3.13/sql/sql_plugin.cc:1432
#16 0x000055c7e3c88d3a in plugin_init (argc=argc@entry=0x55c7e5008248 <remaining_argc>, argv=0x2b1f0244d868, flags=2) at /home/ec2-user/mariadb-10.3.13/sql/sql_plugin.cc:1714
#17 0x000055c7e3bc4081 in init_server_components () at /home/ec2-user/mariadb-10.3.13/sql/mysqld.cc:5385
#18 0x000055c7e3bca0e6 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /home/ec2-user/mariadb-10.3.13/sql/mysqld.cc:5998
#19 0x00002b1f01a10b15 in __libc_start_main () from /lib64/libc.so.6
#20 0x000055c7e3bbd545 in _start ()

Here seems to fail in:

static int PthreadCall(const char* label, int result) {
if (result != 0 && result != ETIMEDOUT)

{ fprintf(stderr, "pthread %s: %s\n", label, strerror(result)); abort(); }

return result;
}

In this case the value returned for result is 22 (EINVAL) for the call pthread_mutex_lock()

In both cases the database renders unrecoverable and the only way to make it start is removing the wal logs from rocks db that would mean that we lost data.

We had:

rocksdb_enable_2pc = 1
rocksdb_use_fsync = 1
sync_binlog = 1
manual_wal_flush = 0

Nothing seems to help except disabling binlog. Without binlog the error does not happen.