maria-developers team mailing list archive
-
maria-developers team
-
Mailing list archive
-
Message #00926
bzr commit into MariaDB 5.1, with Maria 1.5:maria branch (knielsen:2731) Bug#46640
#At lp:maria
2731 knielsen@xxxxxxxxxxxxxxx 2009-09-09
Bug#46640: output from mysqlbinlog command in 5.1 breaks replication
The BINLOG statement was sharing too much code with the slave SQL thread, introduced with
the patch for Bug#32407. This caused statements to be logged with the wrong server_id, the
id stored inside the events of the BINLOG statement rather than the id of the running
server.
Fix by rearranging code a bit so that only relevant parts of the code are executed by
the BINLOG statement.
modified:
mysql-test/extra/binlog_tests/binlog.test
mysql-test/suite/binlog/r/binlog_row_binlog.result
mysql-test/suite/binlog/r/binlog_stm_binlog.result
sql/log_event.cc
sql/slave.cc
sql/slave.h
sql/sql_binlog.cc
per-file messages:
mysql-test/extra/binlog_tests/binlog.test
Add test case.
mysql-test/suite/binlog/r/binlog_row_binlog.result
Add test case.
mysql-test/suite/binlog/r/binlog_stm_binlog.result
Add test case.
sql/log_event.cc
Move rows_event_stmt_clean() call from update_pos() to apply_event(). This in any case
makes more sense, and is needed as update_pos() is no longer called when executing
BINLOG statements.
sql/slave.cc
The skip flag is no longer needed, as the code path for BINLOG statement has been cleaned
up.
sql/slave.h
The skip flag is no longer needed, as the code path for BINLOG statement has been cleaned
up.
sql/sql_binlog.cc
Don't invoke the update_pos() code path for the BINLOG statement, as it contains code that
is redundant and/or harmful (especially setting thd->server_id).
=== modified file 'mysql-test/extra/binlog_tests/binlog.test'
--- a/mysql-test/extra/binlog_tests/binlog.test 2009-03-25 19:41:16 +0000
+++ b/mysql-test/extra/binlog_tests/binlog.test 2009-09-09 15:27:23 +0000
@@ -258,3 +258,39 @@ dec $it;
}
show master status /* must show new binlog index after rotating */;
drop table t3;
+
+
+#
+# Bug#46640: output from mysqlbinlog command in 5.1 breaks replication
+#
+
+connect (fresh,localhost,root,,test);
+connection fresh;
+
+RESET MASTER;
+CREATE TABLE t1 (a INT PRIMARY KEY);
+
+# Format description event, with server_id = 10;
+BINLOG '
+3u9kSA8KAAAAZgAAAGoAAAABAAQANS4xLjM1LW1hcmlhLWJldGExLWRlYnVnLWxvZwAAAAAAAAAA
+AAAAAAAAAAAAAAAAAADe72RIEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
+';
+
+# What server_id is logged for a statement? Should be our own, not the
+# one from the format description event.
+INSERT INTO t1 VALUES (1);
+
+# INSERT INTO t1 VALUES (2), with server_id=20. Check that this is logged
+# with our own server id, not the 20 from the BINLOG statement.
+BINLOG '
+3u9kSBMUAAAAKQAAAJEBAAAAABoAAAAAAAAABHRlc3QAAnQxAAEDAAA=
+3u9kSBcUAAAAIgAAALMBAAAQABoAAAAAAAEAAf/+AgAAAA==
+';
+
+# Show binlog events to check that server ids are correct.
+--replace_column 1 # 2 # 5 #
+--replace_regex /Server ver: .*, Binlog ver: .*/Server ver: #, Binlog ver: #/ /table_id: [0-9]+/table_id: #/
+SHOW BINLOG EVENTS;
+
+DROP TABLE t1;
+disconnect fresh;
=== modified file 'mysql-test/suite/binlog/r/binlog_row_binlog.result'
--- a/mysql-test/suite/binlog/r/binlog_row_binlog.result 2009-03-25 19:41:16 +0000
+++ b/mysql-test/suite/binlog/r/binlog_row_binlog.result 2009-09-09 15:27:23 +0000
@@ -1298,3 +1298,27 @@ show master status /* must show new binl
File Position Binlog_Do_DB Binlog_Ignore_DB
master-bin.000002 106
drop table t3;
+RESET MASTER;
+CREATE TABLE t1 (a INT PRIMARY KEY);
+BINLOG '
+3u9kSA8KAAAAZgAAAGoAAAABAAQANS4xLjM1LW1hcmlhLWJldGExLWRlYnVnLWxvZwAAAAAAAAAA
+AAAAAAAAAAAAAAAAAADe72RIEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
+';
+INSERT INTO t1 VALUES (1);
+BINLOG '
+3u9kSBMUAAAAKQAAAJEBAAAAABoAAAAAAAAABHRlc3QAAnQxAAEDAAA=
+3u9kSBcUAAAAIgAAALMBAAAQABoAAAAAAAEAAf/+AgAAAA==
+';
+SHOW BINLOG EVENTS;
+Log_name Pos Event_type Server_id End_log_pos Info
+# # Format_desc 1 # Server ver: #, Binlog ver: #
+# # Query 1 # use `test`; CREATE TABLE t1 (a INT PRIMARY KEY)
+# # Query 1 # use `test`; BEGIN
+# # Table_map 1 # table_id: # (test.t1)
+# # Write_rows 1 # table_id: # flags: STMT_END_F
+# # Query 1 # use `test`; COMMIT
+# # Query 1 # use `test`; BEGIN
+# # Table_map 1 # table_id: # (test.t1)
+# # Write_rows 1 # table_id: # flags: STMT_END_F
+# # Query 1 # use `test`; COMMIT
+DROP TABLE t1;
=== modified file 'mysql-test/suite/binlog/r/binlog_stm_binlog.result'
--- a/mysql-test/suite/binlog/r/binlog_stm_binlog.result 2009-03-25 19:41:16 +0000
+++ b/mysql-test/suite/binlog/r/binlog_stm_binlog.result 2009-09-09 15:27:23 +0000
@@ -773,3 +773,24 @@ show master status /* must show new binl
File Position Binlog_Do_DB Binlog_Ignore_DB
master-bin.000002 106
drop table t3;
+RESET MASTER;
+CREATE TABLE t1 (a INT PRIMARY KEY);
+BINLOG '
+3u9kSA8KAAAAZgAAAGoAAAABAAQANS4xLjM1LW1hcmlhLWJldGExLWRlYnVnLWxvZwAAAAAAAAAA
+AAAAAAAAAAAAAAAAAADe72RIEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
+';
+INSERT INTO t1 VALUES (1);
+BINLOG '
+3u9kSBMUAAAAKQAAAJEBAAAAABoAAAAAAAAABHRlc3QAAnQxAAEDAAA=
+3u9kSBcUAAAAIgAAALMBAAAQABoAAAAAAAEAAf/+AgAAAA==
+';
+SHOW BINLOG EVENTS;
+Log_name Pos Event_type Server_id End_log_pos Info
+# # Format_desc 1 # Server ver: #, Binlog ver: #
+# # Query 1 # use `test`; CREATE TABLE t1 (a INT PRIMARY KEY)
+# # Query 1 # use `test`; INSERT INTO t1 VALUES (1)
+# # Query 1 # use `test`; BEGIN
+# # Table_map 1 # table_id: # (test.t1)
+# # Write_rows 1 # table_id: # flags: STMT_END_F
+# # Query 1 # use `test`; COMMIT
+DROP TABLE t1;
=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc 2009-06-11 17:49:51 +0000
+++ b/sql/log_event.cc 2009-09-09 15:27:23 +0000
@@ -7427,6 +7427,13 @@ int Rows_log_event::do_apply_event(Relay
const_cast<Relay_log_info*>(rli)->last_event_start_time= my_time(0);
}
+ if (get_flags(STMT_END_F))
+ {
+ error= rows_event_stmt_cleanup(rli, thd);
+ if (error)
+ DBUG_RETURN(error);
+ }
+
DBUG_RETURN(0);
}
@@ -7525,33 +7532,22 @@ Rows_log_event::do_update_pos(Relay_log_
if (get_flags(STMT_END_F))
{
- if ((error= rows_event_stmt_cleanup(rli, thd)) == 0)
- {
- /*
- Indicate that a statement is finished.
- Step the group log position if we are not in a transaction,
- otherwise increase the event log position.
- */
- rli->stmt_done(log_pos, when);
+ /*
+ Indicate that a statement is finished.
+ Step the group log position if we are not in a transaction,
+ otherwise increase the event log position.
+ */
+ rli->stmt_done(log_pos, when);
- /*
- Clear any errors pushed in thd->net.last_err* if for example "no key
- found" (as this is allowed). This is a safety measure; apparently
- those errors (e.g. when executing a Delete_rows_log_event of a
- non-existing row, like in rpl_row_mystery22.test,
- thd->net.last_error = "Can't find record in 't1'" and last_errno=1032)
- do not become visible. We still prefer to wipe them out.
- */
- thd->clear_error();
- }
- else
- {
- rli->report(ERROR_LEVEL, error,
- "Error in %s event: commit of row events failed, "
- "table `%s`.`%s`",
- get_type_str(), m_table->s->db.str,
- m_table->s->table_name.str);
- }
+ /*
+ Clear any errors pushed in thd->net.last_err* if for example "no key
+ found" (as this is allowed). This is a safety measure; apparently
+ those errors (e.g. when executing a Delete_rows_log_event of a
+ non-existing row, like in rpl_row_mystery22.test,
+ thd->net.last_error = "Can't find record in 't1'" and last_errno=1032)
+ do not become visible. We still prefer to wipe them out.
+ */
+ thd->clear_error();
}
else
{
=== modified file 'sql/slave.cc'
--- a/sql/slave.cc 2009-09-03 14:05:38 +0000
+++ b/sql/slave.cc 2009-09-09 15:27:23 +0000
@@ -1882,8 +1882,7 @@ static int has_temporary_error(THD *thd)
@retval 2 No error calling ev->apply_event(), but error calling
ev->update_pos().
*/
-int apply_event_and_update_pos(Log_event* ev, THD* thd, Relay_log_info* rli,
- bool skip)
+int apply_event_and_update_pos(Log_event* ev, THD* thd, Relay_log_info* rli)
{
int exec_res= 0;
@@ -1928,37 +1927,32 @@ int apply_event_and_update_pos(Log_event
ev->when= my_time(0);
ev->thd = thd; // because up to this point, ev->thd == 0
- if (skip)
- {
- int reason= ev->shall_skip(rli);
- if (reason == Log_event::EVENT_SKIP_COUNT)
- --rli->slave_skip_counter;
- pthread_mutex_unlock(&rli->data_lock);
- if (reason == Log_event::EVENT_SKIP_NOT)
- exec_res= ev->apply_event(rli);
+ int reason= ev->shall_skip(rli);
+ if (reason == Log_event::EVENT_SKIP_COUNT)
+ --rli->slave_skip_counter;
+ pthread_mutex_unlock(&rli->data_lock);
+ if (reason == Log_event::EVENT_SKIP_NOT)
+ exec_res= ev->apply_event(rli);
#ifndef DBUG_OFF
- /*
- This only prints information to the debug trace.
+ /*
+ This only prints information to the debug trace.
- TODO: Print an informational message to the error log?
- */
- static const char *const explain[] = {
- // EVENT_SKIP_NOT,
- "not skipped",
- // EVENT_SKIP_IGNORE,
- "skipped because event should be ignored",
- // EVENT_SKIP_COUNT
- "skipped because event skip counter was non-zero"
- };
- DBUG_PRINT("info", ("OPTION_BEGIN: %d; IN_STMT: %d",
- thd->options & OPTION_BEGIN ? 1 : 0,
- rli->get_flag(Relay_log_info::IN_STMT)));
- DBUG_PRINT("skip_event", ("%s event was %s",
- ev->get_type_str(), explain[reason]));
+ TODO: Print an informational message to the error log?
+ */
+ static const char *const explain[] = {
+ // EVENT_SKIP_NOT,
+ "not skipped",
+ // EVENT_SKIP_IGNORE,
+ "skipped because event should be ignored",
+ // EVENT_SKIP_COUNT
+ "skipped because event skip counter was non-zero"
+ };
+ DBUG_PRINT("info", ("OPTION_BEGIN: %d; IN_STMT: %d",
+ thd->options & OPTION_BEGIN ? 1 : 0,
+ rli->get_flag(Relay_log_info::IN_STMT)));
+ DBUG_PRINT("skip_event", ("%s event was %s",
+ ev->get_type_str(), explain[reason]));
#endif
- }
- else
- exec_res= ev->apply_event(rli);
DBUG_PRINT("info", ("apply_event error = %d", exec_res));
if (exec_res == 0)
@@ -2078,7 +2072,7 @@ static int exec_relay_log_event(THD* thd
delete ev;
DBUG_RETURN(1);
}
- exec_res= apply_event_and_update_pos(ev, thd, rli, TRUE);
+ exec_res= apply_event_and_update_pos(ev, thd, rli);
/*
Format_description_log_event should not be deleted because it will be
=== modified file 'sql/slave.h'
--- a/sql/slave.h 2008-12-10 09:02:25 +0000
+++ b/sql/slave.h 2009-09-09 15:27:23 +0000
@@ -190,8 +190,7 @@ int purge_relay_logs(Relay_log_info* rli
void set_slave_thread_options(THD* thd);
void set_slave_thread_default_charset(THD *thd, Relay_log_info const *rli);
void rotate_relay_log(Master_info* mi);
-int apply_event_and_update_pos(Log_event* ev, THD* thd, Relay_log_info* rli,
- bool skip);
+int apply_event_and_update_pos(Log_event* ev, THD* thd, Relay_log_info* rli);
pthread_handler_t handle_slave_io(void *arg);
pthread_handler_t handle_slave_sql(void *arg);
=== modified file 'sql/sql_binlog.cc'
--- a/sql/sql_binlog.cc 2009-05-06 12:03:24 +0000
+++ b/sql/sql_binlog.cc 2009-09-09 15:27:23 +0000
@@ -56,17 +56,21 @@ void mysql_client_binlog_statement(THD*
Format_description_event.
*/
my_bool have_fd_event= TRUE;
- if (!thd->rli_fake)
+ int err;
+ Relay_log_info *rli;
+
+ rli= thd->rli_fake;
+ if (!rli)
{
- thd->rli_fake= new Relay_log_info;
+ rli= thd->rli_fake= new Relay_log_info;
#ifdef HAVE_valgrind
- thd->rli_fake->is_fake= TRUE;
+ rli->is_fake= TRUE;
#endif
have_fd_event= FALSE;
}
- if (thd->rli_fake && !thd->rli_fake->relay_log.description_event_for_exec)
+ if (rli && !rli->relay_log.description_event_for_exec)
{
- thd->rli_fake->relay_log.description_event_for_exec=
+ rli->relay_log.description_event_for_exec=
new Format_description_log_event(4);
have_fd_event= FALSE;
}
@@ -78,16 +82,16 @@ void mysql_client_binlog_statement(THD*
/*
Out of memory check
*/
- if (!(thd->rli_fake &&
- thd->rli_fake->relay_log.description_event_for_exec &&
+ if (!(rli &&
+ rli->relay_log.description_event_for_exec &&
buf))
{
my_error(ER_OUTOFMEMORY, MYF(0), 1); /* needed 1 bytes */
goto end;
}
- thd->rli_fake->sql_thd= thd;
- thd->rli_fake->no_storage= TRUE;
+ rli->sql_thd= thd;
+ rli->no_storage= TRUE;
for (char const *strptr= thd->lex->comment.str ;
strptr < thd->lex->comment.str + thd->lex->comment.length ; )
@@ -170,8 +174,7 @@ void mysql_client_binlog_statement(THD*
}
ev= Log_event::read_log_event(bufptr, event_len, &error,
- thd->rli_fake->relay_log.
- description_event_for_exec);
+ rli->relay_log.description_event_for_exec);
DBUG_PRINT("info",("binlog base64 err=%s", error));
if (!ev)
@@ -209,9 +212,27 @@ void mysql_client_binlog_statement(THD*
reporting.
*/
#if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION)
- if (apply_event_and_update_pos(ev, thd, thd->rli_fake, FALSE))
+ err= ev->apply_event(rli);
+#else
+ err= 0;
+#endif
+ if (ev->get_type_code() == FORMAT_DESCRIPTION_EVENT)
+ {
+ /*
+ Install this as the format description event to use for any
+ following events.
+ */
+ delete rli->relay_log.description_event_for_exec;
+ rli->relay_log.description_event_for_exec=
+ static_cast<Format_description_log_event *>(ev);
+ }
+ else
{
delete ev;
+ }
+ ev= 0;
+ if (err)
+ {
/*
TODO: Maybe a better error message since the BINLOG statement
now contains several events.
@@ -219,17 +240,6 @@ void mysql_client_binlog_statement(THD*
my_error(ER_UNKNOWN_ERROR, MYF(0), "Error executing BINLOG statement");
goto end;
}
-#endif
-
- /*
- Format_description_log_event should not be deleted because it
- will be used to read info about the relay log's format; it
- will be deleted when the SQL thread does not need it,
- i.e. when this thread terminates.
- */
- if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT)
- delete ev;
- ev= 0;
}
}
@@ -238,7 +248,7 @@ void mysql_client_binlog_statement(THD*
my_ok(thd);
end:
- thd->rli_fake->clear_tables_to_lock();
+ rli->clear_tables_to_lock();
my_free(buf, MYF(MY_ALLOW_ZERO_PTR));
DBUG_VOID_RETURN;
}
