| Bug #76379 | binlog_error_action doesn't handle some failures during binlog rotation | ||
|---|---|---|---|
| Submitted: | 18 Mar 2015 18:27 | Modified: | 7 Sep 2015 17:21 |
| Reporter: | Santosh Praneeth Banda | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.6.23, 5.7.6 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[31 Mar 2015 11:37]
MySQL Verification Team
Hello Santosh, Thank you for the report. Observed similar behavior with 5.6.23 source build. Thanks, Umesh
[31 Mar 2015 11:37]
MySQL Verification Team
// Build [umshastr@hod03]/export/umesh/server/source: md5sum mysql-5.6.23.tar.gz 60344f26eae136a267a0277407926e79 mysql-5.6.23.tar.gz // [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23: cmake -DCMAKE_INSTALL_PREFIX=/export/umesh/server/source/mysql-5.6.23 -DWITH_DEBUG=1 [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23: make [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23: make install [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23: cd mysql-test // Mtr [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23/mysql-test: ./mtr --mysqld="--log_bin=master-bin" --mysqld="--log_error=/export/umesh/server/source/mysql-5.6.23/mysql-test/var/mysqld.1/data/log.err" --start Logging: ./mtr --mysqld=--log_bin=master-bin --mysqld=--log_error=/export/umesh/server/source/mysql-5.6.23/mysql-test/var/mysqld.1/data/log.err --start 2015-03-31 13:30:21 10088 [Note] Plugin 'FEDERATED' is disabled. 2015-03-31 13:30:21 10088 [Note] Binlog end 2015-03-31 13:30:21 10088 [Note] Shutting down plugin 'CSV' 2015-03-31 13:30:21 10088 [Note] Shutting down plugin 'MyISAM' MySQL Version 5.6.23 Checking supported features... - SSL connections supported - binaries are debug compiled Using suites: main,sys_vars,binlog,federated,rpl,innodb,innodb_fts,innodb_zip,perfschema,funcs_1,opt_trace,parts,auth_sec Collecting tests... Checking leftover processes... - found old pid 9486 in 'mysqld.1.pid', killing it... process did not exist! Removing old var directory... Creating var directory '/export/umesh/server/source/mysql-5.6.23/mysql-test/var'... Installing system database... ============================================================================== TEST RESULT TIME (ms) or COMMENT -------------------------------------------------------------------------- worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 worker[1] Started [mysqld.1 - pid: 10113, winpid: 10113] worker[1] Using config for test main.1st worker[1] Port and socket path for server(s): worker[1] mysqld.1 13000 /export/umesh/server/source/mysql-5.6.23/mysql-test/var/tmp/mysqld.1.sock worker[1] Waiting for server(s) to exit... // Set parameters [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23: bin/mysql -uroot -p -S/export/umesh/server/source/mysql-5.6.23/mysql-test/var/tmp/mysqld.1.sock Enter password: Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 1 Server version: 5.6.23-debug-log Source distribution Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> set global binlog_error_action=ABORT_SERVER; set global debug='+d,error_unique_log_filename'; set global max_binlog_size=1024*1024; Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) mysql> // mysqlslap 500000 --concurrency=10 --auto-generate-sql-load-type=write --auto-generate-sql-add-autoincrement --csv=a --user=root bin/mysqlslap: Cannot run query INSERT INTO t1 VALUES (NULL,1137990260,'pvYr3YntZ2DoGrwWfL91bW9Epw8iO6vDuR4xrkqOe3Dum1PPEQQpwRvmO3Kg2FtobqlQQRj4Woq8hFZvhrkWBX8bRSFLc09BiuT0L44jsvrZ2GKczwyAS6dvakGAlP') ERROR : Can't generate a unique log-filename master-bin.(1-999) [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23: bin/mysqlslap --socket=/export/umesh/server/source/mysql-5.6.23/mysql-test/var/tmp/mysqld.1.sock --auto-generate-sql --number-of-queries=500000 --concurrency=10 --auto-generate-sql-load-type=write --auto-generate-sql-add-autoincrement --csv=a --user=root bin/mysqlslap: Cannot drop database 'mysqlslap' ERROR : Can't generate a unique log-filename master-bin.(1-999) [umshastr@hod03]/export/umesh/server/source/mysql-5.6.23: bin/mysqlslap --socket=/export/umesh/server/source/mysql-5.6.23/mysql-test/var/tmp/mysqld.1.sock --auto-generate-sql --number-of-queries=500000 --concurrency=10 --auto-generate-sql-load-type=write --auto-generate-sql-add-autoincrement --csv=a --user=root bin/mysqlslap: Cannot drop database 'mysqlslap' ERROR : Can't generate a unique log-filename master-bin.(1-999) // Check error log 2015-03-31 14:30:28 10114 [Note] Server hostname (bind-address): '*'; port: 13000 2015-03-31 14:30:28 10114 [Note] IPv6 is available. 2015-03-31 14:30:28 10114 [Note] - '::' resolves to '::'; 2015-03-31 14:30:28 10114 [Note] Server socket created on IP: '::'. 2015-03-31 14:30:28 10114 [Note] Event Scheduler: Loaded 0 events 2015-03-31 14:30:28 10114 [Note] /export/umesh/server/source/mysql-5.6.23/sql/mysqld: ready for connections. Version: '5.6.23-debug-log' socket: '/export/umesh/server/source/mysql-5.6.23/mysql-test/var/tmp/mysqld.1.sock' port: 13000 Source distribution 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:00 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:00 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:02 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:02 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31 14:31:04 10114 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31 14:31:04 10114 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the
[31 Mar 2015 12:40]
MySQL Verification Team
// 5.7.6 // Build [umshastr@hod03]/export/umesh/server/source: md5sum mysql-5.7.6-m16.tar.gz 4f30560e6abf96e7828604bb205d3556 mysql-5.7.6-m16.tar.gz // [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16: cmake -DCMAKE_INSTALL_PREFIX=/export/umesh/server/source/mysql-5.7.6-m16 -DWITH_DEBUG=1 -DDOWNLOAD_BOOST=1 -DWITH_BOOST=../boost [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16: make [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16: make install // Mtr [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16: cd mysql-test/ [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16/mysql-test: ./mtr --mysqld="--log_bin=master-bin" --mysqld="--log_error=/export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var/mysqld.1/data/log.err" --start Logging: ./mtr --mysqld=--log_bin=master-bin --mysqld=--log_error=/export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var/mysqld.1/data/log.err --start MySQL Version 5.7.6 Checking supported features... - SSL connections supported - binaries are debug compiled Using suites: main,sys_vars,binlog,federated,gis,rpl,innodb,innodb_gis,innodb_fts,innodb_zip,innodb_undo,perfschema,funcs_1,opt_trace,parts,auth_sec,query_rewrite_plugins,gcol Collecting tests... Removing old var directory... Creating var directory '/export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var'... Installing system database... ============================================================================== TEST RESULT TIME (ms) or COMMENT -------------------------------------------------------------------------- worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 worker[1] Started [mysqld.1 - pid: 28720, winpid: 28720] worker[1] Using config for test main.1st worker[1] Port and socket path for server(s): worker[1] mysqld.1 13000 /export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var/tmp/mysqld.1.sock worker[1] Waiting for server(s) to exit... // Set parameters [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16: bin/mysql -uroot -p -S/export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var/tmp/mysqld.1.sock Enter password: Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 2 Server version: 5.7.6-m16-debug-log Source distribution Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> set global binlog_error_action=ABORT_SERVER; set global debug='+d,error_unique_log_filename'; set global max_binlog_size=1024*1024; Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) mysql> // mysqlslap [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16: bin/mysqlslap --socket=/export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var/tmp/mysqld.1.sock --auto-generate-sql --number-of-queries=500000 --concurrency=10 --auto-generate-sql-load-type=write --auto-generate-sql-add-autoincrement --csv=a --user=root bin/mysqlslap: Cannot run query INSERT INTO t1 VALUES (NULL,1665728802,'8qB5MAR1caTvNFXB00HKShGa1uToGCMP2ZMHjpABFg6fnTioTz8pZGNQAkEJwckr9y0kfAvvq1QWM8IkzIZOaprdPxwMaY5bW5C977wy1MKNMe7EwZeWET7fRv1tRy') ERROR : Can't generate a unique log-filename master-bin.(1-999) [umshastr@hod03]/export/umesh/server/source/mysql-5.7.6-m16: bin/mysqlslap --socket=/export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var/tmp/mysqld.1.sock --auto-generate-sql --number-of-queries=500000 --concurrency=10 --auto-generate-sql-load-type=write --auto-generate-sql-add-autoincrement --csv=a --user=root bin/mysqlslap: Cannot drop database 'mysqlslap' ERROR : Can't generate a unique log-filename master-bin.(1-999) // Check error log 2015-03-31T12:34:24.153624Z 0 [Note] /export/umesh/server/source/mysql-5.7.6-m16/sql/mysqld: ready for connections. Version: '5.7.6-m16-debug-log' socket: '/export/umesh/server/source/mysql-5.7.6-m16/mysql-test/var/tmp/mysqld.1.sock' port: 13000 Source distribution 2015-03-31T12:37:09.220659Z 11 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31T12:37:09.220752Z 11 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31T12:37:09.221411Z 3 [Note] Aborted connection 3 to db: 'mysqlslap' user: 'root' host: 'localhost' (Got an error reading communication packets) 2015-03-31T12:37:09.221425Z 11 [Note] Aborted connection 11 to db: 'mysqlslap' user: 'root' host: 'localhost' (Got an error reading communication packets) 2015-03-31T12:37:09.221949Z 9 [Note] Aborted connection 9 to db: 'mysqlslap' user: 'root' host: 'localhost' (Got an error writing communication packets) 2015-03-31T12:37:09.221961Z 8 [Note] Aborted connection 8 to db: 'mysqlslap' user: 'root' host: 'localhost' (Got an error writing communication packets) 2015-03-31T12:37:09.222477Z 12 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31T12:37:09.222498Z 12 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31T12:37:09.222624Z 12 [Note] Aborted connection 12 to db: 'mysqlslap' user: 'root' host: 'localhost' (Can't generate a unique log-filename master-bin.(1-999) ) 2015-03-31T12:37:09.222700Z 5 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31T12:37:09.222725Z 5 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31T12:37:09.222990Z 5 [Note] Aborted connection 5 to db: 'mysqlslap' user: 'root' host: 'localhost' (Can't generate a unique log-filename master-bin.(1-999) ) 2015-03-31T12:37:09.223673Z 7 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31T12:37:09.223681Z 13 [Note] Aborted connection 13 to db: 'mysqlslap' user: 'root' host: 'localhost' (Got an error writing communication packets) 2015-03-31T12:37:09.223693Z 10 [Note] Aborted connection 10 to db: 'mysqlslap' user: 'root' host: 'localhost' (Got an error writing communication packets) 2015-03-31T12:37:09.223703Z 7 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31T12:37:09.223973Z 4 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31T12:37:09.224044Z 4 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31T12:37:09.224220Z 7 [Note] Aborted connection 7 to db: 'mysqlslap' user: 'root' host: 'localhost' (Can't generate a unique log-filename master-bin.(1-999) ) 2015-03-31T12:37:09.224340Z 4 [Note] Aborted connection 4 to db: 'mysqlslap' user: 'root' host: 'localhost' (Can't generate a unique log-filename master-bin.(1-999) ) 2015-03-31T12:37:11.743394Z 14 [ERROR] Can't generate a unique log-filename master-bin.(1-999) 2015-03-31T12:37:11.743424Z 14 [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. 2015-03-31T12:37:11.743689Z 14 [Note] Aborted connection 14 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error reading communication packets)
[7 Sep 2015 17:22]
Jon Stephens
Documented fix in the MySQL 5.6.27, 5.7.9, and 5.8.0 changelogs as follows:
The action specified for binlog_error_action was not alwys
honored correctly when a hardware failure occurred during log
rotation.
Closed.
Description: see how to repeat How to repeat: mtr --mysqld="--log_bin=master-bin" --start Modify configuration on the server. Execute "set global binlog_error_action=ABORT_SERVER; set global debug='+d,error_unique_log_filename'; set global max_binlog_size=1024*1024; mysqlslap --socket=$SERVER_SOCKET --auto-generate-sql --number-of-queries=500000 --concurrency=10 --auto-generate-sql-load-type=write --auto-generate-sql-add-autoincrement --csv=a --user=root Execute some more transactions on server and see they are getting succeeded. Check error log for the following error messages. [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. [ERROR] Can't generate a unique log-filename master-bin.(1-999) [ERROR] The server was unable to create a new log file. An incident event has been written to the binary log which will stop the slaves. [ERROR] Can't generate a unique log-filename master-bin.(1-999) In case of hardware errors in binlog partition during binlog rotate, we can see exactly the above scenario. All replicas break either either due to seeing incident event or simply because the dump thread cannot access binlog partition. binlog_error_action was developed for these purposes (i,e; to avoid server accepting writes even though binlog write are failing), but it doesn't handle the above case. Suggested fix: @@ -5154,7 +5154,10 @@ int MYSQL_BIN_LOG::new_file_impl(bool need_lock_log, Format_description_log_even new file name in the current binary log file. */ if ((error= generate_new_name(new_name, name))) + { + close_on_error = TRUE; goto end; + }