MySQL Bugs: #29861: problems (many errors) using mysqlbinlog...

Bug #29861	problems (many errors) using mysqlbinlog... \| mysql ...
Submitted:	18 Jul 2007 0:31	Modified:	23 Jul 2007 9:19
Reporter:	Don Cohen	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Backup	Severity:	S2 (Serious)
Version:	5.0.18-log	OS:	Linux
Assigned to:		CPU Architecture:	Any

Description:
The doc suggests that you should be able to recover by doing something like
 mysqlbinlog -d devel mysqld-bin.000002  |mysql --user="root" --password="..." --database="devel" 
and yet I get such things as
===
ERROR 1231 (42000) at line 19: Variable 'sql_mode' can't be set to the value of '524288'
I can't even tell what mode that is, but given that it was written into the log it ought to be redoable.
===
errors from defining stored procedures - in the log I see what appear to be normal
definitions of procedures with ; used to end statements.  Of course in the original the delimiter had been changed, but this doesn't seem to appear in the output of mysqlbinlog.  Instead I just get the sort of errors I'd get if the delimiter had not been changed
===
use of connection_id() in statements as if it were deterministic
I get this error:
ERROR 1064 (42000) at line 260: 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 'update lastuse set conn = null where conn = connection_id()' at line 5
Clearly the output of mysqlbinlog should be something like
 ... where conn=NAME_CONST(connection_id(),1234) ...
===
But I now see that NAME_CONST is also breaking.  The log shows thinks like
                   4957 Query       update lastuse set conn = 1750 where temppa\
ssword =  NAME_CONST('temppass',
COMMIT
                   4957 Quit
whenever it reaches a NAME_CONST in the file.
Unfortunately I don't even see any documentation for how to parse this, so I'm
having trouble writing something that fixes it.
Can you give me a hint?

How to repeat:
included above.  I only wish I knew how to NOT repeat it!
I'm not sure which part of the problem is in mysqlbinlog and which part is in the
server or for that matter the mysql client that reads the output of mysqlbinlog and sends the commands to the server.  I can send you whatever output you want.

Thank you for the report.

But version 5.0.18 is quite old. Please upgrade to current version 5.0.45, try with it and if you can repeat please upload your binary log file.

How old are the various versions?
It's not all that easy for me to switch versions, in fact may not be possible.
Until recently I was in 5.0.4(I think), which was the latest in the standard yum repositories for whichever fedora core I was in.  In fact I recently tried moving
another machine to the just released fedora core 7 where the yum version was 5.0.37.
Before I consider switching can you at least try these things and see which ones work in the latest?
Also I worry about what things will work differently if I switch.  Is there a list?

Thank you for the feedback.

> How old are the various versions?

Version 5.0.18 is more than 1 year old and hundreds of bug reports have been fixed since. You can find ChangeLogs at http://dev.mysql.com/doc/refman/5.0/en/news.html To test the bug please use our binaries available from http://dev.mysql.com/downloads/mysql/5.0.html

> Before I consider switching can you at least try these things and see which ones work in the latest?

We need your binary log file, I asked in previous comment for, to repeat the error. Please provide it.

In order to test this and generate a log file to submit I have to move to a more
recent mysql version.  Since I have 37 on my fedora core 7 I thought I'd try that.

Most of the problems seem solved here.
- replay of create procedure worked
- NAME_CONST was restored
  - not what I call well tested, but the appearances I see of NAME_CONST look
    much more reasonable 
    I now see NAME_CONST('z',_latin1'hello 14 3 4')
    whereas I used to see stuff like
    NAME_CONST('te\
mppass',^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@\
^@^@^@^@^@^@^@^@^@^@^@^@^@]^@^@^@v^@^@^@^A^@^@^@^@^@^@^@^L^@^@^@^@^@^@^@^@^@^@\
^@^@^@^@^@_latin1'ff136dde2f235f3015ee43ed734b0cad');
    where the binary data could contain ) and ' and all sorts of stuff that
    made it essentially unparsable
I don't yet have any setting of sql_mode other than 0 so I don't know whether that problem persists.
I still see the problem with connection_id()
Tbe output of mysqlbinlog contains
#070719 13:48:04 server id 1  end_log_pos 211   Query   thread_id=4     exec_time=0      error_code=0 
SET TIMESTAMP=1184878084/*!*/; 
insert into BugReport(text) values(concat("hello ",  NAME_CONST('x',13), " ",  NAME_CONST('y',2), " ", connection_id()))/*!*/; 

In the original this resulted in
|  2 | hello 13 2 4 |  
whereas after the restore I get
|  2 | hello 13 2 5 |  
So there's at least one bug in binary logging as of 5.0.37-log

If you could tell me how to parse the old style NAME_CONST then I might be
able to survive with what I have.
Actually, it would also help to know what the sql_mode constants mean.

Thank you for the feedback.

> I still see the problem with connection_id()

This is absolutely different case than initial report. Additionally I can not repeat it with current development sources. So, please, upgrade to current version 5.0.45 and if the problem still exists, open new bug report.

NAME_CONST problem is seems to be bug #22334.

> Actually, it would also help to know what the sql_mode constants mean.

Bug database is not a place for ask questions about usage of MySQL, but only place for reporting bugs in MySQL code. All answers you will find in the official manual located at http://dev.mysql.com/doc/refman/5.0/en/index.html Just find "SQL Modes" chapter.

Ok, I/ve now installed 5.0.45.
I get the same result as described in the last report.
Transcript (added comments marked by ###)
====
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.0.45-log MySQL Community Server (GPL)

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

mysql> use test;
Database changed
mysql> show tables;
Empty set (0.00 sec)

mysql>  CREATE TABLE BugReport( 
  PRIMARY KEY (id), 
  id INT(11) AUTO_INCREMENT NOT NULL, 
  text blob 
   ) TYPE=INNODB; 
    ->     ->     ->     -> Query OK, 0 rows affected, 1 warning (0.16 sec)

mysql> delimiter $
mysql> create procedure p1(in x integer) 
 begin  
 declare y text; 
 select concat("hi ",max(id)) into y from BugReport; 
 insert into BugReport(text) values(concat("hello ", x, " ", y, " ", connection_id(),now())); 
 end 
 $ 
    ->     ->     ->     ->     ->     -> Query OK, 0 rows affected (0.08 sec)

mysql> call p1(8)$
Query OK, 1 row affected (0.00 sec)

mysql> delimiter ;
mysql> select * from BugReport;
+----+------+
| id | text |
+----+------+
|  1 | NULL | 
+----+------+
1 row in set (0.00 sec)

mysql> call p1(7)$
    -> ;
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 '$' at line 1
mysql> call p1(7);
Query OK, 1 row affected (0.00 sec)

mysql> select * from BugReport;
+----+-----------------------------------+
| id | text                              |
+----+-----------------------------------+
|  1 | NULL                              | 
|  2 | hello 7 hi 1 12007-07-20 01:36:15 | 
+----+-----------------------------------+
2 rows in set (0.00 sec)

mysql> quit
Bye
[root@number8 mysql]# bin/mysqlbinlog -d test > /tmp/log1 ### error - see next
[root@number8 mysql]# bin/mysqlbinlog -d test data/number8-bin.000001 > /tmp/log1
[root@number8 mysql]# ./bin/mysql --user="root" --password="..." -e "drop database test"
[root@number8 mysql]# ./bin/mysql --user="root" --password="..." -e "create database test"
[root@number8 mysql]# ./bin/mysql --user="root" --password="..." test -e "show tables" ### since empty output is not very convincing ...
[root@number8 mysql]# ./bin/mysql --user="root" --password="..." 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 5
Server version: 5.0.45-log MySQL Community Server (GPL)

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

mysql> use test
Database changed
mysql> show tables;
Empty set (0.01 sec)

mysql> exit
Bye
[root@number8 mysql]# cat /tmp/log1 | ./bin/mysql --user="root" --password="..." test
[root@number8 mysql]# ./bin/mysql --user="root" --password="..." test -e "select * from BugReport"
+----+-----------------------------------+
| id | text                              |
+----+-----------------------------------+
|  1 | NULL                              | 
|  2 | hello 7 hi 1 62007-07-20 01:36:15 | 
+----+-----------------------------------+
====
The bug is demonstrated by the last line containing a 6 (the connection id of the process in which the restore was done) rather than a 1 as it did originally.
If you like I can send also the file /tmp/log1 containing the output of mysqlbinlog created above and used to do the restore.
The critical part is as I sent earlier:
#070720  1:36:15 server id 1  end_log_pos 236 	Query	thread_id=1	exec_time=0	error_code=0
SET TIMESTAMP=1184920575/*!*/;
insert into BugReport(text) values(concat("hello ",  NAME_CONST('x',7), " ",  NAME_CONST('y',_latin1'hi 1'), " ", connection_id(),now()))/*!*/;

> Just find "SQL Modes" chapter. 
I believe I read that but it doesn't connect the names to numbers.
I view that as a problem in documentation.

Thank you for the feedback.

CONNECTION_ID is separate issue from original report. So I created new Bug #29928 about this problem. Please subscribe to this new report and add you comments if you want.

Also please check original "syntax error" problem with new version and say us if problem still exists.

> CONNECTION_ID is separate issue from original report. So I created new Bug 
> #29928 about this problem. Please subscribe to this new report and add you 
> comments if you want.
Actually that was one of the problems described explicitly in the original report, but I'm satisfied with a separate bug.

> Also please check original "syntax error" problem with new version and say us > if problem still exists.
I have no reason to believe that the error message was really related to connection_id, but in any case that and all the other problems seem not to arise in .45.
I gather there is no interest in fixing old versions my means other than upgrading.

Thank you for the feedback.

I'll close the report as "Can't repeat" because last comment.