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:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.0.38-BK, 5.0.27 OS:Linux (fedora core4)
Assigned to: Ramil Kalimullin
Tags: BINARY, fail, log, replication

[5 Mar 2007 15:08] Adrian Popescu
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
[5 Mar 2007 15:50] Valerii 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] Valerii 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