Bug #22043 MySQL don't add "USE <DATABASE>" before "DROP PROCEDURE IF EXISTS"
Submitted: 6 Sep 2006 6:49 Modified: 21 Feb 2007 3:12
Reporter: Kenji Hirohama Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.0.34-BK, 5.0.24 OS:Microsoft Windows (Windows, Linux)
Assigned to: Kristofer Pettersson
Tags: bfsm_2007_01_18, bin-log, replication

[6 Sep 2006 6:49] Kenji Hirohama
Description:
MySQL add "USE <DATABASE>" before SQL query in binary log as necessary.
However, "DROP PROCEDURE IF EXISTS" don't add "USE <DATABASE>"

The problem is, if replication works with "replicate_do_db" parameter,
that query is ignored and not send to the slave.

How to repeat:
SHELL>mysql
mysql>drop procedure test.proc1 if exists test.proc1;
mysql>create procedure test.proc1() begin end;

Then, check the bin-log.
My bin-log is the following;
--------------------------------------------
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
# at 4
#060906 15:31:11 server id 1  end_log_pos 98 	Start: binlog v 4, server v 5.0.21-community-nt-log created 060906 15:31:11
# Warning: this binlog was not closed properly. Most probably mysqld crashed writing it.
# at 98
#060906 15:31:26 server id 1  end_log_pos 192 	Query	thread_id=12	exec_time=0	error_code=0
SET TIMESTAMP=1157524286;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1; SET @@session.sql_mode=2097152; /*!\C utf8 */; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33;
drop procedure if exists test.proc1;
# at 192
#060906 15:31:28 server id 1  end_log_pos 321 	Query	thread_id=12	exec_time=0	error_code=0
use test;
SET TIMESTAMP=1157524288;
CREATE DEFINER=`root`@`localhost` procedure test.proc1() begin end; # End of log file ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
------------------------------------------------
[6 Sep 2006 11:16] Sveta Smirnova
Thank you for the report.

Verified as described on Linux using last BK sources:

ssmirnova@shella ~/mysql5.0b
$bin/mysql --socket=/tmp/mysql.sock -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 to server version: 5.0.25-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> create procedure test.proc1() begin end;
Query OK, 0 rows affected (0.00 sec)

mysql> \q
Bye

ssmirnova@shella ~/mysql5.0b
$bin/mysql --socket=/tmp/mysql.sock -uroot
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2 to server version: 5.0.25-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> drop procedure test.proc1 if exists test.proc1;
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 'if exists test.proc1' at line 1
mysql> drop procedure if exists test.proc1;
Query OK, 0 rows affected (0.00 sec)

mysql> create procedure test.proc1() begin end;
Query OK, 0 rows affected (0.00 sec)

mysql> \q
Bye

ssmirnova@shella ~/mysql5.0b
$bin/mysqlbinlog data/bug22043.000001
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
# at 4
#060906 12:41:29 server id 1  end_log_pos 98    Start: binlog v 4, server v 5.0.25-debug-log created 060906 12:41:29 at startup
# Warning: this binlog was not closed properly. Most probably mysqld crashed writing it.
ROLLBACK;
# at 98
#060906 12:42:03 server id 1  end_log_pos 227   Query   thread_id=1     exec_time=0     error_code=0
use test;
SET TIMESTAMP=1157539323;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1;
SET @@session.sql_mode=0;
/*!\C latin1 */;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=33;
CREATE DEFINER=`root`@`localhost` procedure test.proc1() begin end;
# at 227
#060906 12:43:02 server id 1  end_log_pos 321   Query   thread_id=2     exec_time=0     error_code=0
SET TIMESTAMP=1157539382;
drop procedure if exists test.proc1;
# at 321
#060906 12:43:17 server id 1  end_log_pos 450   Query   thread_id=2     exec_time=0     error_code=0
use test;
SET TIMESTAMP=1157539397;
CREATE DEFINER=`root`@`localhost` procedure test.proc1() begin end;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
[6 Sep 2006 11:20] Kenji Hirohama
Thanks for your confirmation.
I believe this would cause some replication problems, so I'm happy if you have any plan to fix/solve it.
Thanks,
Kenji
[6 Sep 2006 11:39] Sveta Smirnova
Altough our tip about replicate-do-db=db_name in "Replication Startup Options" (http://dev.mysql.com/doc/refman/5.0/en/replication-options.html) chapter is working, 2 things are strange:

1. There is USE test; statement before CREATE PROCEDURE ..., but not before DROP PROCEDURE ...
2. It is not intuitive to use replicate-wild-do-table option to replicate stored procedures from the database. May be an alias needed?
[28 Sep 2006 7:25] Lars Thalmann
The used database is always replicated, but is not always visible when
printing with mysqlbinlog program.  The idea is that it is only
printed if it is needed.  If a 'use database' is printed earlier in
the mysqlbinlog output then there is no need to re-print it.

This code in log_event.cc does the printout of 'use <database>':

  if (!(flags & LOG_EVENT_SUPPRESS_USE_F) && db)
  {
    if (different_db= memcmp(print_event_info->db, db, db_len + 1))
      memcpy(print_event_info->db, db, db_len + 1);
    if (db[0] && different_db) 
      fprintf(file, "use %s;\n", db);
  }

#
#  Example:
#  PRINTING JUST THE EVENT SHOWS 'USE DATABASE'
#

lthalmann@dl145j:~/bk/mysql-5.0/mysql-test$ ../client/mysqlbinlog --hexdump --start-pos=95368 --stop-pos=95370 var/log/master-bin.000001 
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
# at 95368
#060928  8:50:47 server id 1  end_log_pos 95453 
# 00017488 c7 70 1b 45 02 01 00 00  00 55 00 00 00 dd 74 01 |.p.E.....U....t.|
# 00017498 00 00 00 01 00 00 00 00  00 00 00 04 00 00 1a 00 |................|
# 000174a8 00 00 40 00 00 01 00 00  00 00 00 00 00 00 06 03 |................|
# 000174b8 73 74 64 04 08 00 08 00  08 00 74 65 73 74 00 64 |std.......test.d|
# 000174c8 72 6f                                            |ro|
#       Query   thread_id=1     exec_time=0     error_code=0
use test;
SET TIMESTAMP=1159426247;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1;
SET @@session.sql_mode=0;
/*!\C latin1 */;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8;
drop procedure bug2614;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

#
#  Example:
#  PRINTING ALL THE EVENTS DOES NOT SHOW 'USE DATABASE'
#

lthalmann@dl145j:~/bk/mysql-5.0/mysql-test$ ../client/mysqlbinlog --hexdump --stop-pos=95370 var/log/master-bin.000001 
  .
  .
  .  
# at 95368
#060928  8:50:47 server id 1  end_log_pos 95453 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
# 00017488 c7 70 1b 45   02   01 00 00 00   55 00 00 00   dd 74 01 00   00 00
# 0001749b 01 00 00 00 00 00 00 00  04 00 00 1a 00 00 00 40 |................|
# 000174ab 00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64 |.............std|
# 000174bb 04 08 00 08 00 08 00 74  65 73 74 00 64 72 6f 70 |.......test.drop|
# 000174cb 20 70 72 6f 63 65 64 75  72 65 20 62 75 67 32 36 |.procedure.bug26|
# 000174db 31 34                                            |14|
#       Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1159426247;
drop procedure bug2614;

My opinions:

1. We need to fix so that 'use database' is always printed before
   a statement.  It does not have to be close to the statement, but 
   somewhere before it.  In Sveta's example there is such a printout, 
   but in Kenji's example there is not.

2. Investigate why (or if) it consistently print 'use database' in
   front of CREATE but not in front of DROP.
[28 Nov 2006 15:09] 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/15971

ChangeSet@1.2297, 2006-11-28 16:03:53+01:00, thek@kpdesk.mysql.com +4 -0
  Bug#22043 MySQL don't add "USE <DATABASE>" before "DROP PROCEDURE EXISTS"
  
  - CREATE PROCEDURE stores database name based on query context instead
    of 'current database' as set by 'USE' according to manual.
    The bug reporter interpret the filtering statements as bug for
     DROP PROCEDURE based on this behavior.
  - Removed the code which changes db context.
  - Added code to check that a valid db was supplied.
[29 Nov 2006 12:16] 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/16091

ChangeSet@1.2399, 2006-11-29 11:45:29+01:00, thek@kpdesk.mysql.com +2 -0
  Bug#22043 MySQL don't add "USE <DATABASE>" before "DROP PROCEDURE IF EXISTS"
  
  - Merge patch.
  - Test case needed update because event number were off.
  - Error code has changed because db name validation rules
    changes between 5.0 and 5.1
[30 Nov 2006 14:57] 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/16222

ChangeSet@1.2298, 2006-11-30 15:57:11+01:00, thek@kpdesk.mysql.com +5 -0
  Bug#22043 MySQL don't add "USE <DATABASE>" before "DROP PROCEDURE IF EXISTS"
  
  - Refactoring of duplicate code
  - Modified bad test cases
  - Changed expected error when operating on information_schema.
[1 Dec 2006 11:51] 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/16298

ChangeSet@1.2298, 2006-12-01 12:50:57+01:00, thek@kpdesk.mysql.com +5 -0
  Bug#22043 MySQL don't add "USE <DATABASE>" before "DROP PROCEDURE IF EXISTS"
  
  - Refactoring of duplicate code
  - Modified bad test cases
  - Changed expected error when operating on information_schema.
[1 Dec 2006 16:37] 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/16323

ChangeSet@1.2401, 2006-12-01 17:36:51+01:00, thek@kpdesk.mysql.com +2 -0
  Bug#22043 MySQL don't add "USE <DATABASE>" before "DROP PROCEDURE IF EXISTS"
  
  - Merged; updated test case.
[21 Dec 2006 20:16] Paul Dubois
Noted in 5.0.32, 5.1.15 changelogs.

The code for generating USE statements for binary logging of CREATE
PROCEDURE statements resulted in confusing output from mysqlbinlog
for DROP PROCEDURE statements.
[4 Jan 2007 6:10] Valerii Kravchuk
Sorry, but while this bug is fixed in 5.1.15-BK, it is not fixed in 5.0.32, and even in latest 5.0.34-BK:

openxs@suse:~/dbs/5.0> bin/mysql -uroot
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.34-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> use mysql;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed

mysql> create procedure test.proc1() begin end;
Query OK, 0 rows affected (0.02 sec)

mysql> drop procedure if exists test.proc1;
Query OK, 0 rows affected (0.00 sec)

mysql> show binlog events in 'suse-bin.000014' from 2;
+-----------------+-----+-------------+-----------+-------------+---------------
------------------------------------------------------------------+
| Log_name        | Pos | Event_type  | Server_id | End_log_pos | Info
                                                                  |
+-----------------+-----+-------------+-----------+-------------+---------------
------------------------------------------------------------------+
| suse-bin.000014 |   4 | Format_desc |         1 |          98 | Server ver: 5.
0.34-debug-log, Binlog ver: 4                                     |
| suse-bin.000014 |  98 | Query       |         1 |         228 | use `mysql`; C
REATE DEFINER=`root`@`localhost` procedure test.proc1() begin end |
| suse-bin.000014 | 228 | Query       |         1 |         322 | drop procedure
 if exists test.proc1                                             |
+-----------------+-----+-------------+-----------+-------------+---------------
------------------------------------------------------------------+
3 rows in set (0.00 sec)
[12 Jan 2007 9:12] Valerii Kravchuk
Now (ChangeSet@1.2366, 2007-01-11 09:19:32+01:00) results changed:

openxs@suse:~/dbs/5.0> bin/mysql -uroot
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.0.34-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> use mysql;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> drop procedure if exists test.proc1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> create procedure test.proc1() begin end;
Query OK, 0 rows affected (0.02 sec)

mysql> drop procedure if exists test.proc1;
Query OK, 0 rows affected (0.00 sec)

mysql> show master status;
+-----------------+----------+--------------+------------------+
| File            | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+-----------------+----------+--------------+------------------+
| suse-bin.000016 |      417 |              |                  |
+-----------------+----------+--------------+------------------+
1 row in set (0.00 sec)

mysql> show binlog events in 'suse-bin.000016' from 2;
+-----------------+-----+-------------+-----------+-------------+---------------
------------------------------------------------------------------+
| Log_name        | Pos | Event_type  | Server_id | End_log_pos | Info
                                                                  |
+-----------------+-----+-------------+-----------+-------------+---------------
------------------------------------------------------------------+
| suse-bin.000016 |   4 | Format_desc |         1 |          98 | Server ver: 5.
0.34-debug-log, Binlog ver: 4                                     |
| suse-bin.000016 |  98 | Query       |         1 |         188 | use `test`; DE
LETE FROM `test`.`lookup`                                         |
| suse-bin.000016 | 188 | Query       |         1 |         318 | use `mysql`; C
REATE DEFINER=`root`@`localhost` procedure test.proc1() begin end |
| suse-bin.000016 | 318 | Query       |         1 |         417 | use `mysql`; d
rop procedure if exists test.proc1                                |
+-----------------+-----+-------------+-----------+-------------+---------------
------------------------------------------------------------------+
4 rows in set (0.01 sec)

mysql> exit
Bye

So, looks like bug (if any) is already fixed in 5.0.34-BK. At least, we have similar consistent results in 5.1-BK and 5.0-BK for both CREATE and DROP.
[14 Feb 2007 15:43] Chad MILLER
Available in 5.0.36 and 5.1.16-beta.
[21 Feb 2007 3:12] Paul Dubois
I moved the 5.0 changelog entry from 5.0.32 to 5.0.36.