Error reading GTIDs from binary log: -1

Wonder how MySQL Slave server will act, when disk full condition occurs? Before in our articles we use only single MySQL server. Now think about replication topology, where slave server has problem with full partition. Firstly we will enable Binary Log/GTID on Slave side and will ensure that the changes also applied to binary log on Slave side:

      # BINARY LOGGING # 
      server_id = 2 
      log_bin = /opt/mysql/datadir/mysql-bin 
      log_bin_index = /opt/mysql/datadir/mysql-bin 
      expire_logs_days = 14 
      sync_binlog = 1 
      binlog_format = row 
      relay_log = /opt/mysql/datadir/mysql-relay-bin 
      log_slave_updates = 1 
      read_only = 1 
      gtid-mode = on 
      enforce-gtid-consistency = true 
      master-info-repository = TABLE 
      relay-log-info-repository = TABLE 
      slave-parallel-workers = 15 
      binlog-checksum = CRC32 
      master-verify-checksum = 1 
      slave-sql-verify-checksum = 1 
      binlog-rows-query-log_events = 1 

When disk full condition comes up, error log will be filled as follows:

     2015-05-01 04:42:10 2033 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000002' at position 557, relay log '/opt/mysql/datadir/mysql-relay-bin.000001' position: 4 2015-05-01 04:50:50 7f3b79865700 
     InnoDB: Error: Write to file ./test1/sales.ibd failed at offset 184549376. 
     InnoDB: 1048576 bytes should have been written, only 688128 were written. 
     InnoDB: Operating system error number 0. 
     InnoDB: Check that your OS and file system support files of this size. 
     InnoDB: Check also that the disk is not full or a disk quota exceeded. 
     InnoDB: Error number 0 means 'Success'. 
     InnoDB: Some operating system error numbers are described at 
     InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html 2015-05-01 04:50:51 2033 
     [ERROR] /opt/mysql/bin/mysqld: The table 'sales' is full 2015-05-01 04:50:51 2033 
     [ERROR] Slave SQL: Worker 14 failed executing transaction '328e26e9-ea51-11e4-8023-080027745404:242' at master log mysql-bin.000002, end_log_pos 275717680; Could not execute Write_rows event on table test1.sales; 
      The table 'sales' is full, 
      Error_code: 1114; handler error HA_ERR_RECORD_FILE_FULL; the event's master log mysql-bin.000002, end_log_pos 275717680, 
     Error_code: 1114 2015-05-01 04:50:51 2033 
     [Warning] Slave SQL: ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries  could lead to problems. In such cases you have to examine your data (see documentation for details). 
    Error_code: 1756 2015-05-01 04:50:51 2033 
    [Note] Error reading relay log event: slave SQL thread was killed 2015-05-01 04:50:51 2033 
    [Warning] Slave SQL: ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details). 
   Error_code: 1756 2015-05-01 04:50:51 2033 
   [Warning] Slave SQL: ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details). Error_code: 1756 2015-05-01 04:50:52 2033 
   [Warning] Disk is full writing '/opt/mysql/datadir/mysql-relay-bin.000003' (Errcode: 28 - No space left on device). Waiting for someone to free space... 

Interesting thing is OS error number which is equal to 0. And 0 equals to “success”. After if you try disable binary log/GTID and store only relay-log information in my.cnf as follows:

    # BINARY LOGGING # # 
    server_id = 2 
    #log_bin = /opt/mysql/datadir/mysql-bin 
    #log_bin_index = /opt/mysql/datadir/mysql-bin 
    #expire_logs_days = 14 
    #sync_binlog = 1 
    #binlog_format = row 
    relay_log = /opt/mysql/datadir/mysql-relay-bin 
    #log_slave_updates = 1 
    read_only = 1 
    #gtid-mode = on 
    #enforce-gtid-consistency = true 
    master-info-repository = TABLE 
    relay-log-info-repository = TABLE 
    #slave-parallel-workers = 15 
    #binlog-checksum = CRC32 
    #master-verify-checksum = 1 
    #slave-sql-verify-checksum = 1 
    #binlog-rows-query-log_events = 1 

If you try to start there will be some interesting errors in error log:

2015-05-01 05:05:09 2698 [ERROR] /opt/mysql/bin/mysqld: Found a Gtid_log_event or Previous_gtids_log_event when @@GLOBAL.GTID_MODE = OFF. 
2015-05-01 05:05:14 2698 [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 8178, event_type: 30 
2015-05-01 05:05:14 2698 [Warning] Error reading GTIDs from binary log: -1 
2015-05-01 05:05:15 2698 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2015-05-01 05:05:15 2698 [Note] Slave I/O thread: connected to master 'repl@192.168.1.164:3307',replication started in log 'mysql-bin.000002' at position 204643802 
2015-05-01 05:05:16 2698 [ERROR] Slave I/O: The slave IO thread stops because the master has @@GLOBAL.GTID_MODE ON and this server has @@GLOBAL.GTID_MODE OFF, Error_code: 1593 
2015-05-01 05:05:16 2698 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.000002', position 204643802 
2015-05-01 05:05:16 2698 [Note] Event Scheduler: Loaded 0 events 
2015-05-01 05:05:16 2698 [Note] /opt/mysql/bin/mysqld: ready for connections. Version: '5.6.24-debug' socket: '/opt/mysql/datadir/mysqld-new.sock' port: 3307 Shahriyar Rzayev's MySQL 
2015-05-01 05:05:16 2698 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000002' at position 274388137, relay log '/opt/mysql/datadir/mysql-relay-bin.000003' position: 274387894 
2015-05-01 05:05:16 2698 [ERROR] Slave SQL: @@SESSION.GTID_NEXT cannot be set to UUID:NUMBER when @@GLOBAL.GTID_MODE = OFF. Error_code: 1781 
2015-05-01 05:05:16 2698 [Warning] Slave: @@SESSION.GTID_NEXT cannot be set to UUID:NUMBER when @@GLOBAL.GTID_MODE = OFF. Error_code: 1781 
2015-05-01 05:05:16 2698 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000002' position 274388137 [/code] Errors about disabled GTID is normal and it must be here as usual. But must interesting is:  [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 8178, event_type: 30           
[Warning] Error reading GTIDs from binary log: -1  

[Warning] Error reading GTIDs from binary log: -1. Related BUG report -> #72437 If you have another issue path related to slave server’s disk usage, will be interesting to hear from you.

Author: Shahriyar Rzayev

Azerbaijan MySQL User Group leader.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s