Bug #85695 An incident event has been written to the binary log which will stop the slaves
Submitted: 30 Mar 2017 5:34 Modified: 1 Apr 2017 8:37
Reporter: Ji Zhang Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.7, 5.7.17 OS:Any
Assigned to: CPU Architecture:Any

[30 Mar 2017 5:34] Ji Zhang
Description:
In MySQL Community Server  5.7.17 and 5.7.16,Use the grant statement to authorize two users at the same time, a user exists, a user does not exist,perform successfully on master,failure on slave, and slave will generate an incident event.Following information:
[ERROR] REVOKE/GRANT failed while granting/revoking privileges in databases. An incident event has been written to the binary log which will stop the slaves. 

And user already exists on slave will be successfully authorized.

Slave database error  log information is as follows:
..........
..........
[ERROR] REVOKE/GRANT failed while granting/revoking privileges in databases. An incident event has been written to the binary log which will stop the slaves. 
[ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '27314c3f-2040-11e8-8e65-005056b75053:5' at master log mysql-bin.000002, end_log_pos 1228; Error 'Can't find any matching row in the user table' on query. Default database: ''. Query: 'GRANT USAGE ON *.* TO ''@'','root'@'%' WITH GRANT OPTION', Error_code: 1133 
[Warning] Slave SQL for channel '': ... 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 
[Note] Slave SQL thread for channel '' exiting, replication stopped in log 'mysql-bin.000002' at position 1020 
..........
..........

master database mysql.user table info:
[root@localhost][(none)]> select user,host from mysql.user; 
+-----------+-----------+ 
| user      | host      | 
+-----------+-----------+ 
| iotrpl    | %         | 
| root      | %         | 
| rpl       | %         | 
| mysql.sys | localhost | 
| root      | localhost | 
+-----------+-----------+ 
You can see ''@'' user does not exist.

master binlog information:
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#180305 14:40:53 server id 1  end_log_pos 123 CRC32 0xba3d471f 	Start: binlog v 4, server v 5.7.16-log created 180305 14:40:53 at startup
ROLLBACK/*!*/;
BINLOG '
deacWg8BAAAAdwAAAHsAAAAAAAQANS43LjE2LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAB15pxaEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AR9HPbo=
'/*!*/;
# at 123
#180305 14:40:54 server id 1  end_log_pos 154 CRC32 0xda048813 	Previous-GTIDs
# [empty]
# at 154
#180305 14:40:59 server id 1  end_log_pos 177 CRC32 0xd354f8e3 	Stop
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#180305 14:41:08 server id 1  end_log_pos 123 CRC32 0xd8c90e9e 	Start: binlog v 4, server v 5.7.16-log created 180305 14:41:08 at startup
ROLLBACK/*!*/;
BINLOG '
hOacWg8BAAAAdwAAAHsAAAAAAAQANS43LjE2LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAACE5pxaEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AZ4Oydg=
'/*!*/;
# at 123
#180305 14:41:08 server id 1  end_log_pos 154 CRC32 0xd914b810 	Previous-GTIDs
# [empty]
# at 154
#180305 14:41:13 server id 1  end_log_pos 219 CRC32 0xaba45bc8 	GTID	last_committed=0	sequence_number=1
SET @@SESSION.GTID_NEXT= '27314c3f-2040-11e8-8e65-005056b75053:1'/*!*/;
# at 219
#180305 14:41:13 server id 1  end_log_pos 398 CRC32 0x1e38ed16 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1520232073/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549120/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
ALTER USER 'root'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*81F5E21E35407D884A6CD4A731AEBFB6AF209E1B'
/*!*/;
# at 398
#180305 14:41:13 server id 1  end_log_pos 463 CRC32 0x4cec02be 	GTID	last_committed=1	sequence_number=2
SET @@SESSION.GTID_NEXT= '27314c3f-2040-11e8-8e65-005056b75053:2'/*!*/;
# at 463
#180305 14:41:13 server id 1  end_log_pos 564 CRC32 0x05211c3f 	Query	thread_id=4	exec_time=0	error_code=0
SET TIMESTAMP=1520232073/*!*/;
drop user if exists 'root'@'%'
/*!*/;
# at 564
#180305 14:41:13 server id 1  end_log_pos 629 CRC32 0x9512c73e 	GTID	last_committed=2	sequence_number=3
SET @@SESSION.GTID_NEXT= '27314c3f-2040-11e8-8e65-005056b75053:3'/*!*/;
# at 629
#180305 14:41:13 server id 1  end_log_pos 809 CRC32 0xd410bbd4 	Query	thread_id=5	exec_time=0	error_code=0
SET TIMESTAMP=1520232073/*!*/;
CREATE USER 'root'@'%' IDENTIFIED WITH 'mysql_native_password' AS '*81F5E21E35407D884A6CD4A731AEBFB6AF209E1B'
/*!*/;
# at 809
#180305 14:41:13 server id 1  end_log_pos 874 CRC32 0x7d818f8c 	GTID	last_committed=3	sequence_number=4
SET @@SESSION.GTID_NEXT= '27314c3f-2040-11e8-8e65-005056b75053:4'/*!*/;
# at 874
#180305 14:41:13 server id 1  end_log_pos 1020 CRC32 0x20fe4021 	Query	thread_id=6	exec_time=0	error_code=0
SET TIMESTAMP=1520232073/*!*/;
GRANT ALL PRIVILEGES ON *.* TO 'root'@'%' WITH GRANT OPTION
/*!*/;
# at 1020
#180305 14:41:13 server id 1  end_log_pos 1085 CRC32 0x9d2c950c 	GTID	last_committed=4	sequence_number=5
SET @@SESSION.GTID_NEXT= '27314c3f-2040-11e8-8e65-005056b75053:5'/*!*/;
# at 1085
#180305 14:41:13 server id 1  end_log_pos 1228 CRC32 0x2069c848 	Query	thread_id=7	exec_time=0	error_code=0
SET TIMESTAMP=1520232073/*!*/;
GRANT USAGE ON *.* TO ''@'','root'@'%' WITH GRANT OPTION
/*!*/;
# at 1228
#180305 14:41:13 server id 1  end_log_pos 1293 CRC32 0x575afd8e 	GTID	last_committed=5	sequence_number=6
SET @@SESSION.GTID_NEXT= '27314c3f-2040-11e8-8e65-005056b75053:6'/*!*/;
# at 1293
#180305 14:41:13 server id 1  end_log_pos 1393 CRC32 0x9c1edf31 	Query	thread_id=8	exec_time=0	error_code=0
SET TIMESTAMP=1520232073/*!*/;
drop user if exists 'rpl'@'%'
/*!*/;
# at 1393
#180305 14:41:13 server id 1  end_log_pos 1458 CRC32 0xfe597a0d 	GTID	last_committed=6	sequence_number=7
SET @@SESSION.GTID_NEXT= '27314c3f-2040-11e8-8e65-005056b75053:7'/*!*/;
# at 1458
#180305 14:41:13 server id 1  end_log_pos 1637 CRC32 0x9c7544f3 	Query	thread_id=9	exec_time=0	error_code=0
SET TIMESTAMP=1520232073/*!*/;
CREATE USER 'rpl'@'%' IDENTIFIED WITH 'mysql_native_password' AS '*624459C87E534A126498ADE1B12E0C66EDA035A3'
............
............
You can see fifth gtid statements.

slave binlog information:
========
========binlog1:
========
........
........
# at 320
#170330 13:01:31 server id 1  end_log_pos 385 CRC32 0xf419f101  GTID    last_committed=1        sequence_number=2
SET @@SESSION.GTID_NEXT= 'be7815ee-0897-11e7-a197-c81f66de7923:2'/*!*/;
# at 385
#170330 13:01:31 server id 1  end_log_pos 518 CRC32 0x22aaebc3  Query   thread_id=6     exec_time=0     error_code=0
SET TIMESTAMP=1490850091/*!*/;
CREATE USER 'root'@'%' IDENTIFIED WITH 'mysql_native_password'
/*!*/;
# at 518
#170330 13:01:31 server id 1  end_log_pos 612 CRC32 0xac06eb86 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 612
#170330 13:01:31 server id 1  end_log_pos 656 CRC32 0xdb44eb00  Rotate to binlog.000002  pos: 4
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

You can see binlog has been accidentally rotated .

How to repeat:
Vsesion: MySQL Community Server  5.7.17
Platform:linux x64
my.cnf:
[client]
socket = /data/mysql/data5717/mysql.sock
[mysqld_safe]
plugin-dir = /usr/local/mysql5717/lib/mysql/plugin
[mysqld]
user = mysql
basedir = /usr/local/mysql5717
plugin-dir = /usr/local/mysql5717/lib/mysql/plugin
datadir = /data/mysql/data5717
port = 5717
socket = /data/mysql/data5717/mysql.sock
log-error=error.log
server-id = 1
skip-name-resolve
skip-host-cache
log_bin=binlog
back_log = 1000
max_connections = 4000
max_connect_errors = 6000
open_files_limit = 65535
table_open_cache = 8000
table_open_cache_instances=64
max_allowed_packet = 16M
max_heap_table_size = 1000M
tmp_table_size = 1000M
read_buffer_size = 8M
read_rnd_buffer_size = 8M
sort_buffer_size = 8M
join_buffer_size = 8M
key_buffer_size = 1024M
thread_cache_size = 200
query_cache_type = 0
performance_schema = 0
explicit_defaults_for_timestamp
lower_case_table_names = 1
skip-external-locking
innodb_file_per_table = 1
innodb_open_files = 5000
innodb_buffer_pool_size = 1G
innodb_buffer_pool_instances=1
sync_binlog = 0
innodb_read_io_threads=4
innodb_write_io_threads=4
innodb_max_purge_lag_delay=10000000
innodb_max_purge_lag=0
innodb_monitor_enable='%'
innodb_use_native_aio=1
innodb_checksums=off
innodb_support_xa=off
innodb_max_dirty_pages_pct_lwm=10
innodb_lru_scan_depth=4000
innodb_page_cleaners=4
innodb_thread_concurrency = 0
innodb_purge_threads = 4
innodb_flush_log_at_trx_commit = 0
innodb_log_buffer_size = 64M
innodb_log_file_size = 100M
innodb_log_files_in_group = 3
innodb_max_dirty_pages_pct = 90
innodb_lock_wait_timeout = 120
bulk_insert_buffer_size = 8M
interactive_timeout = 28800
wait_timeout = 28800
default_tmp_storage_engine=Memory
innodb_doublewrite=off
innodb_io_capacity=2000
innodb_io_capacity_max=5000
transaction-isolation=READ-COMMITTED
innodb_flush_method=O_DIRECT_NO_FSYNC
innodb_stats_persistent=1
innodb_adaptive_flushing = 1
innodb_flush_neighbors=0
innodb_adaptive_hash_index=0
innodb_monitor_disable = all
innodb_checksum_algorithm=NONE
master-info-repository=TABLE
relay-log-info-repository=TABLE
gtid-mode              = on
enforce-gtid-consistency
[mysqldump]
quick
max_allowed_packet = 16M
[mysql]
auto-rehash
prompt = "\\u@\\h : \\d \\R:\\m:\\s> "
[myisamchk]
key_buffer_size = 8M
sort_buffer_size = 8M
read_buffer = 4M
write_buffer = 4M

Repeat step:
1.Initialize a database using my.cnf
./bin/mysqld --defaults-file=my.cnf --initialize --user=mysql
2.Log on using socket,change root@localhost user password
3.Execute create user, authorization statement:

mysql> show master status;
+---------------+----------+--------------+------------------+------------------------------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+---------------+----------+--------------+------------------+------------------------------------------+
| binlog.000001 |      486 |              |                  | be7815ee-0897-11e7-a197-c81f66de7923:1-2 |
+---------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)
mysql> select user,host from mysql.user;
+-----------+-----------+
| user      | host      |
+-----------+-----------+
| mysql.sys | localhost |
| root      | localhost |
+-----------+-----------+
2 rows in set (0.00 sec)
mysql> CREATE USER 'test'@'%' IDENTIFIED by 'test';
Query OK, 0 rows affected (0.00 sec)

mysql> select user,host from mysql.user;
+-----------+-----------+
| user      | host      |
+-----------+-----------+
| test      | %         |
| mysql.sys | localhost |
| root      | localhost |
+-----------+-----------+
3 rows in set (0.00 sec)

mysql> show grants for 'test'@'%';
+----------------------------------+
| Grants for test@%                |
+----------------------------------+
| GRANT USAGE ON *.* TO 'test'@'%' |
+----------------------------------+
1 row in set (0.00 sec)

mysql> show master status;
+---------------+----------+--------------+------------------+------------------------------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+---------------+----------+--------------+------------------+------------------------------------------+
| binlog.000001 |      731 |              |                  | be7815ee-0897-11e7-a197-c81f66de7923:1-3 |
+---------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

mysql> GRANT USAGE ON *.* TO ''@'','test'@'%' WITH GRANT OPTION;    
ERROR 1133 (42000): Can't find any matching row in the user table
mysql> show master status;
+---------------+----------+--------------+------------------+------------------------------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set                        |
+---------------+----------+--------------+------------------+------------------------------------------+
| binlog.000002 |      194 |              |                  | be7815ee-0897-11e7-a197-c81f66de7923:1-3 |
+---------------+----------+--------------+------------------+------------------------------------------+
1 row in set (0.00 sec)

mysql> show grants for 'test'@'%';
+----------------------------------------------------+
| Grants for test@%                                  |
+----------------------------------------------------+
| GRANT USAGE ON *.* TO 'test'@'%' WITH GRANT OPTION |
+----------------------------------------------------+
1 row in set (0.00 sec)
mysql> show binlog events in "binlog.000001";
+---------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
| Log_name      | Pos | Event_type     | Server_id | End_log_pos | Info                                                                                                          |
+---------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
| binlog.000001 |   4 | Format_desc    |         1 |         123 | Server ver: 5.7.17-log, Binlog ver: 4                                                                         |
| binlog.000001 | 123 | Previous_gtids |         1 |         154 |                                                                                                               |
| binlog.000001 | 154 | Gtid           |         1 |         219 | SET @@SESSION.GTID_NEXT= 'be7815ee-0897-11e7-a197-c81f66de7923:1'                                             |
| binlog.000001 | 219 | Query          |         1 |         320 | drop user if exists 'test'@'%'                                                                                |
| binlog.000001 | 320 | Gtid           |         1 |         385 | SET @@SESSION.GTID_NEXT= 'be7815ee-0897-11e7-a197-c81f66de7923:2'                                             |
| binlog.000001 | 385 | Query          |         1 |         486 | drop user if exists 'test'@'%'                                                                                |
| binlog.000001 | 486 | Gtid           |         1 |         551 | SET @@SESSION.GTID_NEXT= 'be7815ee-0897-11e7-a197-c81f66de7923:3'                                             |
| binlog.000001 | 551 | Query          |         1 |         731 | CREATE USER 'test'@'%' IDENTIFIED WITH 'mysql_native_password' AS '*94BDCEBE19083CE2A1F959FD02F964C7AF4CFC29' |
| binlog.000001 | 731 | Incident       |         1 |         825 | #1 (LOST_EVENTS)                                                                                              |
| binlog.000001 | 825 | Rotate         |         1 |         869 | binlog.000002;pos=4                                                                                           |
+---------------+-----+----------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------+
10 rows in set (0.00 sec)

mysql> show binlog events in "binlog.000002";
+---------------+-----+----------------+-----------+-------------+------------------------------------------+
| Log_name      | Pos | Event_type     | Server_id | End_log_pos | Info                                     |
+---------------+-----+----------------+-----------+-------------+------------------------------------------+
| binlog.000002 |   4 | Format_desc    |         1 |         123 | Server ver: 5.7.17-log, Binlog ver: 4    |
| binlog.000002 | 123 | Previous_gtids |         1 |         194 | be7815ee-0897-11e7-a197-c81f66de7923:1-3 |
+---------------+-----+----------------+-----------+-------------+------------------------------------------+
2 rows in set (0.00 sec)

4.At the same time the error log will have the following information:
2017-03-30T05:21:34.180968Z 8 [ERROR] REVOKE/GRANT failed while granting/revoking privileges in databases. An incident event has been written to the binary log which will stop the slaves.

binlog information :
===========
===========binlog1
===========
........
........
# at 551
#170330 13:25:11 server id 1  end_log_pos 731 CRC32 0x6cbbc1f7  Query   thread_id=8     exec_time=0     error_code=0
SET TIMESTAMP=1490851511/*!*/;
CREATE USER 'test'@'%' IDENTIFIED WITH 'mysql_native_password' AS '*94BDCEBE19083CE2A1F959FD02F964C7AF4CFC29'
/*!*/;
# at 731
#170330 13:26:03 server id 1  end_log_pos 825 CRC32 0x41285f86 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 825
#170330 13:26:03 server id 1  end_log_pos 869 CRC32 0x70d00a82  Rotate to binlog.000002  pos: 4
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
===========
===========binlog2
===========
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170330 13:26:03 server id 1  end_log_pos 123 CRC32 0xba2f4418  Start: binlog v 4, server v 5.7.17-log created 170330 13:26:03
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
65bcWA8BAAAAdwAAAHsAAAABAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
ARhEL7o=
'/*!*/;
# at 123
#170330 13:26:03 server id 1  end_log_pos 194 CRC32 0xd5dc576b  Previous-GTIDs
# be7815ee-0897-11e7-a197-c81f66de7923:1-3
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
[31 Mar 2017 12:53] Umesh Shastry
Bug #85699 marked as duplicate of this
[31 Mar 2017 13:03] Umesh Shastry
Hello Ji Zhang,

Thank you for the report.

Thanks,
Umesh
[1 Apr 2017 8:37] Ji Zhang
In the production environment, the problem is 85695, and I repeat the situation is 85699, the reasons for these problems should be similar to the two, please give priority to the 85699, thank you.