MySQL Bugs: #20396: Bin Log does not get DELIMETER cmd

Bug #20396	Bin Log does not get DELIMETER cmd - Recover StoredProc fails
Submitted:	12 Jun 2006 13:57	Modified:	23 Jan 2007 20:28
Reporter:	John Smythe	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.0.23-BK, 5.0.22	OS:	Linux (Linux)
Assigned to:	Alexander Barkov	CPU Architecture:	Any

Description:
Problem with create of a stored Procedure/Func when restoring from a Binary Log.  Performing create function fails (error) after the "drop procedure" from the binary log has removed the procedure.  End result is that the previously existing strored proc no longer exists for that database.

How to repeat:
The following steps produce the problem (MySQL 5.0.22)

This problem occurs with a database that contains stored procedures & stored functions.

1. Create a clean dump of the database (starting point).
   Transaction logging should be enabled.
2. Verify all stored procedures/functions present in database
3. Flush binary logs
4. Run a script to update procedures/functions
 in the database.
  Script performs a "drop procedure" then a "create procedure" to 
  modify strored proc.
  Same sequence of commands for a stored func that follows.
5. Capture binary log of procedure update
6. Stop database and Restore database from dump in step 1
7. Roll forward with binary log captured in step 5
8. Observe/capture error in roll forward
9. The first function/procedure in binary log is no longer present in database.

The script used to change the stored proc & stored func was run through SQLYog GUI (no errors occurred in performing updates to Stored Proc & Stored Func).

Problem clarified:  The DELIMETER function is not captured in the Bin Log and fails on playback of this sequence of commands, although the Delimeter command does work when the script is executed initially from the command processor.

Below are the details of the test.  Script to apply the stored procedure based on the method described on this mysql manual page: http://dev.mysql.com/doc/refman/5.0/en/create-procedure.html
 
The test7 procedure was added from the command tool as follows:
 
mysql> delimiter //
mysql> CREATE PROCEDURE test.test7 ()
-> BEGIN
-> SELECT 1;
-> END;
-> //
Query OK, 0 rows affected (0.00 sec)
mysql> delimiter ;
mysql> exit
 
This resulting excerpt from the binlog shows that the delimiter change is not captured and this fails when it gets to the first semicolon in the stored proc:
use test;
SET TIMESTAMP=1150392216;
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;
CREATE DEFINER=`root`@`localhost` PROCEDURE test.test7 ()
BEGIN
SELECT 1;
END;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Clarified Synopsis: This error is critical because recovery of a stored procedure from binary logs fails.  Unable to recovery database when log contains activity to REMOVE and then CREATE a stored procedure.

Verified just as described with 5.0.23-BK on Linux:

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 6 to server version: 5.0.23-log

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

mysql> delimiter //
mysql> create procedure proc1() begin select 1; end;//
Query OK, 0 rows affected (0.03 sec)

mysql> create procedure proc2() begin select 2; end;//
Query OK, 0 rows affected (0.00 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.0> bin/mysqlbinlog var/suse-bin.000003
...
# at 1015
#060619 15:17:25 server id 1  end_log_pos 1149  Query   thread_id=6     exec_time=0     error_code=0
SET TIMESTAMP=1150719445;
CREATE DEFINER=`root`@`localhost` procedure proc1() begin select 1; end;
# at 1149
#060619 15:17:28 server id 1  end_log_pos 1283  Query   thread_id=6     exec_time=0     error_code=0
SET TIMESTAMP=1150719448;
CREATE DEFINER=`root`@`localhost` procedure proc2() begin select 2; end;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

openxs@suse:~/dbs/5.0> bin/mysqladmin -uroot shutdown
STOPPING server from pid file /home/openxs/dbs/5.0/var/suse.pid
060619 15:18:15  mysqld ended

[1]+  Done                    bin/mysqld_safe --log-bin
openxs@suse:~/dbs/5.0> bin/mysqlbinlog var/suse-bin.000003 --start-position=1149
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
# at 1149
#060619 15:17:28 server id 1  end_log_pos 1283  Query   thread_id=6     exec_time=0     error_code=0
use test;
SET TIMESTAMP=1150719448;
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;
CREATE DEFINER=`root`@`localhost` procedure proc2() begin select 2; end;
# at 1283
#060619 15:18:13 server id 1  end_log_pos 1302  Stop
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

openxs@suse:~/dbs/5.0> bin/mysqld_safe &
[1] 6902
openxs@suse:~/dbs/5.0> Starting mysqld daemon with databases from /home/openxs/dbs/5.0/var

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 to server version: 5.0.23

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

mysql> drop procedure proc1;
Query OK, 0 rows affected (0.02 sec)

mysql> drop procedure proc2;
Query OK, 0 rows affected (0.00 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.0> bin/mysqlbinlog var/suse-bin.000003 --start-position=1149 | bin/mysql -uroot test
ERROR 1064 (42000) at line 11: 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 'select 2' at line 1

So, yes, you are right. It is a serious bug, it seems.

Any prospects for this bug to be fixed in next point release?

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

ChangeSet@1.2310, 2006-11-28 16:26:15+04:00, bar@mysql.com +12 -0
  Bug#20396 Bin Log does not get DELIMETER cmd - Recover StoredProc fails
  Problem: when loading mysqlbinlog dumps, CREATE PROCEDURE having semicolons
  in their bodies failed.
  Fix: Using safe delimiter "/*!*/;" to dump log entries.

Patch reviewed and works correctly. No problems with binlog replay WRT delimiter.

Pushed into 5.0.36, 5.1.15

Noted in 5.0.36, 5.1.15 changelogs.

A stored routines containing semicolon in its body could not be
reloaded from a dump of a binary log.