[MDEV-13643] rpl.rpl_gtid_crash sporadic fail in buildbot with Lost connection Created: 2017-08-25  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Replication, Tests
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.4, 10.5

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Andrei Elkin
Resolution: Unresolved Votes: 0
Labels: None


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/9336/steps/test_3/logs/stdio

rpl.rpl_gtid_crash 'innodb,mix'          w4 [ fail ]
        Test ended at 2017-08-24 15:21:16
 
CURRENT_TEST: rpl.rpl_gtid_crash
mysqltest: At line 189: query 'SET GLOBAL debug_dbug="+d,crash_commit_after"' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
*** Test crashing slave at various points and check that it recovers crash-safe. ***
include/stop_slave.inc
SET GLOBAL debug_dbug="+d,inject_crash_before_write_rpl_slave_state";
START SLAVE;
connection server_1;
INSERT INTO t1 VALUES (4);
include/save_master_gtid.inc
connection server_2;
include/sync_with_master_gtid.inc
include/stop_slave.inc
START SLAVE;
SET GLOBAL debug_dbug="+d,crash_commit_before";
connection server_1;
INSERT INTO t1 VALUES (5);
include/save_master_gtid.inc
connection server_2;
include/sync_with_master_gtid.inc
include/stop_slave.inc
START SLAVE;
SET GLOBAL debug_dbug="+d,crash_commit_after";
 
More results from queries before failure can be found in /mnt/buildbot/build/mariadb-10.3.1/mysql-test/var/4/log/rpl_gtid_crash.log
 
 
Server [mysqld.2 - pid: 21088, winpid: 21088, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2017-08-24 15:20:59 0 [Note] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld (mysqld 10.3.1-MariaDB-debug-log) starting as process 20334 ...
2017-08-24 15:20:59 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2017-08-24 15:20:59 0 [Note] Plugin 'partition' is disabled.
2017-08-24 15:20:59 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-08-24 15:20:59 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-08-24 15:20:59 0 [Note] InnoDB: Uses event mutexes
2017-08-24 15:20:59 0 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
2017-08-24 15:20:59 0 [Note] InnoDB: Using Linux native AIO
2017-08-24 15:20:59 0 [Note] InnoDB: Number of pools: 1
2017-08-24 15:20:59 0 [Note] InnoDB: Using generic crc32 instructions
2017-08-24 15:20:59 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2017-08-24 15:20:59 0 [Note] InnoDB: Completed initialization of buffer pool
2017-08-24 15:20:59 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-08-24 15:20:59 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2017-08-24 15:20:59 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-08-24 15:20:59 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-08-24 15:20:59 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-08-24 15:21:00 0 [Note] InnoDB: Waiting for purge to start
2017-08-24 15:21:00 0 [Note] InnoDB: 5.7.19 started; log sequence number 1632811
2017-08-24 15:21:00 0 [Note] InnoDB: Loading buffer pool(s) from /run/shm/var_auto_vtrH/4/mysqld.2/data/ib_buffer_pool
2017-08-24 15:21:00 0 [Note] InnoDB: Buffer pool(s) load completed at 170824 15:21:00
2017-08-24 15:21:00 0 [Note] Plugin 'SEQUENCE' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_CMP' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'FEEDBACK' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'user_variables' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-08-24 15:21:00 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-08-24 15:21:00 0 [Warning] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld: unknown option '--loose-pam-debug'
2017-08-24 15:21:00 0 [Note] Server socket created on IP: '127.0.0.1'.
2017-08-24 15:21:00 0 [Note] Reading of all Master_info entries succeded
2017-08-24 15:21:00 0 [Note] Added new Master_info '' to hash table
2017-08-24 15:21:00 0 [Note] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld: ready for connections.
Version: '10.3.1-MariaDB-debug-log'  socket: '/mnt/buildbot/build/mariadb-10.3.1/mysql-test/var/tmp/4/mysqld.2.sock'  port: 16001  Source distribution
2017-08-24 15:21:00 10 [Note] Deleted Master_info file '/mnt/buildbot/build/mariadb-10.3.1/mysql-test/var/4/mysqld.2/data/master.info'.
2017-08-24 15:21:00 10 [Note] Deleted Master_info file '/mnt/buildbot/build/mariadb-10.3.1/mysql-test/var/4/mysqld.2/data/relay-log.info'.
2017-08-24 15:21:00 10 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
2017-08-24 15:21:00 10 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16000', master_log_file='master-bin.000001', master_log_pos='4'.
2017-08-24 15:21:00 12 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication started in log 'master-bin.000001' at position 4
2017-08-24 15:21:00 13 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
2017-08-24 15:21:01 13 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 1924
2017-08-24 15:21:01 12 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 1924
2017-08-24 15:21:01 10 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
2017-08-24 15:21:01 10 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16000', master_log_file='master-bin.000001', master_log_pos='1924'. New state master_host='127.0.0.1', master_port='16000', master_log_file='', master_log_pos='4'.
2017-08-24 15:21:01 10 [Note] Previous Using_Gtid=No. New Using_Gtid=Current_Pos
2017-08-24 15:21:01 14 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication starts at GTID position '0-1-7'
2017-08-24 15:21:01 15 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 4, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-7'
2017-08-24 15:21:02 14 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
2017-08-24 15:21:02 14 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000001' at position 37150; GTID position '0-1-209'
2017-08-24 15:21:02 14 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16000' - retry-time: 1  maximum-retries: 100  message: Can't connect to MySQL server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003
2017-08-24 15:21:06 14 [Note] Slave: connected to master 'root@127.0.0.1:16000',replication resumed in log 'master-bin.000001' at position 37150
2017-08-24 15:21:06 15 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000002' at position 664; GTID position '0-1-211'
2017-08-24 15:21:06 14 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 664; GTID position 0-1-211
2017-08-24 15:21:07 16 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication starts at GTID position ''
2017-08-24 15:21:07 17 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 664, relay log './slave-relay-bin.000001' position: 4; GTID position ''
2017-08-24 15:21:07 16 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
2017-08-24 15:21:07 16 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000003' at position 375; GTID position '1-1-2,2-1-1,0-1-1'
2017-08-24 15:21:07 16 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16000' - retry-time: 1  maximum-retries: 100  message: Can't connect to MySQL server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003
2017-08-24 15:21:10 16 [Note] Slave: connected to master 'root@127.0.0.1:16000',replication resumed in log 'master-bin.000003' at position 375
2017-08-24 15:21:10 17 [Note] Error reading relay log event: slave SQL thread was killed
2017-08-24 15:21:10 17 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000004' at position 375; GTID position '0-1-1,1-1-2,2-1-1'
2017-08-24 15:21:10 16 [Note] Slave I/O thread exiting, read up to log 'master-bin.000004', position 375; GTID position 1-1-2,2-1-1,0-1-1
2017-08-24 15:21:10 19 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 375, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-1,1-1-2,2-1-1'
2017-08-24 15:21:10 18 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication starts at GTID position '1-1-2,0-1-1,2-1-1'
SIGKILL myself
2017-08-24 15:21:11 0 [Note] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld (mysqld 10.3.1-MariaDB-debug-log) starting as process 21000 ...
2017-08-24 15:21:11 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2017-08-24 15:21:11 0 [Note] Plugin 'partition' is disabled.
2017-08-24 15:21:11 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-08-24 15:21:11 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-08-24 15:21:11 0 [Note] InnoDB: Uses event mutexes
2017-08-24 15:21:11 0 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
2017-08-24 15:21:11 0 [Note] InnoDB: Using Linux native AIO
2017-08-24 15:21:11 0 [Note] InnoDB: Number of pools: 1
2017-08-24 15:21:11 0 [Note] InnoDB: Using generic crc32 instructions
2017-08-24 15:21:11 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2017-08-24 15:21:11 0 [Note] InnoDB: Completed initialization of buffer pool
2017-08-24 15:21:11 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-08-24 15:21:11 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1870767
2017-08-24 15:21:11 0 [Note] InnoDB: Last binlog file './slave-bin.000001', position 981
2017-08-24 15:21:11 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2017-08-24 15:21:11 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-08-24 15:21:11 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-08-24 15:21:11 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-08-24 15:21:11 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-08-24 15:21:12 0 [Note] InnoDB: Waiting for purge to start
2017-08-24 15:21:12 0 [Note] InnoDB: 5.7.19 started; log sequence number 1870828
2017-08-24 15:21:12 0 [Note] InnoDB: Loading buffer pool(s) from /run/shm/var_auto_vtrH/4/mysqld.2/data/ib_buffer_pool
2017-08-24 15:21:12 0 [Note] InnoDB: Buffer pool(s) load completed at 170824 15:21:12
2017-08-24 15:21:12 0 [Note] Plugin 'SEQUENCE' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_CMP' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'FEEDBACK' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'user_variables' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-08-24 15:21:12 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-08-24 15:21:12 0 [Warning] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld: unknown option '--loose-pam-debug'
2017-08-24 15:21:12 0 [Note] Recovering after a crash using slave-bin
2017-08-24 15:21:12 0 [Note] Starting crash recovery...
2017-08-24 15:21:12 0 [Note] Crash recovery finished.
2017-08-24 15:21:12 0 [Note] Server socket created on IP: '127.0.0.1'.
2017-08-24 15:21:12 0 [Note] Reading of all Master_info entries succeded
2017-08-24 15:21:12 0 [Note] Added new Master_info '' to hash table
2017-08-24 15:21:12 10 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication starts at GTID position '1-1-2,0-1-1,2-1-1'
2017-08-24 15:21:12 0 [Note] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld: ready for connections.
Version: '10.3.1-MariaDB-debug-log'  socket: '/mnt/buildbot/build/mariadb-10.3.1/mysql-test/var/tmp/4/mysqld.2.sock'  port: 16001  Source distribution
2017-08-24 15:21:12 11 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 4, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-1,1-1-2,2-1-1'
2017-08-24 15:21:12 11 [Note] Error reading relay log event: slave SQL thread was killed
2017-08-24 15:21:12 11 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000004' at position 540; GTID position '0-1-2,1-1-2,2-1-1'
2017-08-24 15:21:12 10 [Note] Slave I/O thread exiting, read up to log 'master-bin.000004', position 540; GTID position 1-1-2,0-1-2,2-1-1
2017-08-24 15:21:13 13 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication starts at GTID position '1-1-2,0-1-2,2-1-1'
2017-08-24 15:21:13 14 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 540, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-2,1-1-2,2-1-1'
SIGKILL myself
2017-08-24 15:21:13 0 [Note] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld (mysqld 10.3.1-MariaDB-debug-log) starting as process 21089 ...
2017-08-24 15:21:13 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
2017-08-24 15:21:13 0 [Note] Plugin 'partition' is disabled.
2017-08-24 15:21:13 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-08-24 15:21:13 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-08-24 15:21:13 0 [Note] InnoDB: Uses event mutexes
2017-08-24 15:21:13 0 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
2017-08-24 15:21:13 0 [Note] InnoDB: Using Linux native AIO
2017-08-24 15:21:13 0 [Note] InnoDB: Number of pools: 1
2017-08-24 15:21:13 0 [Note] InnoDB: Using generic crc32 instructions
2017-08-24 15:21:13 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2017-08-24 15:21:13 0 [Note] InnoDB: Completed initialization of buffer pool
2017-08-24 15:21:13 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-08-24 15:21:13 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1870915
2017-08-24 15:21:14 0 [Note] InnoDB: Transaction 2050 was in the XA prepared state.
2017-08-24 15:21:14 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2017-08-24 15:21:14 0 [Note] InnoDB: Trx id counter is 2560
2017-08-24 15:21:14 0 [Note] InnoDB: Starting final batch to recover 2 pages from redo log.
2017-08-24 15:21:14 0 [Note] InnoDB: Last binlog file './slave-bin.000001', position 981
2017-08-24 15:21:15 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
2017-08-24 15:21:15 0 [Note] InnoDB: Rollback of non-prepared transactions completed
2017-08-24 15:21:15 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2017-08-24 15:21:15 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-08-24 15:21:15 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-08-24 15:21:15 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-08-24 15:21:15 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-08-24 15:21:15 0 [Note] InnoDB: Waiting for purge to start
2017-08-24 15:21:15 0 [Note] InnoDB: 5.7.19 started; log sequence number 1871350
2017-08-24 15:21:15 0 [Note] InnoDB: Loading buffer pool(s) from /run/shm/var_auto_vtrH/4/mysqld.2/data/ib_buffer_pool
2017-08-24 15:21:15 0 [Note] InnoDB: Buffer pool(s) load completed at 170824 15:21:15
2017-08-24 15:21:15 0 [Note] Plugin 'SEQUENCE' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_CMP' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'FEEDBACK' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'user_variables' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-08-24 15:21:15 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-08-24 15:21:15 0 [Warning] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld: unknown option '--loose-pam-debug'
2017-08-24 15:21:15 0 [Note] Recovering after a crash using slave-bin
2017-08-24 15:21:15 0 [Note] Starting crash recovery...
2017-08-24 15:21:15 0 [Note] InnoDB: Starting recovery for XA transactions...
2017-08-24 15:21:15 0 [Note] InnoDB: Transaction 2050 in prepared state after recovery
2017-08-24 15:21:15 0 [Note] InnoDB: Transaction contains changes to 2 rows
2017-08-24 15:21:15 0 [Note] InnoDB: 1 transactions in prepared state after recovery
2017-08-24 15:21:15 0 [Note] Found 1 prepared transaction(s) in InnoDB
2017-08-24 15:21:15 0 [Note] commit xid 'MySQLXid\2\0\0\0\4\0\0\0\0\0\0\0'
2017-08-24 15:21:15 0 [Note] Crash recovery finished.
2017-08-24 15:21:15 0 [Note] Server socket created on IP: '127.0.0.1'.
2017-08-24 15:21:15 0 [Note] Reading of all Master_info entries succeded
2017-08-24 15:21:15 0 [Note] Added new Master_info '' to hash table
2017-08-24 15:21:15 0 [Note] /mnt/buildbot/build/mariadb-10.3.1/sql/mysqld: ready for connections.
Version: '10.3.1-MariaDB-debug-log'  socket: '/mnt/buildbot/build/mariadb-10.3.1/mysql-test/var/tmp/4/mysqld.2.sock'  port: 16001  Source distribution
2017-08-24 15:21:15 11 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 540, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-2,1-1-2,2-1-1'
2017-08-24 15:21:15 10 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication starts at GTID position '1-1-2,0-1-2,2-1-1'
2017-08-24 15:21:16 11 [Note] Error reading relay log event: slave SQL thread was killed
2017-08-24 15:21:16 11 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000004' at position 705; GTID position '0-1-3,1-1-2,2-1-1'
2017-08-24 15:21:16 10 [Note] Slave I/O thread exiting, read up to log 'master-bin.000004', position 705; GTID position 1-1-2,0-1-3,2-1-1
2017-08-24 15:21:16 14 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 705, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-3,1-1-2,2-1-1'
2017-08-24 15:21:16 13 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication starts at GTID position '1-1-2,0-1-3,2-1-1'
SIGKILL myself
----------SERVER LOG END-------------



 Comments   
Comment by Elena Stepanova [ 2017-08-25 ]

Just 3 recorded occurrences – 10.2, bb-10.3-monty and 10.3; however, it's reproducible locally with --repeat (at least it happened once locally for me, which means it doesn't require any special environment, just enough luck):

rpl.rpl_gtid_crash 'innodb,mix'          [ pass ]  44413
rpl.rpl_gtid_crash 'innodb,mix'          [ pass ]  45160
rpl.rpl_gtid_crash 'innodb,mix'          [ pass ]  44693
rpl.rpl_gtid_crash 'innodb,mix'          [ pass ]  45038
rpl.rpl_gtid_crash 'innodb,mix'          [ pass ]  45050
rpl.rpl_gtid_crash 'innodb,mix'          [ pass ]  46268
rpl.rpl_gtid_crash 'innodb,mix'          [ pass ]  45164
rpl.rpl_gtid_crash 'innodb,mix'          [ fail ]
        Test ended at 2017-08-25 14:45:48
 
CURRENT_TEST: rpl.rpl_gtid_crash
mysqltest: At line 165: query 'SET GLOBAL debug_dbug="+d,crash_commit_before"' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
master-bin.000004	#	Gtid_list	#	#	#
connection server_2;
SELECT * FROM t1 ORDER BY a;
a
1
2
3
*** Test crashing slave at various points and check that it recovers crash-safe. ***
include/stop_slave.inc
SET GLOBAL debug_dbug="+d,inject_crash_before_write_rpl_slave_state";
START SLAVE;
connection server_1;
INSERT INTO t1 VALUES (4);
include/save_master_gtid.inc
connection server_2;
include/sync_with_master_gtid.inc
include/stop_slave.inc
START SLAVE;
SET GLOBAL debug_dbug="+d,crash_commit_before";

On all occasions it happened with ps-protocol.

There is no sign of a crash in error logs (apart from self-inflicted SIGKILLs), possibly crash injections work before the query finishes execution?

Comment by Alice Sherepa [ 2021-07-01 ]

currently test fails on 10.5 10.6 with a warning:
10.6 390014781b6832597e83ceffe0
http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/29601/steps/mtr_nm/logs/stdio

rpl.rpl_gtid_crash 'innodb,row'          w4 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2021-06-29 08:41:13
line
2021-06-29  8:41:03 5 [Warning] Slave I/O: SET @master_heartbeat_period to master failed with error: Lost connection to server during query, Internal MariaDB error code: 2013
^ Found warnings in /mnt/buildbot/build/mariadb-10.6.3/mysql-test/var/4/log/mysqld.2.err
ok

Comment by Angelique Sklavounos (Inactive) [ 2022-08-22 ]

currently test fails on 10.5 10.6 with a warning:

Seen again: https://buildbot.mariadb.org/#/builders/168/builds/13911

10.6 f02ca429f70c16be2b2e3d5671d9990cd3d474b6

rpl.rpl_gtid_crash 'innodb,mix'          w3 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2022-08-22 06:46:49
line
2022-08-22  6:46:38 5 [Warning] Slave I/O: SET @master_heartbeat_period to master failed with error: Lost connection to server during query, Internal MariaDB error code: 2013
^ Found warnings in /buildbot/amd64-ubuntu-1804-clang10-asan/build/mysql-test/var/3/log/mysqld.2.err
ok

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