This commit fixes several bugs in error handling around disk full when writing the statement/transaction binlog caches: 1. If the error occurs during a non-transactional statement, the code attempts to binlog the partially executed statement (as it cannot roll back). The stmt_cache->error was still set from the disk full error. This caused MYSQL_BIN_LOG::write_cache() to get an error while trying to read the cache to copy it to the binlog. This was then wrongly interpreted as a disk full error writing to the binlog file. As a result, a partial event group containing just a GTID event (no query or commit) was binlogged. Fixed by checking if an error is set in the statement cache, and if so binlog an INCIDENT event instead of a corrupt event group. 2. For LOAD DATA LOCAL INFILE, if a disk full error occured while writing to the statement cache, the code would attempt to abort and read-and-discard any remaining data sent by the client. The discard code would however continue trying to write data to the statement cache, and wrongly interpret another disk full error as end-of-file from the client. This left the client connection with extra data which corrupts the communication for the next command, as well as again causing an corrupt/incomplete event to be binlogged. Fixed by restoring the default read function before reading any remaining data from the client connection. Signed-off-by: Kristian Nielsen <knielsen@knielsen-hq.org> --- .../rpl_binlog_cache_disk_full_loaddata.test | 45 +++++++ .../rpl/t/rpl_binlog_cache_disk_full_row.test | 59 +++++++++ sql/log.cc | 121 ++++++++++++------ sql/sql_load.cc | 4 + sql/sql_repl.cc | 34 ++++- 5 files changed, 224 insertions(+), 39 deletions(-) create mode 100644 mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_loaddata.test create mode 100644 mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_row.test diff --git a/mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_loaddata.test b/mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_loaddata.test new file mode 100644 index 00000000000..be4399a52ac --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_loaddata.test @@ -0,0 +1,45 @@ +--source include/have_binlog_format_statement.inc +--source include/have_debug.inc +--source include/master-slave.inc + +--connection master +# Set minimal cache size so smaller transaction can trigger spill to disk. +SET @save_binlog_stmt_cache_size= @@GLOBAL.binlog_stmt_cache_size; +SET GLOBAL binlog_stmt_cache_size= 4096; + +CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=MyISAM; + +FLUSH STATUS; +SHOW STATUS LIKE "binlog_stmt_cache%"; +SET @old_dbug= @@SESSION.debug_dbug; +SET SESSION debug_dbug="+d,load_data_binlog_cache_error"; +--error 3 +LOAD DATA CONCURRENT LOCAL INFILE 'std_data/bug30435_5k.txt' + REPLACE INTO TABLE t1 (a); +SET SESSION debug_dbug= @old_dbug; +SHOW STATUS LIKE "binlog_stmt_cache%"; +# The actual number of rows left after the disk full error may change as +# binlog event sizes are modified. So here we just test that we get partial +# update from the last INSERT..SELECT that gets disk full error. +SELECT IF(COUNT(*) > 0 AND COUNT(*) < 5000, + "ok", + CONCAT("ERROR! Row count ", COUNT(*), " not as expected for partially executed query")) + AS check_result + FROM t1; + +--save_master_pos + +--connection slave +--let $slave_sql_errno= 1590 +--source include/wait_for_slave_sql_error_and_skip.inc + +--sync_with_master +SELECT COUNT(*) FROM t1; + +# Cleanup + +--connection master +SET GLOBAL binlog_stmt_cache_size= @save_binlog_stmt_cache_size; +DROP TABLE t1; + +--source include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_row.test b/mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_row.test new file mode 100644 index 00000000000..eb67eca5071 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_binlog_cache_disk_full_row.test @@ -0,0 +1,59 @@ +--source include/have_binlog_format_row.inc +--source include/have_debug.inc +--source include/master-slave.inc + +--connection master +# Set minimal cache size so smaller transaction can trigger spill to disk. +SET @save_binlog_stmt_cache_size= @@GLOBAL.binlog_stmt_cache_size; +SET GLOBAL binlog_stmt_cache_size= 4096; + +CREATE TABLE t1 (a INT PRIMARY KEY, b VARCHAR(255)) ENGINE=MyISAM; + +FLUSH STATUS; +SHOW STATUS LIKE "binlog_stmt_cache%"; +INSERT INTO t1 VALUES (0, CONCAT("?", "-", REPEAT("x", 200))); +INSERT INTO t1 SELECT a+1, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +INSERT INTO t1 SELECT a+2, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +INSERT INTO t1 SELECT a+4, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +INSERT INTO t1 SELECT a+8, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +INSERT INTO t1 SELECT a+16, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +INSERT INTO t1 SELECT a+32, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +INSERT INTO t1 SELECT a+64, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +INSERT INTO t1 SELECT a+128, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +SHOW STATUS LIKE "binlog_stmt_cache%"; + +SET @old_dbug= @@SESSION.debug_dbug; +SET SESSION debug_dbug="+d,simulate_disk_full_at_flush_pending"; +--error 3 +INSERT INTO t1 SELECT a+256, CONCAT(a, "-", REPEAT("x", 200)) FROM t1; +SET SESSION debug_dbug= @old_dbug; +SHOW STATUS LIKE "binlog_stmt_cache%"; +# The actual number of rows left after the disk full error may change as +# binlog event sizes are modified. So here we just test that we get partial +# update from the last INSERT..SELECT that gets disk full error. +SELECT IF(COUNT(*) > 256 AND COUNT(*) < 512, + "ok", + CONCAT("ERROR! Row count ", COUNT(*), " not as expected for partially executed query")) + AS check_result + FROM t1; + +# A random extra event that helped show the bug that a partial event +# group was binlogged. +ALTER TABLE t1 COMMENT '<mumble>'; + +--save_master_pos + +--connection slave +--let $slave_sql_errno= 1590 +--source include/wait_for_slave_sql_error_and_skip.inc + +--sync_with_master +SELECT COUNT(*) FROM t1; + +# Cleanup + +--connection master +SET GLOBAL binlog_stmt_cache_size= @save_binlog_stmt_cache_size; +DROP TABLE t1; + +--source include/rpl_end.inc diff --git a/sql/log.cc b/sql/log.cc index e7292064747..8c93f9adf41 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -6005,8 +6005,17 @@ MYSQL_BIN_LOG::flush_and_set_pending_rows_event(THD *thd, /* Write pending event to the cache. */ +#ifndef DBUG_OFF + bool clear_dbug= false; +#endif DBUG_EXECUTE_IF("simulate_disk_full_at_flush_pending", - {DBUG_SET("+d,simulate_file_write_error");}); + { + if (my_b_tell(&cache_data->cache_log) > 10000) + { + DBUG_SET("+d,simulate_file_write_error"); + clear_dbug= true; + } + }); if (writer.write(pending)) { set_write_error(thd, is_transactional); @@ -6016,9 +6025,17 @@ MYSQL_BIN_LOG::flush_and_set_pending_rows_event(THD *thd, delete pending; cache_data->set_pending(NULL); DBUG_EXECUTE_IF("simulate_disk_full_at_flush_pending", - {DBUG_SET("-d,simulate_file_write_error");}); + { + if (clear_dbug) + DBUG_SET("-d,simulate_file_write_error"); + }); DBUG_RETURN(1); } + DBUG_EXECUTE_IF("simulate_disk_full_at_flush_pending", + { + if (clear_dbug) + DBUG_SET("-d,simulate_file_write_error"); + }); delete pending; } @@ -8337,51 +8354,83 @@ MYSQL_BIN_LOG::write_transaction_or_stmt(group_commit_entry *entry, binlog_cache_mngr *mngr= entry->cache_mngr; DBUG_ENTER("MYSQL_BIN_LOG::write_transaction_or_stmt"); - if (write_gtid_event(entry->thd, false, entry->using_trx_cache, commit_id)) - DBUG_RETURN(ER_ERROR_ON_WRITE); + bool do_stmt= entry->using_stmt_cache && !mngr->stmt_cache.empty(); + bool do_trx= entry->using_trx_cache && !mngr->trx_cache.empty(); + IO_CACHE *stmt_cache= mngr->get_binlog_cache_log(FALSE); + IO_CACHE *trx_cache= mngr->get_binlog_cache_log(TRUE); - if (entry->using_stmt_cache && !mngr->stmt_cache.empty() && - write_cache(entry->thd, mngr->get_binlog_cache_log(FALSE))) + if (likely(!( (do_stmt && stmt_cache->error) || + (do_trx && trx_cache->error) ))) { - entry->error_cache= &mngr->stmt_cache.cache_log; - DBUG_RETURN(ER_ERROR_ON_WRITE); - } + if (write_gtid_event(entry->thd, false, entry->using_trx_cache, commit_id)) + DBUG_RETURN(ER_ERROR_ON_WRITE); - if (entry->using_trx_cache && !mngr->trx_cache.empty()) - { - DBUG_EXECUTE_IF("crash_before_writing_xid", + if (do_stmt && + write_cache(entry->thd, mngr->get_binlog_cache_log(FALSE))) + { + entry->error_cache= &mngr->stmt_cache.cache_log; + DBUG_RETURN(ER_ERROR_ON_WRITE); + } + + if (do_trx) + { + DBUG_EXECUTE_IF("crash_before_writing_xid", + { + if ((write_cache(entry->thd, + mngr->get_binlog_cache_log(TRUE)))) + DBUG_PRINT("info", ("error writing binlog cache")); + else + flush_and_sync(0); + + DBUG_PRINT("info", ("crashing before writing xid")); + DBUG_SUICIDE(); + }); + + if (write_cache(entry->thd, mngr->get_binlog_cache_log(TRUE))) + { + entry->error_cache= &mngr->trx_cache.cache_log; + DBUG_RETURN(ER_ERROR_ON_WRITE); + } + } + + DBUG_EXECUTE_IF("inject_error_writing_xid", { - if ((write_cache(entry->thd, - mngr->get_binlog_cache_log(TRUE)))) - DBUG_PRINT("info", ("error writing binlog cache")); - else - flush_and_sync(0); - - DBUG_PRINT("info", ("crashing before writing xid")); - DBUG_SUICIDE(); + entry->error_cache= NULL; + errno= 28; + DBUG_RETURN(ER_ERROR_ON_WRITE); }); - if (write_cache(entry->thd, mngr->get_binlog_cache_log(TRUE))) + if (write_event(entry->end_event)) { - entry->error_cache= &mngr->trx_cache.cache_log; + entry->error_cache= NULL; DBUG_RETURN(ER_ERROR_ON_WRITE); } + status_var_add(entry->thd->status_var.binlog_bytes_written, + entry->end_event->data_written); } + else + { + /* + If writing the IO_CACHE caused an error, we musn't flush it to the main + binlog, it's probably corrupt/truncated. - DBUG_EXECUTE_IF("inject_error_writing_xid", - { - entry->error_cache= NULL; - errno= 28; - DBUG_RETURN(ER_ERROR_ON_WRITE); - }); + We clear the error (otherwise it would be interpreted as an error + _reading_ the IO_CACHE). - if (write_event(entry->end_event)) - { - entry->error_cache= NULL; - DBUG_RETURN(ER_ERROR_ON_WRITE); + And generate an incident event, if one wasn't set already. + */ + stmt_cache->error= trx_cache->error= 0; + if (!entry->incident_event) + { + Incident_log_event inc_ev(entry->thd, INCIDENT_LOST_EVENTS, + &write_error_msg); + if (write_event(&inc_ev)) + { + entry->error_cache= NULL; + DBUG_RETURN(ER_ERROR_ON_WRITE); + } + } } - status_var_add(entry->thd->status_var.binlog_bytes_written, - entry->end_event->data_written); if (entry->incident_event) { @@ -8392,12 +8441,12 @@ MYSQL_BIN_LOG::write_transaction_or_stmt(group_commit_entry *entry, } } - if (unlikely(mngr->get_binlog_cache_log(FALSE)->error)) + if (unlikely(do_stmt && stmt_cache->error)) { entry->error_cache= &mngr->stmt_cache.cache_log; DBUG_RETURN(ER_ERROR_ON_WRITE); } - if (unlikely(mngr->get_binlog_cache_log(TRUE)->error)) // Error on read + if (unlikely(do_trx && trx_cache->error)) // Error on read { entry->error_cache= &mngr->trx_cache.cache_log; DBUG_RETURN(ER_ERROR_ON_WRITE); diff --git a/sql/sql_load.cc b/sql/sql_load.cc index 8264286a022..cc4361b0472 100644 --- a/sql/sql_load.cc +++ b/sql/sql_load.cc @@ -253,6 +253,10 @@ class READ_INFO: public Load_data_param */ void skip_data_till_eof() { +#ifndef EMBEDDED_LIBRARY + if (mysql_bin_log.is_open()) + cache.read_function= cache.real_read_function; +#endif while (GET != my_b_EOF) ; } diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc index d9b93742195..0d2e61f7f59 100644 --- a/sql/sql_repl.cc +++ b/sql/sql_repl.cc @@ -4499,6 +4499,10 @@ int log_loaded_block(IO_CACHE* file, uchar *Buffer, size_t Count) /* buffer contains position where we started last read */ uchar* buffer= (uchar*) my_b_get_buffer_start(file); uint max_event_size= lf_info->thd->variables.max_allowed_packet; + int res; +#ifndef DBUG_OFF + bool did_dbug_inject= false; +#endif if (lf_info->thd->is_current_stmt_binlog_format_row()) goto ret; @@ -4506,6 +4510,19 @@ int log_loaded_block(IO_CACHE* file, uchar *Buffer, size_t Count) lf_info->last_pos_in_file >= my_b_get_pos_in_file(file)) goto ret; + DBUG_EXECUTE_IF("load_data_binlog_cache_error", + { + /* + Simulate "disk full" error in the middle of writing to + the binlog cache. + */ + if (lf_info->last_pos_in_file >= 2*4096) + { + DBUG_SET("+d,simulate_file_write_error"); + did_dbug_inject= true; + } + };); + for (block_len= (uint) (my_b_get_bytes_in_buffer(file)); block_len > 0; buffer += MY_MIN(block_len, max_event_size), block_len -= MY_MIN(block_len, max_event_size)) @@ -4517,7 +4534,10 @@ int log_loaded_block(IO_CACHE* file, uchar *Buffer, size_t Count) MY_MIN(block_len, max_event_size), lf_info->log_delayed); if (mysql_bin_log.write(&a)) - DBUG_RETURN(1); + { + res= 1; + goto err; + } } else { @@ -4526,12 +4546,20 @@ int log_loaded_block(IO_CACHE* file, uchar *Buffer, size_t Count) MY_MIN(block_len, max_event_size), lf_info->log_delayed); if (mysql_bin_log.write(&b)) - DBUG_RETURN(1); + { + res= 1; + goto err; + } lf_info->wrote_create_file= 1; } } ret: - int res= Buffer ? lf_info->real_read_function(file, Buffer, Count) : 0; + res= Buffer ? lf_info->real_read_function(file, Buffer, Count) : 0; +err: +#ifndef DBUG_OFF + if (did_dbug_inject) + DBUG_SET("-d,simulate_file_write_error"); +#endif DBUG_RETURN(res); } -- 2.30.2