MySQL Bugs: #25843: changing default database between PREPARE and EXECUTE of statement breaks binlog

Bug #25843	changing default database between PREPARE and EXECUTE of statement breaks binlog
Submitted:	25 Jan 2007 10:50	Modified:	23 Oct 2007 19:23
Reporter:	Guilhem Bichot	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Prepared statements	Severity:	S3 (Non-critical)
Version:	5.1-bk/5.0bk	OS:	Linux (linux)
Assigned to:	Alexander Nozdrin	CPU Architecture:	Any

Description:
*********************************************
VERIFIER: I did not test with 5.0, please test with 5.0.
Please test when statements are prepared using the binary protocol (the present test is only for the PREPARE SQL command).
*********************************************

A prepared statement executes in the database which was default at the time of preparation, not at the time of execution (this is how it has to be).
But, when at execution a binary log event is written, a mention of the current database at the time of execution is binlogged into it, while a mention of the current database at the time of preparation should be.
create database test;
create database mysqltest;
use mysqltest;
create table t1(n char(30));
use test;
create table t1(n char(30));
prepare stmt1 from 'insert into t1 values (?)';
set @var1= "from-master-1";
# that one will insert into test.t1 and binlog will be correct
execute stmt1 using @var1;
use mysqltest;
# that one will insert into test.1 (mysqltest.t1 stays untouched)
# and binlog will be wrong
execute stmt1 using @var1;

"show binlog events" then shows:
| gbichot3-bin.000001 | 192 | User var    |         1 |         242 | @`var1`=_latin1 0x66726F6D2D6D61737465722D31 COLLATE latin1_swedish_ci |
| gbichot3-bin.000001 | 242 | Query       |         1 |         336 | use `test`; insert into t1 values (@'var1')                            |
| gbichot3-bin.000001 | 336 | Query       |         1 |         431 | use `mysqltest`; create table t1(n char(30))                           |
| gbichot3-bin.000001 | 431 | User var    |         1 |         481 | @`var1`=_latin1 0x66726F6D2D6D61737465722D31 COLLATE latin1_swedish_ci |
| gbichot3-bin.000001 | 481 | Query       |         1 |         580 | use `mysqltest`; insert into t1 values (@'var1')      

See: the last execution, even though it inserted into test.t1, has a "use mysqltest" in the binlog.

How to repeat:
see "how to repeat"

Suggested fix:
Konstantin said "we should just add db to the Statement structure, and it will automatically get set and restored in set_n_backup_statement/restore..."

Thank you for the bug report. Verified in 5.0.

Forgot to paste:

mysql> show binlog events;
+------------------+-----+-------------+-----------+-------------+------------------------------------------------------------------------+
| Log_name         | Pos | Event_type  | Server_id | End_log_pos | Info                                                                   |
+------------------+-----+-------------+-----------+-------------+------------------------------------------------------------------------+
| light-bin.000001 |   4 | Format_desc |         1 |          98 | Server ver: 5.0.36-debug-log, Binlog ver: 4                            | 
| light-bin.000001 |  98 | Query       |         1 |         181 | create database test                                                   | 
| light-bin.000001 | 181 | Query       |         1 |         274 | create database mysqltest                                              | 
| light-bin.000001 | 274 | Query       |         1 |         369 | use `mysqltest`; create table t1(n char(30))                           | 
| light-bin.000001 | 369 | Query       |         1 |         459 | use `test`; create table t1(n char(30))                                | 
| light-bin.000001 | 459 | User var    |         1 |         509 | @`var1`=_latin1 0x66726F6D2D6D61737465722D31 COLLATE latin1_swedish_ci | 
| light-bin.000001 | 509 | Query       |         1 |         603 | use `test`; insert into t1 values (@'var1')                            | 
| light-bin.000001 | 603 | User var    |         1 |         653 | @`var1`=_latin1 0x66726F6D2D6D61737465722D31 COLLATE latin1_swedish_ci | 
| light-bin.000001 | 653 | Query       |         1 |         752 | use `mysqltest`; insert into t1 values (@'var1')                       | 
+------------------+-----+-------------+-----------+-------------+------------------------------------------------------------------------+
9 rows in set (0.00 sec

Something to watch: we sometimes do strange things with thd->db like:
in THD::set_db() where we x_free(db) (that could happen during DROP DATABASE, I don't think that kind of statement can be prepared though).
So, if we have done something like:
thd->db= stmt->db;
execution of prepared statement;
that would free thd->db thus free stmt->db which may not be desirable.

Now that the query cache is used for prepared statements too (BUG#735, fixed in 5.1), as the query cache uses "query+thd->db" as look-up key, the present bug applies to query cache & prepared statements, like this:

# be sure that your tree contains the fix for BUG#735 (currently only in
# 5.1-runtime), save this test in mysql-test/t/bug.test, and run:
# ./mtr bug --record --mysqld=--query-cache-size=1000000; cat r/bug.result 

# set up everything
create database prod;
create database dev;
use prod;
create table t1(n char(30));
insert into t1 values("SECRET");
create table t2(a int);
use dev;
create table t1(n char(30));
insert into t1 values("garbage");

flush status;

use prod;
select database();
prepare stmt1 from 'select * from t1';
execute stmt1;

use dev;
select database();
prepare stmt2 from 'select * from t1';
use prod;
execute stmt2;
show status like "qcache_hits";

# you will observe that result:
create database prod;
create database dev;
use prod;
create table t1(n char(30));
insert into t1 values("SECRET");
create table t2(a int);
use dev;
create table t1(n char(30));
insert into t1 values("garbage");
flush status;
use prod;
select database();
database()
prod
prepare stmt1 from 'select * from t1';
execute stmt1;
n
SECRET
use dev;
select database();
database()
dev
prepare stmt2 from 'select * from t1';
use prod;
execute stmt2;
n
SECRET
show status like "qcache_hits";
Variable_name   Value
Qcache_hits     1

It's a bug that the second EXECUTE returns SECRET; if I disable the query cache it returns "garbage" which is as it should be (prepared statement executes in the db where it was prepared).

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/32868

ChangeSet@1.2569, 2007-08-22 14:33:23+04:00, anozdrin@ibm.opbmk +7 -0
  Fix for BUG#25843: changing default database between PREPARE and EXECUTE
  of statement breaks binlog.
  
  There were two problems discovered by this bug:
  
    1. Default (current) database is not fixed at the creation time.
       That leads to wrong output of DATABASE() function.
  
    2. Database attributes (@@collation_database) are not fixed at the creation
       time. That leads to wrong resultset.
  
  Binlog breakage and Query Cache wrong output happened because of the first
  problem.
  
  The fix is to remember the current database at the PREPARE-time and set it
  each time at EXECUTE.

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/33451

ChangeSet@1.2587, 2007-08-30 20:06:19+04:00, anozdrin@ibm.opbmk +3 -0
  Cleanup-patch for BUG#25843: changing default database between
  PREPARE and EXECUTE of statement breaks binlog.

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/33539

ChangeSet@1.2588, 2007-08-31 20:42:14+04:00, anozdrin@ibm.opbmk +13 -0
  Fix for BUG#25843: changing default database between PREPARE and EXECUTE
  of statement breaks binlog.
  
  There were two problems discovered by this bug:
  
    1. Default (current) database is not fixed at the creation time.
       That leads to wrong output of DATABASE() function.
  
    2. Database attributes (@@collation_database) are not fixed at
       the creation time. That leads to wrong resultset.
  
  Binlog breakage and Query Cache wrong output happened because of
  the first problem.
  
  The fix is to remember the current database at the PREPARE-time and
  set it each time at EXECUTE.

Pushed into 5.1-runtime.

Pushed into 5.1.23-beta

Documented bugfix in 5.1.23 changelog as:

          For a prepared statement <replaceable>stmt</replaceable>,
          changing the default database following <literal>PREPARE
            <replaceable>stmt</replaceable></literal> but before
          <literal>EXECUTE  <replaceable>stmt</replaceable></literal>
          caused <replaceable>stmt</replaceable> to be recorded
          incorrectly in the binary log. (Bug #25843) 

Question: will this fix be made in 5.0 also?

I don't think so -- the patch is too risky for 5.0.