[MDEV-23033] All slaves crash once in ~24 hours and loop restart with signal 11 Created: 2020-06-27  Updated: 2021-05-23  Resolved: 2021-01-04

Status: Closed
Project: MariaDB Server
Component/s: Replication, Virtual Columns
Affects Version/s: 10.4.12, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.2.37, 10.3.28, 10.4.18, 10.5.9

Type: Bug Priority: Critical
Reporter: Grigoriy Assignee: Sujatha Sivakumar (Inactive)
Resolution: Fixed Votes: 1
Labels: Slave
Environment:

Ubuntu 18.0.4
Master 6 cores/6Gb and 2 Slaves 4 cores/4Gbs
Yandex Cloud VPS

Attachments: Zip Archive binlog.000879.zip    
Issue Links:
Blocks
Duplicate
is duplicated by MDEV-24326 MariaDB crash loop on DELETE Closed
Relates
relates to MDEV-16856 Crash Closed
relates to MDEV-21153 Galera: Replica nodes crash with sign... Closed

 Description   

Hello.
We have a Master-to-multi-Slave config and are regularly facing slaves crashes (they crash together at the same time, approx. once every 24 hours). Maybe this has something to do with load, but crashed did not happen under heavy load and still happened today with relatively (50%) of highest load we've had so far.

Master 10.4.12 setup is Ubuntu 18.0.4 cloud VPS (yandex cloud) with 6 cores 100% quota, 6 Gbs RAM, 30 Gbs space.
Slaves 10.4.12 and 10.4.13 setup is Ubuntu 18.0.4 cloud VPS (yandex cloud) with 4 cores 100% quota, 4 Gbs RAM, 30 Gbs space.

Replication is setup using this guide - https://mariadb.com/kb/en/setting-up-a-replication-slave-with-mariabackup/
Everything works well, until slaves crash.

Currently Web API sends DML statements to Master directly and SELECT statements are sent to HAProxy with wieght distribution 20/40/40 (Master/Slave1/Slave2).
Before that we had Master 10.4.12 and only 1 Slave 10.4.12 with direct requests from API to Slave without HAProxy - Slave still crashed, I hoped with 2 slaves we would at least have 1 standing... but alas...

We removed all triggers from the DB.
We use GTIDs.
We now use mixed binlog (but id did crash with 'row' mode).
We don't have any DDL statements running (except a few CREATE TEMPORARY TABLE).
We use InnoDB only to store data.
We don't have any FullText Indexes.
We don't use compression.
We don't use SSL between Mater and Slaves.
Timezone on all machines is UTC.
Data size now approximately 800Mb, InnoDb buffer pool size is 1024Mb, InnoDb log file size is128Mb.

Here's syslog:

Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: 200627 12:44:00 [ERROR] mysqld got signal 11 ;
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: This could be because you hit a bug. It is also possible that this binary
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: or one of the libraries it was linked against is corrupt, improperly built,
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: We will try our best to scrape up some info that will hopefully help
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: diagnose the problem, but since we have already crashed,
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: something is definitely wrong and this may fail.
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Server version: 10.4.12-MariaDB-1:10.4.12+maria~bionic-log
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: key_buffer_size=134217728
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: read_buffer_size=2097152
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: max_used_connections=15
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: max_threads=77
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: thread_count=24
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: It is possible that mysqld could use up to
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 606038 K  bytes of memory
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Hope that's ok; if not, decrease some variables in the equation.
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Thread pointer: 0x7f40500014f8
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Attempting backtrace. You can use the following information to find out
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: where mysqld died. If you see no messages after this, something went
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: terribly wrong...
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: stack_bottom = 0x7f40fc901e98 thread_stack 0x49000
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55b8a063ac3e]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(handle_fatal_signal+0x515)[0x55b8a00aecf5]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7f411d583890]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /lib/x86_64-linux-gnu/libc.so.6(+0x18f039)[0x7f411c008039]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xae4170)[0x55b8a031e170]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xa205dd)[0x55b8a025a5dd]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xb10a85)[0x55b8a034aa85]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xb116be)[0x55b8a034b6be]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xb1224c)[0x55b8a034c24c]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xae7959)[0x55b8a0321959]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xad0db6)[0x55b8a030adb6]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xb0b658)[0x55b8a0345658]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xb1173f)[0x55b8a034b73f]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xb1224c)[0x55b8a034c24c]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xae73a4)[0x55b8a03213a4]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xa21f8f)[0x55b8a025bf8f]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(_ZN7handler13ha_delete_rowEPKh+0x9f)[0x55b8a00ba7af]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(_ZN21Delete_rows_log_event11do_exec_rowEP14rpl_group_info+0x12d)[0x55b8a01b12ad]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEP14rpl_group_info+0x25d)[0x55b8a01a440d]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0x5b6e90)[0x55b89fdf0e90]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(handle_slave_sql+0x17b4)[0x55b89fdfa344]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /usr/sbin/mysqld(+0xdab79a)[0x55b8a05e579a]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7f411d5786db]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f411bf9a88f]
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Trying to get some variables.
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Some pointers may be invalid and cause the dump to abort.
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Query (0x0):
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Connection ID (thread ID): 49
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Status: NOT_KILLED
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: information that should help you find out what is causing the crash.
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Writing a core file...
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Working directory at /var/lib/mysql
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Resource Limits:
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Limit                     Soft Limit           Hard Limit           Units
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max cpu time              unlimited            unlimited            seconds
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max file size             unlimited            unlimited            bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max data size             unlimited            unlimited            bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max stack size            8388608              unlimited            bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max core file size        0                    unlimited            bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max resident set          unlimited            unlimited            bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max processes             15602                15602                processes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max open files            16364                16364                files
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max locked memory         16777216             16777216             bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max address space         unlimited            unlimited            bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max file locks            unlimited            unlimited            locks
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max pending signals       15602                15602                signals
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max msgqueue size         819200               819200               bytes
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max nice priority         0                    0
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max realtime priority     0                    0
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Max realtime timeout      unlimited            unlimited            us
 
Jun 27 12:44:00 vox-db1-read1 mysqld[7728]: Core pattern: core
 
Jun 27 12:44:00 vox-db1-read1 kernel: [264684.731198] mysqld[7861]: segfault at 115 ip 00007f411c008039 sp 00007f40fc8fcfc8 error 6 in libc-2.27.so[7f411be79000+1e7000]
 
Jun 27 12:44:00 vox-db1-read1 systemd[1]: mariadb.service: Main process exited, code=killed, status=11/SEGV
 
Jun 27 12:44:00 vox-db1-read1 systemd[1]: mariadb.service: Failed with result 'signal'.
 
Jun 27 12:44:05 vox-db1-read1 systemd[1]: mariadb.service: Service hold-off time over, scheduling restart.
 
Jun 27 12:44:05 vox-db1-read1 systemd[1]: mariadb.service: Scheduled restart job, restart counter is at 1.
 
Jun 27 12:44:05 vox-db1-read1 systemd[1]: Stopped MariaDB 10.4.12 database server.
 
Jun 27 12:44:05 vox-db1-read1 systemd[1]: Starting MariaDB 10.4.12 database server...
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] /usr/sbin/mysqld (mysqld 10.4.12-MariaDB-1:10.4.12+maria~bionic-log) starting as process 12132 ...
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Using Linux native AIO
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Uses event mutexes
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Number of pools: 1
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 8, chunk size = 128M
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: Completed initialization of buffer pool
 
Jun 27 12:44:06 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:06 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
Jun 27 12:44:07 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:07 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=142473402785
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 2 row operations to undo
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Trx id counter is 11134299
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Starting final batch to recover 63 pages from redo log.
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Last binlog file '/var/log/mysql/mariadb-bin.000634', position 59120658
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: 10.4.12 started; log sequence number 142473413250; transaction id 11134301
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] Plugin 'FEEDBACK' is disabled.
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] Recovering after a crash using /var/log/mysql/mariadb-bin
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] Starting crash recovery...
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] Crash recovery finished.
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Rolled back recovered transaction 11134298
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] InnoDB: Rollback of non-prepared transactions completed
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] Server socket created on IP: '0.0.0.0'.
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] Reading of all Master_info entries succeeded
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Note] Added new Master_info '' to hash table
 
Jun 27 12:44:10 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:10 0 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--log-basename=#' or '--relay-log=mysqld-relay-bin' to avoid this problem.
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:11 10 [Note] Slave I/O thread: Start asynchronous replication to master 'replication_user@10.130.0.25:3306' in log 'mariadb-bin.000712' at position 4
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:11 11 [Note] Slave SQL thread initialized, starting replication in log 'mariadb-bin.000712' at position 4, relay log './mysqld-relay-bin.000001' position: 4; GTID position '0-1-5332814'
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:11 0 [Note] /usr/sbin/mysqld: ready for connections.
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: Version: '10.4.12-MariaDB-1:10.4.12+maria~bionic-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: 2020-06-27 12:44:11 10 [Note] Slave I/O thread: connected to master 'replication_user@10.130.0.25:3306',replication starts at GTID position '0-1-5332814'
 
Jun 27 12:44:11 vox-db1-read1 systemd[1]: Started MariaDB 10.4.12 database server.
 
Jun 27 12:44:11 vox-db1-read1 /etc/mysql/debian-start[12175]: Upgrading MySQL tables if necessary.
 
Jun 27 12:44:11 vox-db1-read1 /etc/mysql/debian-start[12178]: Looking for 'mysql' as: /usr/bin/mysql
 
Jun 27 12:44:11 vox-db1-read1 /etc/mysql/debian-start[12178]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
 
Jun 27 12:44:11 vox-db1-read1 /etc/mysql/debian-start[12178]: This installation of MariaDB is already upgraded to 10.4.12-MariaDB, use --force if you still need to run mysql_upgrade
 
Jun 27 12:44:11 vox-db1-read1 /etc/mysql/debian-start[12186]: Checking for insecure root accounts.
 
Jun 27 12:44:11 vox-db1-read1 /etc/mysql/debian-start[12190]: Triggering myisam-recover for all MyISAM tables and aria-recover for all Aria tables
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: 200627 12:44:11 [ERROR] mysqld got signal 11 ;
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: This could be because you hit a bug. It is also possible that this binary
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: or one of the libraries it was linked against is corrupt, improperly built,
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: or misconfigured. This error can also be caused by malfunctioning hardware.
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: We will try our best to scrape up some info that will hopefully help
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: diagnose the problem, but since we have already crashed,
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: something is definitely wrong and this may fail.
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: Server version: 10.4.12-MariaDB-1:10.4.12+maria~bionic-log
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: key_buffer_size=134217728
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: read_buffer_size=2097152
 
Jun 27 12:44:11 vox-db1-read1 mysqld[12132]: max_used_connections=1

...and so on, it loops indefinitely.

My theory is that something comes from Master that breaks Slaves.
When first crash occured (same day I've setup replication, ~4-5 days ago) I tried to restore Slave from same backup I used to initilize it. And Slave could not be started. I suppose while catching up to Master it still encountered this breaking transaction and crashed. Then I just took a fresh backup from Master, and Slave started without problems.

Since then every time Slaves crash I just take make backup (with mariabackup) and restore slaves. This is stupid I know, but what choice do we currently have?

What additional information can I provide you with to find the root of this issue?

Thanks!

 Comments   
Comment by Alice Sherepa [ 2020-06-29 ]

Could you please provide the output of "Show binlog events" for 'mariadb-bin.000712'?

Comment by Grigoriy [ 2020-06-29 ]

Hello,

We've faced 3 crashes since then (2 on Sunday and 1 Monday).
We had to rotate logs and I did not save that particular log you ask for.

Last crash's log reads log # 879 in the same place where #712 was:

Jun 29 11:19:27 vox-db1-read2 mysqld[9112]: 2020-06-29 11:19:27 10 [Note] Slave I/O thread: Start asynchronous replication to master 'replication_user@10.130.0.25:3306' in log 'mariadb-bin.000879' at position 4
Jun 29 11:19:27 vox-db1-read2 mysqld[9112]: 2020-06-29 11:19:27 11 [Note] Slave SQL thread initialized, starting replication in log 'mariadb-bin.000879' at position 4, relay log './mysqld-relay-bin.000001' position: 4; GTID position '0-1-6364314'

So I am attaching fresh show bonlog events in 'mariadb-bin.000879' export. I hope that helps.

I've passworded the attached ZIP file and emailed you the password to alice.sherepa@mariadb.com.

Comment by Alice Sherepa [ 2020-07-20 ]

Thanks a lot! The issue repeatable on 10.2-10.5 with InnoDB engine.
The test case:

--source include/have_binlog_format_row.inc
 
--source include/have_innodb.inc
 
--source include/master-slave.inc
 
 
 
CREATE TABLE t1 (id int NOT NULL PRIMARY KEY) ENGINE=InnoDB;
 
INSERT INTO t1 VALUES (1),(2),(3);
 
 
 
CREATE TABLE t2 ( id int NOT NULL PRIMARY KEY, t1_id int NOT NULL, c1 text, 
	v_c1 varchar(256) AS (json_value(c1,'$.login')) virtual,
 
	KEY (v_c1), 
	KEY (t1_id), 
	CONSTRAINT a FOREIGN KEY (t1_id) REFERENCES t1 (id) ON DELETE CASCADE
 
) ENGINE=InnoDB;
 
INSERT INTO t2 VALUES (90,1,NULL,NULL);
 
 
 
delete from t1 WHERE id=1; 
--sync_slave_with_master
 
 
 
--connection master
 
drop table t2,t1;

10.2 a1e52e7f32cee7c204078db4

 
mysqld: /10.2/storage/innobase/handler/ha_innodb.cc:21982: dfield_t* innobase_get_computed_value(dtuple_t*, const dict_v_col_t*, const dict_index_t*, mem_heap_t**, mem_heap_t*, const dict_field_t*, THD*, TABLE*, byte*, const dict_table_t*, upd_t*, dict_foreign_t*): Assertion `mysql_table' failed.
 
200720  9:45:29 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.2.33-MariaDB-debug-log
 
 
 
linux/raise.c:51(__GI_raise)[0x7fe2a66507bb]
 
stdlib/abort.c:81(__GI_abort)[0x7fe2a663b535]
 
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7fe2a663b40f]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x30102)[0x7fe2a6649102]
 
handler/ha_innodb.cc:21984(innobase_get_computed_value(dtuple_t*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*))[0x55bc0eea1c61]
 
row/row0upd.cc:2189(row_upd_store_v_row(upd_node_t*, upd_t const*, THD*, TABLE*))[0x55bc0f0184e5]
 
row/row0upd.cc:2261(row_upd_store_row(upd_node_t*, THD*, TABLE*))[0x55bc0f018743]
 
row/row0upd.cc:2995(row_upd_del_mark_clust_rec(upd_node_t*, dict_index_t*, unsigned short*, que_thr_t*, unsigned long, bool, mtr_t*))[0x55bc0f01aa70]
 
row/row0upd.cc:3166(row_upd_clust_step(upd_node_t*, que_thr_t*))[0x55bc0f01b362]
 
row/row0upd.cc:3292(row_upd(upd_node_t*, que_thr_t*))[0x55bc0f01b84c]
 
row/row0upd.cc:3438(row_upd_step(que_thr_t*))[0x55bc0f01bd23]
 
row/row0mysql.cc:2110(row_update_cascade_for_mysql(que_thr_t*, upd_node_t*, dict_table_t*))[0x55bc0efc6ea3]
 
row/row0ins.cc:1419(row_ins_foreign_check_on_constraint(que_thr_t*, dict_foreign_t*, btr_pcur_t*, dtuple_t*, mtr_t*))[0x55bc0efa2783]
 
row/row0ins.cc:1808(row_ins_check_foreign_constraint(unsigned long, dict_foreign_t*, dict_table_t*, dtuple_t*, que_thr_t*))[0x55bc0efa3560]
 
row/row0upd.cc:325(row_upd_check_references_constraints(upd_node_t*, btr_pcur_t*, dict_table_t*, dict_index_t*, unsigned short*, que_thr_t*, mtr_t*))[0x55bc0f014ace]
 
row/row0upd.cc:3005(row_upd_del_mark_clust_rec(upd_node_t*, dict_index_t*, unsigned short*, que_thr_t*, unsigned long, bool, mtr_t*))[0x55bc0f01ab40]
 
row/row0upd.cc:3166(row_upd_clust_step(upd_node_t*, que_thr_t*))[0x55bc0f01b362]
 
row/row0upd.cc:3292(row_upd(upd_node_t*, que_thr_t*))[0x55bc0f01b84c]
 
row/row0upd.cc:3438(row_upd_step(que_thr_t*))[0x55bc0f01bd23]
 
row/row0mysql.cc:1827(row_update_for_mysql(row_prebuilt_t*))[0x55bc0efc64ba]
 
handler/ha_innodb.cc:9105(ha_innobase::delete_row(unsigned char const*))[0x55bc0ee8ba1f]
 
sql/handler.cc:6168(handler::ha_delete_row(unsigned char const*))[0x55bc0ec9a1d0]
 
sql/log_event.cc:13746(Delete_rows_log_event::do_exec_row(rpl_group_info*))[0x55bc0edc0104]
 
sql/log_event.cc:11101(Rows_log_event::do_apply_event(rpl_group_info*))[0x55bc0edb9f4b]
 
sql/log_event.h:1452(Log_event::apply_event(rpl_group_info*))[0x55bc0e9607d3]
 
sql/slave.cc:3567(apply_event_and_update_pos_apply(Log_event*, THD*, rpl_group_info*, int))[0x55bc0e9556d5]
 
sql/slave.cc:3735(apply_event_and_update_pos(Log_event*, THD*, rpl_group_info*))[0x55bc0e955c22]
 
sql/slave.cc:4034(exec_relay_log_event(THD*, Relay_log_info*, rpl_group_info*))[0x55bc0e956349]
 
sql/slave.cc:5181(handle_slave_sql)[0x55bc0e95982f]
 
perfschema/pfs.cc:1871(pfs_spawn_thread)[0x55bc0f364d74]
 
nptl/pthread_create.c:487(start_thread)[0x7fe2a6d8efa3]
 
x86_64/clone.S:97(clone)[0x7fe2a67124cf]
 
 
 
Query (0x7fe23c014dd3): delete from t1 WHERE id=1

not-debug build:

10.5 054f10365c49b70a3868edc0c955ff

 
200720 11:27:37 [ERROR] mysqld got signal 11 ;
 
 
 
??:0(__restore_rt)[0x7fe18c3c5730]
 
handler/ha_innodb.cc:20930(innobase_get_computed_value(dtuple_t*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*))[0x56093ba52555]
 
row/row0upd.cc:1865(row_upd_store_v_row)[0x56093ba53a0e]
 
row/row0upd.cc:2689(row_upd_del_mark_clust_rec)[0x56093ba5506a]
 
row/row0upd.cc:2997(row_upd)[0x56093ba2ebe9]
 
row/row0mysql.cc:2252(row_update_cascade_for_mysql(que_thr_t*, upd_node_t*, dict_table_t*))[0x56093ba1e787]
 
row/row0ins.cc:1395(row_ins_foreign_check_on_constraint)[0x56093ba4ff51]
 
bits/atomic_base.h:524(row_upd_check_references_constraints(upd_node_t*, btr_pcur_t*, dict_table_t*, dict_index_t*, unsigned short*, que_thr_t*, mtr_t*) [clone .part.49])[0x56093ba53f28]
 
row/row0upd.cc:231(row_upd_check_references_constraints)[0x56093ba5506a]
 
row/row0upd.cc:2997(row_upd)[0x56093ba30894]
 
row/row0mysql.cc:1887(row_update_for_mysql(row_prebuilt_t*))[0x56093b975bdf]
 
handler/ha_innodb.cc:8645(ha_innobase::delete_row(unsigned char const*))[0x56093b6bf71e]
 
sql/handler.cc:7249(handler::ha_delete_row(unsigned char const*))[0x56093b7af9e4]
 
sql/log_event_server.cc:8148(Delete_rows_log_event::do_exec_row(rpl_group_info*))[0x56093b7a443f]
 
sql/log_event_server.cc:5675(Rows_log_event::do_apply_event(rpl_group_info*))[0x56093b42a082]
 
sql/log_event.h:1497(apply_event_and_update_pos_apply(Log_event*, THD*, rpl_group_info*, int))[0x56093b433a3f]
 
sql/slave.cc:4482(exec_relay_log_event)[0x56093b8e1d7b]
 
nptl/pthread_create.c:487(start_thread)[0x7fe18c3bafa3]
 
x86_64/clone.S:97(clone)[0x7fe18b9c34cf]
 
 
 
Query (0x7fe12c01ac9b): delete from t1 WHERE id=1

Comment by Sujatha Sivakumar (Inactive) [ 2020-12-31 ]

Hello Andrei,

Thank you for the review comments.
I have addressed all your review comments. Please find the following patch

https://github.com/MariaDB/server/commit/3f48bc08b92b2734c2af7408c246b96338675205

Comment by Andrei Elkin [ 2020-12-31 ]

Please point in the description that only slave needs upgrading, master is not buggy.
Approved.

Comment by Sujatha Sivakumar (Inactive) [ 2021-01-04 ]

Fix is implemented in 10.2.37.

10.2 fix is cherry-picked on higher versions and tested on build bot.

10.3 patch: https://github.com/MariaDB/server/commit/a1d9614d8c026949dc2c53d719943af6bebd8a0c
10.4 patch: https://github.com/MariaDB/server/commit/c42021422e4ee9dfe2239853cf378f15ba10b4f8
10.5 patch: https://github.com/MariaDB/server/commit/3eb27d04ed5a112f2f47782083f0b7e878216b84

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