Bug #68892 Invalid use of GRANT command breaks replication
Submitted: 9 Apr 2013 0:05 Modified: 19 Sep 2013 14:16
Reporter: Maciej Dobrzanski Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.6 OS:Any
Assigned to:
Tags: grant, replication, revoke

[9 Apr 2013 0:05] Maciej Dobrzanski
Description:
Issuing a GRANT statement with invalid parameters causes master to write LOST_EVENTS event into its binary logs, which effectively breaks replication on all slaves:

*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 18675
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000003
          Read_Master_Log_Pos: 120
               Relay_Log_File: mysql_sandbox18676-relay-bin.000004
                Relay_Log_Pos: 283
        Relay_Master_Log_File: mysql-bin.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1590
                   Last_Error: The incident LOST_EVENTS occured on the master. Message: error writing to the binary log
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 120
              Relay_Log_Space: 1155
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 1590
               Last_SQL_Error: The incident LOST_EVENTS occured on the master. Message: error writing to the binary log
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
                  Master_UUID: 4d9b6b99-a0a4-11e2-950b-00270e0ffdb6
             Master_Info_File: /home/psce/sandboxes/rsandbox_mysql-5_6_10/node1/data/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: 
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 130409 01:54:13
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set: 
            Executed_Gtid_Set: 
                Auto_Position: 0

How to repeat:
Issue the following statement:

master [localhost] {root} (mysql) > GRANT FILE ON test.* TO test@127.0.0.1;
ERROR 1221 (HY000): Incorrect usage of DB GRANT and GLOBAL PRIVILEGES

Instead of writing the bad statement or ignoring it altogether, MySQL writes the following event into the binary log:

#130409  1:54:13 server id 1  end_log_pos 177 CRC32 0x110405fc 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 177
[10 Apr 2013 13:00] Umesh Shastry
Hello Maciej,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[10 Apr 2013 13:01] Umesh Shastry
## invalid Grant breaks replication

## Master
mysql> show processlist;
+----+------+-----------------+------+-------------+------+-----------------------------------------------------------------------+------------------+
| Id | User | Host            | db   | Command     | Time | State                                                                 | Info             |
+----+------+-----------------+------+-------------+------+-----------------------------------------------------------------------+------------------+
|  1 | root | localhost:40250 | test | Query       |    0 | init                                                                  | show processlist |
|  2 | repl | localhost:36515 | NULL | Binlog Dump |   16 | Master has sent all binlog to slave; waiting for binlog to be updated | NULL             |
+----+------+-----------------+------+-------------+------+-----------------------------------------------------------------------+------------------+
2 rows in set (0.00 sec)

mysql> GRANT FILE ON test.* TO test@127.0.0.1;
ERROR 1221 (HY000): Incorrect usage of DB GRANT and GLOBAL PRIVILEGES

## Slave

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: localhost
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: ushastry-bin.000002
          Read_Master_Log_Pos: 120
               Relay_Log_File: ushastry-relay-bin.000002
                Relay_Log_Pos: 286
        Relay_Master_Log_File: ushastry-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1590
                   Last_Error: The incident LOST_EVENTS occured on the master. Message: error writing to the binary log
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 817
              Relay_Log_Space: 1087
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 1590
               Last_SQL_Error: The incident LOST_EVENTS occured on the master. Message: error writing to the binary log
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
                  Master_UUID: c837062c-a1d9-11e2-9ced-0800272e2cce
             Master_Info_File: /tmp/5610slave_/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: 
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 130410 18:06:40
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set: 
            Executed_Gtid_Set: 
                Auto_Position: 0
1 row in set (0.00 sec)

#130410 18:06:40 server id 1  end_log_pos 874 CRC32 0x4d815dbc 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 874
#130410 18:06:40 server id 1  end_log_pos 924 CRC32 0x9079cacf 	Rotate to ushastry-bin.000002  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
[root@ushastry 5610_]# /home/ushastry/mybuilds/mysql-5.6.10/bin/mysqlbinlog -v --base64-output=DECODE-ROWS ushastry-bin.000002
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130410 18:06:40 server id 1  end_log_pos 120 CRC32 0x9d129815 	Start: binlog v 4, server v 5.6.10-debug-log created 130410 18:06:40
# Warning: this binlog is either in use or was not closed properly.
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
[root@ushastry 5610_]#
[30 Apr 2013 20:21] Paul Court
Also seeing this in a 5.6.11 install.

Not quite sure how the severity scales are generally used, but shouldn't a trivial command that breaks the one feature that is being splatted all over the homepage as having significant improvements be a little higher than "non-critical" ?
[30 May 2013 6:09] Szilard Gyorgy
HI 

There is any update with this problem ? 
Every time when somebody change some rights the replication crash.

Also the Second_behind_master value is flapping - in one moment I have 10000s a minute after 0 and after another one minute is back to 100000.
And how can be Second_behind_master 0 when I use SQL_Delay: 3600 ? 

Best,
Szilard Gyorgy
[8 Aug 2013 4:03] Ronald Bradford
I am getting the same error with 5.6.13-log.
Extremely annoying because now I have to fix 6 slaves, all because of an SQL Statement that should have failed and never sent to the binary log????

This is more then non-critical!
[9 Aug 2013 12:36] Moritz Schuepp
Replication also breaks if you revoke the grant option from a database or table if the grant is not defined.

mysql> REVOKE GRANT OPTION ON `testdb`.`test_table` FROM 'testuser'@'127.0.0.1';
ERROR 1141 (42000): There is no such grant defined for user 'testuser' on host '127.0.0.1'

Leads to the same "Incident: LOST_EVENTS"-Entry in binary log and makes the slaves stop.

phpMyAdmin for example removes the grant option by default if you modify user rights even if there is no grant option defined for that user, so Replication always breaks if you user phpMyAdmin to modify user rights for a certain table on which the user has no grant option.
[28 Aug 2013 11:07] Jason Temple
Hello,

This bug was created in April.  Here we are with a critical bug (not listed here as such, but that is not relevant), and four months later, there has not been any resolution.

Can we expect a patch for this any time, or should we just give up on ever issuing GRANT commands if we want to use replication?

Thanks,

Jason
[17 Sep 2013 2:25] James Day
I've updated the severity from 3 to 2 to show the severity we've actually been using for this. The fix for this is likely to be released within a few months. As usual, issues found in testing could delay things, so don't count on it until it is actually released.

James Day, MySQL Senior Principal Support Engineer, Oracle
[19 Sep 2013 14:16] Jon Stephens
Fixed in 5.6+. Documented fix in the 5.6.15 and 5.7.3 changelogs, as follows:

        Issuing a GRANT statement with invalid parameters caused the
        master to write LOST_EVENTS events into its binary logs, causing
        replication to stop. Now such cases, if one or more grants or
        revocations of privileges are successful, an incident is written
        to the log; otherwise, only a warning is logged.
      

Closed.
[4 Dec 2013 11:30] Laurynas Biveinis
5.6$ bzr log -r 5449
------------------------------------------------------------
revno: 5449
committer: Bill Qu <bill.qu@Oracle.com>
branch nick: mysql-5.6
timestamp: Fri 2013-09-13 10:29:30 +0800
message:
  Bug #16629195 	INVALID USE OF GRANT COMMAND BREAKS REPLICATION
  
  To failed REVOKE/GRANT statement, we wrote an incident event
  into binary log, which breaks replication on all slaves.
  
  Before ACLs are changed to execute fully or none at all,
  we go with the following fix, write an incident if one
  or more users are granted/revoked successfully (it has
  a partial execution), otherwise, do not write an incident,
  just log a warning.

5.6$ bzr log -r 5450
------------------------------------------------------------
revno: 5450
committer: Bill Qu <bill.qu@Oracle.com>
branch nick: mysql-5.6
timestamp: Fri 2013-09-13 14:24:17 +0800
message:
  Bug #16629195 	INVALID USE OF GRANT COMMAND BREAKS REPLICATION
  
  Post-fix failed thread_pool.thread_pool_connect.
[8 Jan 2014 16:50] Jeff Bilbro
We just hit this bug running 5.6.14.  I see a fix is available, but that doesn't help me much right now.  Can someone tell me how to get replication working again?
[9 Jun 2014 10:29] Leandro Morgado
Jeff, if you don't need this GRANT to be executed on the slave, simply skip the event:
  http://dev.mysql.com/doc/refman/5.1/en/set-global-sql-slave-skip-counter.html

Alternatively, you can look into executing the same GRANT on the slave to synchronize the master and slave user accounts. 

Please be careful with sql_slave_skip_counter as skipping the wrong transactions can cause master and slave to go out of sync.

As a last resort, a rebuild of the slave will also work.
[11 Aug 2014 22:17] Leandro Morgado
If using GTIDs, please see Scott's comment in Bug 69811:
===
[2 Jul 15:15] Scott Noyes
The problem is that the LOST_EVENT does not have a GTID, so we can't replace it with an empty transaction. The workaround is to manually execute the next transaction, then reset replication.

Use mysqlbinlog to find the next transaction. It is probably the first transaction in the next log file after the LOST_EVENT. Copy everything up to the COMMIT for that transaction, being sure to include the SET @@SESSION.GTID_NEXT. Even if you're using ROW format, you can still run BINLOG row events in the command line client.

STOP SLAVE;
Run the transaction copied above.
The mysqlbinlog output sets the delimiter to /*!*/;, so set it back:
DELIMITER ;

SET GTID_NEXT=automatic;
RESET SLAVE;
START SLAVE;
====
[3 Mar 18:01] monty solomon
This happens on 5.7.17. Please update the documentation to reflect that this can happen and how to fix it when it does.

               Slave_IO_State: Waiting for master to send event
                  Master_Host: bold-band
                  Master_User: SUSR_Repl
                  Master_Port: 3306
                Connect_Retry: 15
              Master_Log_File: bin.004161
          Read_Master_Log_Pos: 44021782
               Relay_Log_File: relay.002528
                Relay_Log_Pos: 355
        Relay_Master_Log_File: bin.004157
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1590
                   Last_Error: The incident LOST_EVENTS occured on the master. Message: REVOKE/GRANT failed while granting/revoking privileges in databases.
[3 Mar 18:24] Paul Court
Wait a min, this is still happening 4 YEARS LATER, and the fix is "put a work around in the docs"!?
[3 Mar 19:20] monty solomon
The previous comments in this bug report are how to work around the bug.
[3 Mar 19:45] monty solomon
Here are the entries from the relay log files.

relay.002528
# at 355
#170227 21:58:00 server id 3569742263  end_log_pos 368 CRC32 0xd7679266 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 449
#170228 18:27:44 server id 3152558033  end_log_pos 492 CRC32 0xcca5a878         Rotate to relay.002529  pos: 4

relay.002530
# at 355
#170227 21:58:00 server id 3569742263  end_log_pos 368 CRC32 0xd7679266 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 449
#170228 18:27:44 server id 3152558033  end_log_pos 492 CRC32 0xdb65110b         Rotate to relay.002531  pos: 4

relay.002532
# at 887854
#170227 22:38:49 server id 3569742263  end_log_pos 887867 CRC32 0x88d1b178 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 887948
#170228 18:27:44 server id 3152558033  end_log_pos 887991 CRC32 0x19a4330f      Rotate to relay.002533  pos: 4

relay.002534
# at 2432
#170227 22:38:54 server id 3569742263  end_log_pos 2405 CRC32 0x071799a4 
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 2526
#170228 18:27:44 server id 3152558033  end_log_pos 2569 CRC32 0x11addf2a        Rotate to relay.002535  pos: 4