Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-13643

rpl.rpl_gtid_crash sporadic fail in buildbot with Lost connection

Details

    • Bug
    • Status: Open (View Workflow)
    • Major
    • Resolution: Unresolved
    • 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6
    • 10.5
    • Replication, Tests
    • 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-------------
      
      

      Attachments

        Issue Links

          Activity

            elenst Elena Stepanova added a comment - - edited

            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?

            elenst Elena Stepanova added a comment - - edited 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?
            alice Alice Sherepa added a comment -

            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
            

            alice Alice Sherepa added a comment - 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

            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
            

            angelique.sklavounos Angelique Sklavounos (Inactive) added a comment - 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
            danblack Daniel Black added a comment -

            10.5.25-MariaDB-debug-log source revision a398f5596f75ed6e8b2d28acc657352075cc1bb4 https://buildbot.mariadb.org/#/builders/572/builds/7783

             
            rpl.rpl_gtid_crash 'innodb,stmt'         w1 [ fail ]  Found warnings/errors in server log file!
                    Test ended at 2024-03-27 01:42:13
            line
            2024-03-27  1:41:56 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 /home/buildbot/amd64-debian-11-msan/build/mysql-test/var/1/log/mysqld.2.err
            ok
             - saving '/home/buildbot/amd64-debian-11-msan/build/mysql-test/var/1/log/rpl.rpl_gtid_crash-innodb,stmt/' to '/home/buildbot/amd64-debian-11-msan/build/mysql-test/var/log/rpl.rpl_gtid_crash-innodb,stmt/'
            

            log: https://ci.mariadb.org/44853/logs/amd64-debian-11-msan/mysqld.2.err.1

            Server log around this exact time:

            2024-03-27  1:41:47 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000005' at position 510; GTID position '1-1-2,0-1-7,2-1-1', GTID event skip 2
            2024-03-27  1:41:47 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1  maximum-retries: 100  message: Lost connection to server at 'reading initial communication packet', system error: 104 "Connection reset by peer", Internal MariaDB error code: 2013
            2024-03-27  1:41:48 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1  maximum-retries: 100  message: Can't connect to server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003
            2024-03-27  1:41:51 5 [Note] Slave: connected to master 'root@127.0.0.1:16020',replication resumed in log 'master-bin.000005' at position 510
            2024-03-27  1:41:51 5 [Warning] The server_id of master server changed in the middle of GTID 0-3-8. Assuming a change of master server, so rolling back the previously received partial transaction. Expected: 3, received: 1
            2024-03-27  1:41:51 6 [Note] Slave SQL: Rolling back unfinished transaction (no COMMIT or ROLLBACK in relay log). A probable cause is that the master died while writing the transaction to its binary log, thus rolled back too. Internal MariaDB error code: 0
            2024-03-27  1:41:52 5 [ERROR] Error reading packet from server: Lost connection to server during query (server_errno=2013)
            2024-03-27  1:41:52 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000006' at position 707; GTID position '1-1-2,0-1-9,2-1-1'
            2024-03-27  1:41:52 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1  maximum-retries: 100  message: Lost connection to server at 'reading initial communication packet', system error: 104 "Connection reset by peer", Internal MariaDB error code: 2013
            2024-03-27  1:41:53 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1  maximum-retries: 100  message: Can't connect to server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003
            2024-03-27  1:41:56 5 [Note] Slave: connected to master 'root@127.0.0.1:16020',replication resumed in log 'master-bin.000006' at position 707
            2024-03-27  1:41:56 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
            2024-03-27  1:41:57 5 [Warning] Slave I/O: Master command COM_REGISTER_SLAVE failed: failed registering on master, reconnecting to try again, log 'master-bin.000006' at position 707; GTID position '1-1-2,0-1-9,2-1-1', Internal MariaDB error code: 1597
            2024-03-27  1:41:57 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1  maximum-retries: 100  message: Can't connect to server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003
            2024-03-27  1:42:01 5 [Note] Slave: connected to master 'root@127.0.0.1:16020',replication resumed in log 'master-bin.000006' at position 707
            2024-03-27  1:42:01 5 [ERROR] Error reading packet from server: Lost connection to server during query (server_errno=2013)
            

            danblack Daniel Black added a comment - 10.5.25-MariaDB-debug-log source revision a398f5596f75ed6e8b2d28acc657352075cc1bb4 https://buildbot.mariadb.org/#/builders/572/builds/7783   rpl.rpl_gtid_crash 'innodb,stmt' w1 [ fail ] Found warnings/errors in server log file! Test ended at 2024-03-27 01:42:13 line 2024-03-27 1:41:56 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 /home/buildbot/amd64-debian-11-msan/build/mysql-test/var/1/log/mysqld.2.err ok - saving '/home/buildbot/amd64-debian-11-msan/build/mysql-test/var/1/log/rpl.rpl_gtid_crash-innodb,stmt/' to '/home/buildbot/amd64-debian-11-msan/build/mysql-test/var/log/rpl.rpl_gtid_crash-innodb,stmt/' log: https://ci.mariadb.org/44853/logs/amd64-debian-11-msan/mysqld.2.err.1 Server log around this exact time: 2024-03-27 1:41:47 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000005' at position 510; GTID position '1-1-2,0-1-7,2-1-1', GTID event skip 2 2024-03-27 1:41:47 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1 maximum-retries: 100 message: Lost connection to server at 'reading initial communication packet', system error: 104 "Connection reset by peer", Internal MariaDB error code: 2013 2024-03-27 1:41:48 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1 maximum-retries: 100 message: Can't connect to server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003 2024-03-27 1:41:51 5 [Note] Slave: connected to master 'root@127.0.0.1:16020',replication resumed in log 'master-bin.000005' at position 510 2024-03-27 1:41:51 5 [Warning] The server_id of master server changed in the middle of GTID 0-3-8. Assuming a change of master server, so rolling back the previously received partial transaction. Expected: 3, received: 1 2024-03-27 1:41:51 6 [Note] Slave SQL: Rolling back unfinished transaction (no COMMIT or ROLLBACK in relay log). A probable cause is that the master died while writing the transaction to its binary log, thus rolled back too. Internal MariaDB error code: 0 2024-03-27 1:41:52 5 [ERROR] Error reading packet from server: Lost connection to server during query (server_errno=2013) 2024-03-27 1:41:52 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000006' at position 707; GTID position '1-1-2,0-1-9,2-1-1' 2024-03-27 1:41:52 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1 maximum-retries: 100 message: Lost connection to server at 'reading initial communication packet', system error: 104 "Connection reset by peer", Internal MariaDB error code: 2013 2024-03-27 1:41:53 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1 maximum-retries: 100 message: Can't connect to server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003 2024-03-27 1:41:56 5 [Note] Slave: connected to master 'root@127.0.0.1:16020',replication resumed in log 'master-bin.000006' at position 707 2024-03-27 1:41:56 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 2024-03-27 1:41:57 5 [Warning] Slave I/O: Master command COM_REGISTER_SLAVE failed: failed registering on master, reconnecting to try again, log 'master-bin.000006' at position 707; GTID position '1-1-2,0-1-9,2-1-1', Internal MariaDB error code: 1597 2024-03-27 1:41:57 5 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16020' - retry-time: 1 maximum-retries: 100 message: Can't connect to server on '127.0.0.1' (111 "Connection refused"), Internal MariaDB error code: 2003 2024-03-27 1:42:01 5 [Note] Slave: connected to master 'root@127.0.0.1:16020',replication resumed in log 'master-bin.000006' at position 707 2024-03-27 1:42:01 5 [ERROR] Error reading packet from server: Lost connection to server during query (server_errno=2013)

            People

              Elkin Andrei Elkin
              alice Alice Sherepa
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.