| Bug #26842 | master binary log contains invalid queries - replication fails | ||
|---|---|---|---|
| Submitted: | 5 Mar 2007 15:08 | Modified: | 10 Jun 2007 18:23 |
| Reporter: | Adrian Popescu | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S1 (Critical) |
| Version: | 5.0.38-BK, 5.0.27 | OS: | Linux (fedora core4) |
| Assigned to: | Ramil Kalimullin | CPU Architecture: | Any |
| Tags: | BINARY, fail, log, replication | ||
[5 Mar 2007 15:50]
Valeriy Kravchuk
Thank you for a problem report. Do you use prepared statements on master? Why do you think that INSERT statement had not inserted any data on master?
[6 Mar 2007 8:56]
Adrian Popescu
Yes , I am using prepared statements on master. The data is updated on master; but not on the slave ! === From what I read in mysql docs: (how replication deals with prepared-statements) 10.4.6. Prepared Statements For the moment, a substituted normal query is written to the master's binlog. Using prepared statements on the slave as well is on the TODO. === Seems that the substituted query from the master's binlog is not quite equivalent and is generating an errror. Cannot be used for replication or from recovery using "mysqlbinlog". # Here is a simplified test query which can reproduce the error: SET @`percentage`:=123; PREPARE STMT FROM ' SELECT * FROM mytable LIMIT ?; '; EXECUTE STMT using @`percentage`; (which works just fine.) !!! The problem seems to be how the parameter after LIMIT is interpreted. if I try: mysql> select @`percentage`; +---------------+ | @`percentage` | +---------------+ | 123 | +---------------+ mysql>select * from mytable LIMIT 123; (works OK !!! ) mysql>select * from mytable LIMIT @`percentage`; (ERROR !!! ) ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '@`per centage`' at line 1
[6 Mar 2007 9:17]
Valeriy Kravchuk
Yes, this is what I expected. Now we have a repeatable test case proving that replication will be broken in cases like this:
openxs@suse:~/dbs/5.0> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.38-log Source distribution
Type 'help;' or '\h' for help. Type '\c' to clear the buffer.
mysql> desc t1;
+-------+---------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-------+---------+------+-----+---------+-------+
| c1 | int(11) | YES | | NULL | |
| c2 | int(11) | YES | | NULL | |
| c3 | int(11) | YES | | NULL | |
+-------+---------+------+-----+---------+-------+
3 rows in set (0.01 sec)
mysql> prepare stmt from "insert into t1(c1) select 1 from information_schema.tables limit ?";
Query OK, 0 rows affected (0.00 sec)
Statement prepared
mysql> set @a=1;
Query OK, 0 rows affected (0.01 sec)
mysql> select @a;
+------+
| @a |
+------+
| 1 |
+------+
1 row in set (0.00 sec)
mysql> execute stmt using @a;
Query OK, 1 row affected (0.02 sec)
Records: 1 Duplicates: 0 Warnings: 0
mysql> show master status\G
*************************** 1. row ***************************
File: suse-bin.000001
Position: 272
Binlog_Do_DB:
Binlog_Ignore_DB:
1 row in set (0.00 sec)
mysql> show binlog events in 'suse-bin.000001'\G
*************************** 1. row ***************************
Log_name: suse-bin.000001
Pos: 4
Event_type: Format_desc
Server_id: 1
End_log_pos: 98
Info: Server ver: 5.0.38-log, Binlog ver: 4
*************************** 2. row ***************************
Log_name: suse-bin.000001
Pos: 98
Event_type: User var
Server_id: 1
End_log_pos: 42
Info: @`a`=1
*************************** 3. row ***************************
Log_name: suse-bin.000001
Pos: 140
Event_type: Query
Server_id: 1
End_log_pos: 174
Info: use `test`; insert into t1(c1) select 1 from information_schema.tab
les limit @'a'
3 rows in set (0.00 sec)
mysql> select @a;
+------+
| @a |
+------+
| 1 |
+------+
1 row in set (0.00 sec)
mysql> insert into t1(c1) select 1 from information_schema.tables limit @'a';
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that
corresponds to your MySQL server version for the right syntax to use near '@'a''
at line 1
So, as one can see, statement that will never be properly executed is written into the binary log. Replcation will be surely broken if you use prepared statements with parameters in LIMIT clause. Verified with latest 5.0.38-BK on Linux.
[12 Mar 2007 15:25]
Rafal Somla
REFINED PROBLEM DESCRIPTION
===========================
When invocation of a prepared statement is written to binlog, the query stored in the binlog entry is constructed by prepared statement's set_params_from_vars() method which is a pointer to function
bool insert_params_from_vars_with_log(Prepared_statement *stmt,
List<LEX_STRING>& varnames,
String *query)
defined in sql_prepare.cc. This is the code which executes a prepared statement (sql_prepare.cc).
-----------------------------------------------------------
void mysql_sql_stmt_execute(THD *thd)
{
LEX *lex= thd->lex;
Prepared_statement *stmt;
String expanded_query;
...
if (!(stmt= (Prepared_statement*) thd->stmt_map.find_by_name(name)))
{ ... }
...
if (stmt->set_params_from_vars(stmt, lex->prepared_stmt_params,
&expanded_query))
goto set_params_data_err;
(void) stmt->execute(&expanded_query, FALSE);
DBUG_VOID_RETURN;
set_params_data_err:
...
DBUG_VOID_RETURN;
}
-----------------------------------------------------------
Writing binlog entry happens inside stmt->execute() using expanded_query string passed as an argument.
The problem is that stmt->set_params_from_vars, i.e., insert_params_from_vars_with_log can produce syntacticly incorrect query when replacing some parameters with variable *names* (instead of variable values). E.g., in the reported case of "LIMIT ?" clause. Replacing "?" with "@var" produces "LIMIT @var" which is not a correct SQL syntax.
Why the stored statement executes correctly if the expanded query is incorrect? This is because stmt->execute() method doesn't look at the expanded query at all when executing the statement. It uses other members of the stmt structure (such as LEX structures etc.). The expanded query is only used for logging purposes.
[12 Mar 2007 15:28]
Rafal Somla
An obvious solution would be to use variable values, not names when filling prepared statement's slots. Needs to be seen if this will not break anything.
[21 Mar 2007 10:41]
Rafal Somla
PROPOSED SOLUTION
=================
Make the stored statement string created upon its execution use variable values, instead of names, to fill placeholders.
This can be done by modifying insert_params_from_vars_with_log() function defined in sql_prepare.cc. The function constructs a string containing the statement with all placeholders filled. This code fragment in the function:
--------------------------------------------------------------------------
if (entry)
{
char *begin, *ptr;
buf.length(0);
if (buf.reserve(entry->name.length*2+3))
DBUG_RETURN(1);
begin= ptr= buf.c_ptr_quick();
*ptr++= '@';
*ptr++= '\'';
ptr+= escape_string_for_mysql(&my_charset_utf8_general_ci,
ptr, 0, entry->name.str,
entry->name.length);
*ptr++= '\'';
buf.length(ptr - begin);
val= &buf;
}
else
val= &my_null_string;
<...>
if (query->replace(param->pos_in_query+length, 1, *val))
--------------------------------------------------------------------------
sets val to the escaped name of the variable and then inserts it into the query string in the position of a placeholder. Pointer entry points at user_var_entry structure filled with a call to get_var_with_binlog(). This describes the variable which is supposed to be inserted into the placeholder.
The code should be changed so that val contains not the name but value of the variable. What needs to be done:
- find out where the value of the variable is stored inside user_var_entry
structure (user_var_entry::value ?).
- make sure that the value is filled (does get_var_with_binlog() do that?)
- make sure that the string representing the value has correct SQL syntax
- replace name with the value in the above code.
Note: function insert_params_from_vars_with_log() is called from mysql_sql_stmt_execute() when executing previously prepared statement. The string it produces is written to binlog in the entry corresponding to that execution.
[17 Apr 2007 9:04]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/24629 ChangeSet@1.2456, 2007-04-17 14:03:56+05:00, ramil@mysql.com +6 -0 Fix for bug #26842: master binary log contains invalid queries - replication fails bug #12826: Possible to get inconsistent slave using SQL syntax Prepared Statements Problem: binlogging PS' we may produce syntacticly incorrect queries in the binlog replacing some parameters with variable names (instead of variable values). E.g. in the reported case of "limit ?" clause: replacing "?" with "@var" produces "limit @var" which is not a correct SQL syntax. Also it may lead to different query execution on slave if we set and use a variable in the same statement, e.g. "insert into t1 values (@x:=@x+1, ?)" Fix: make the stored statement string created upon its execution use variable values (instead of names) to fill placeholders.
[24 May 2007 10:36]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/27265 ChangeSet@1.2497, 2007-05-24 15:35:43+05:00, ramil@mysql.com +6 -0 Fix for bug #26842: master binary log contains invalid queries - replication fails bug #12826: Possible to get inconsistent slave using SQL syntax Prepared Statements Problem: binlogging PS' we may produce syntacticly incorrect queries in the binlog replacing some parameters with variable names (instead of variable values). E.g. in the reported case of "limit ?" clause: replacing "?" with "@var" produces "limit @var" which is not a correct SQL syntax. Also it may lead to different query execution on slave if we set and use a variable in the same statement, e.g. "insert into t1 values (@x:=@x+1, ?)" Fix: make the stored statement string created upon its execution use variable values (instead of names) to fill placeholders.
[25 May 2007 13:08]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/27340 ChangeSet@1.2508, 2007-05-25 17:24:45+05:00, ramil@mysql.com +4 -0 Test for bug #26842 moved to a separate file as it uses 'show binlog events' and fails with --binlog-format=row.
[6 Jun 2007 16:54]
Bugs System
Pushed into 5.1.20-beta
[6 Jun 2007 16:57]
Bugs System
Pushed into 5.0.44
[10 Jun 2007 18:23]
Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.
If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at
http://dev.mysql.com/doc/en/installing-source.html
Documented fix in 5.0.44 and 5.1.20 changelogs.
[2 Jul 2007 15:05]
Bugs System
Pushed into 5.1.21-beta
Description: Seems that master binary logs contains queries (inserts) that updates no data. (mysql v 5.0.27) I thought that: "The binary log does not contain statements that do not modify any data." The problem is that "binary log" seems it cannot be used or trusted for replication or recovery. This makes Slave to stop when trying to execute a query from bin log, query which contains errors . (slave runs for a while until such a query is executed) Both bin-log(master) and relay-log(slave) seems ok ; and I can dump them with "mysqlbinlog". I can find the query in master bin-log as well as in slave relay-log. (tables are using InnoDB) running the query in mysql CLI - also fails . (tested on slave) mysql> show slave status \G *************************** 1. row *************************** Slave_IO_State: Master_Host: x.x.x.x Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: mysql-bin.000090 Read_Master_Log_Pos: 14659714 Relay_Log_File: slave-relay-bin.000036 Relay_Log_Pos: 344436437 Relay_Master_Log_File: mysql-bin.000083 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: 1064 Last_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '@'percentage' ) tmp , hours where hour in (10,18' at line 7' on query. Default database: 'test'. Query: 'insert into tasks (source_id, due_at, status_code, pri_code) select id, curdate(), maketime(hour,30,00)) as due_at, 'WAIT' as status, 'HIGH' from ( select st.id from cl_src st join sources s on st.id = s.id order by mdays desc, mhrs desc LIMIT @'percentage' ) tmp , hours where hour in (10,18)' Skip_Counter: 0 Exec_Master_Log_Pos: 344436300 Relay_Log_Space: 7536116891 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 1 row in set (0.00 sec) mysql> ###### master# mysqlbinlog --start-position=344436300 mysql-bin.000083 /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; # at 344436300 #070301 0:08:53 server id 1 end_log_pos 28 Intvar SET INSERT_ID=1; # at 344436328 #070301 0:08:57 server id 1 end_log_pos 77 User_var SET @`percentage`:=123; # at 344436377 #070301 0:08:53 server id 1 end_log_pos 547 Query thread_id=5543 exec_time=4 error_code=0 use test; SET TIMESTAMP=1172707733; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1; SET @@session.sql_mode=0; /*!\C utf8 */; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33; SET @@session.time_zone='SYSTEM'; insert into tasks (source_id, due_at, status_code, pri_code) select id, curdate(), maketime(hour,30,00)) as due_at, 'WAIT' as status, 'HIGH' from ( select st.id from cl_src st join sources s on st.id = s.id order by mdays desc, mhrs desc LIMIT @'percentage' ) tmp , hours where hour in (10,18); # at 344436847 #070301 0:08:53 server id 1 end_log_pos 344436874 Xid = 55683458 COMMIT; How to repeat: - Suggested fix: could use slave-skip-errors but then my replication will not be in sync