Fix several bugs in error handling for failed binlog write: - Failure in write_cache() not logged due to bogus assignment of write_error. - Assertion in net_end_statement() due to not calling my_error() in error case. - Not resetting transaction cache after failed binlog write. - XtraDB not releasing prepare_commit_mutex in innobase_rollback() when binlogging fails. Also includes test case for these conditions. Note that there is still the problem that we can leave partially written transactions in the binlog file; that problem is not solved by this patch. === modified file 'sql/log.cc' --- mysql-test/suite/binlog/r/binlog_ioerr.result | 28 +++++++++++++++++++++++++ mysql-test/suite/binlog/t/binlog_ioerr.test | 29 ++++++++++++++++++++++++++ sql/log.cc | 15 +++++++------ storage/xtradb/handler/ha_innodb.cc | 4 +++ 4 files changed, 69 insertions(+), 7 deletions(-) Index: sql/log.cc =================================================================== --- sql/log.cc.orig 2010-05-05 10:45:59.000000000 +0200 +++ sql/log.cc 2010-05-05 11:03:22.000000000 +0200 @@ -208,7 +208,7 @@ public: completely. */ void reset() { - if (!empty()) + if (trans_log.type != WRITE_CACHE || !empty()) truncate(0); before_stmt_pos= MY_OFF_T_UNDEF; incident= FALSE; @@ -4681,6 +4681,7 @@ int MYSQL_BIN_LOG::write_cache(IO_CACHE } /* Write data to the binary log file */ + DBUG_EXECUTE_IF("fail_binlog_write_1", return ER_ERROR_ON_WRITE;); if (my_b_write(&log_file, cache->read_pos, length)) return ER_ERROR_ON_WRITE; cache->read_pos=cache->read_end; // Mark buffer used up @@ -4781,6 +4782,7 @@ bool MYSQL_BIN_LOG::write_transaction_to if (likely(is_open())) // Should always be true { IO_CACHE *cache= &trx_data->trans_log; + write_error= 0; /* We only bother to write to the binary log if there is anything @@ -4808,9 +4810,8 @@ bool MYSQL_BIN_LOG::write_transaction_to DBUG_EXECUTE_IF("crash_before_writing_xid", { - if ((write_error= write_cache(cache))) - DBUG_PRINT("info", ("error writing binlog cache: %d", - write_error)); + if (write_cache(cache)) + DBUG_PRINT("info", ("error writing binlog cache")); else flush_and_sync(); @@ -4818,7 +4819,7 @@ bool MYSQL_BIN_LOG::write_transaction_to abort(); }); - if ((write_error= write_cache(cache))) + if (write_cache(cache)) goto err; if (commit_event && commit_event->write(&log_file)) @@ -4832,7 +4833,7 @@ bool MYSQL_BIN_LOG::write_transaction_to DBUG_EXECUTE_IF("half_binlogged_transaction", DBUG_ABORT();); if (cache->error) // Error on read { - sql_print_error(ER(ER_ERROR_ON_READ), cache->file_name, errno); + my_error(ER_ERROR_ON_READ, MYF(ME_NOREFRESH), cache->file_name, errno); write_error=1; // Don't give more errors goto err; } @@ -4864,7 +4865,7 @@ err: if (!write_error) { write_error= 1; - sql_print_error(ER(ER_ERROR_ON_WRITE), name, errno); + my_error(ER_ERROR_ON_WRITE, MYF(ME_NOREFRESH), name, errno); } VOID(pthread_mutex_unlock(&LOCK_log)); DBUG_RETURN(1); Index: storage/xtradb/handler/ha_innodb.cc =================================================================== --- storage/xtradb/handler/ha_innodb.cc.orig 2010-05-05 10:45:41.000000000 +0200 +++ storage/xtradb/handler/ha_innodb.cc 2010-05-05 10:45:59.000000000 +0200 @@ -2866,6 +2866,10 @@ innobase_rollback( || !thd_test_options(thd, OPTION_NOT_AUTOCOMMIT | OPTION_BEGIN)) { error = trx_rollback_for_mysql(trx); + if (trx->active_trans == 2) { + + pthread_mutex_unlock(&prepare_commit_mutex); + } trx->active_trans = 0; } else { error = trx_rollback_last_sql_stat_for_mysql(trx); Index: mysql-test/suite/binlog/r/binlog_ioerr.result =================================================================== --- /dev/null 1970-01-01 00:00:00.000000000 +0000 +++ mysql-test/suite/binlog/r/binlog_ioerr.result 2010-05-05 11:02:04.000000000 +0200 @@ -0,0 +1,28 @@ +CALL mtr.add_suppression("Error writing file 'master-bin'"); +RESET MASTER; +CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb; +INSERT INTO t1 VALUES(0); +SET SESSION debug='+d,fail_binlog_write_1'; +INSERT INTO t1 VALUES(1); +ERROR HY000: Error writing file 'master-bin' (errno: 22) +INSERT INTO t1 VALUES(2); +ERROR HY000: Error writing file 'master-bin' (errno: 22) +SET SESSION debug=''; +INSERT INTO t1 VALUES(3); +SELECT * FROM t1; +a +0 +3 +SHOW BINLOG EVENTS; +Log_name Pos Event_type Server_id End_log_pos Info +BINLOG POS Format_desc 1 ENDPOS Server ver: #, Binlog ver: # +BINLOG POS Query 1 ENDPOS use `test`; CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb +BINLOG POS Query 1 ENDPOS BEGIN +BINLOG POS Query 1 ENDPOS use `test`; INSERT INTO t1 VALUES(0) +BINLOG POS Xid 1 ENDPOS COMMIT /* XID */ +BINLOG POS Query 1 ENDPOS BEGIN +BINLOG POS Query 1 ENDPOS BEGIN +BINLOG POS Query 1 ENDPOS BEGIN +BINLOG POS Query 1 ENDPOS use `test`; INSERT INTO t1 VALUES(3) +BINLOG POS Xid 1 ENDPOS COMMIT /* XID */ +DROP TABLE t1; Index: mysql-test/suite/binlog/t/binlog_ioerr.test =================================================================== --- /dev/null 1970-01-01 00:00:00.000000000 +0000 +++ mysql-test/suite/binlog/t/binlog_ioerr.test 2010-05-05 11:03:35.000000000 +0200 @@ -0,0 +1,29 @@ +source include/have_debug.inc; +source include/have_innodb.inc; +source include/have_log_bin.inc; +source include/have_binlog_format_mixed_or_statement.inc; + +CALL mtr.add_suppression("Error writing file 'master-bin'"); + +RESET MASTER; + +CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb; +INSERT INTO t1 VALUES(0); +SET SESSION debug='+d,fail_binlog_write_1'; +--error ER_ERROR_ON_WRITE +INSERT INTO t1 VALUES(1); +--error ER_ERROR_ON_WRITE +INSERT INTO t1 VALUES(2); +SET SESSION debug=''; +INSERT INTO t1 VALUES(3); +SELECT * FROM t1; + +# Actually the output from this currently shows a bug. +# The injected IO error leaves partially written transactions in the binlog in +# the form of stray "BEGIN" events. +# These should disappear from the output if binlog error handling is improved. +--replace_regex /\/\* xid=.* \*\//\/* XID *\// /Server ver: .*, Binlog ver: .*/Server ver: #, Binlog ver: #/ /table_id: [0-9]+/table_id: #/ +--replace_column 1 BINLOG 2 POS 5 ENDPOS +SHOW BINLOG EVENTS; + +DROP TABLE t1;