| Bug #38753 | Replication fails with Errno 1064: You have an error in your SQL syntax | ||
|---|---|---|---|
| Submitted: | 12 Aug 2008 18:19 | Modified: | 6 Nov 2008 7:13 |
| Reporter: | Michael McLagan | Email Updates: | |
| Status: | No Feedback | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S1 (Critical) |
| Version: | 5.0.67 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
[12 Aug 2008 18:19]
Michael McLagan
[12 Aug 2008 18:35]
Mats Kindahl
In order to analyze this one, it is necessary to see if it is really a case of BUG#26489, which it might not be, it is necessary to see what statement was actually attempted on the slave. To find out what statement it is, use mysqlbinlog on the relay log on the slave and look what is at position 649564 in relay-bin.000013. Also, to ensure that there is no error on master, the entry should be compared with what is at position 649424 in bin.022976.
[12 Aug 2008 18:40]
Sveta Smirnova
Thank you for the report. Could you please provide us relay-bin.000013 and bin.022944 so we can check if you only experience only same symptom of bug #26489 or cause is same too. You can upload them to our FTP server as described in "Files" section of the bug report interface.
[12 Aug 2008 18:42]
Michael McLagan
It blew up again, this time the attempted SQL is rather interesting, specifically:
--------------------------------------------------------------------------------
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 'AAND Location = '/kernel/v2.6/27-rc1' at line 1' on query. Default database: 'mysql'. Query: 'UPDATE advert.counter SET Value=Value+1 WHERE ObjectID = 1 AAND Location = '/kernel/v2.6/27-rc1'
--------------------------------------------------------------------------------
The master log shows:
# at 649501
#080807 22:44:22 server id 1 end_log_pos 649660 Query thread_id=2312546 exec_time=0 error_code=0
SET TIMESTAMP=1218163462/*!*/;
UPDATE advert.counter SET Value=Value+1 WHERE ObjectID = 1 AND ActionID = 1 AND RecordID = 1577/*!*/;
--------------------------------------------------------------------------------
The closest lines matching the 2nd part of the error are:
# at 372093
#080807 22:44:14 server id 1 end_log_pos 372286 Query thread_id=2312185 exec_time=0 error_code=0
SET TIMESTAMP=1218163454/*!*/;
UPDATE log_20080807.page SET Value = Value+1 WHERE PlaceID = 6 AND Location = '/kernel/v2.6/27-rc1-git6/include/asm-arm/shmbuf.h'/*!*/;
.....
# at 626170
#080807 22:44:21 server id 1 end_log_pos 626364 Query thread_id=2312018 exec_time=0 error_code=0
SET TIMESTAMP=1218163461/*!*/;
UPDATE log_20080807.target SET Value = Value+1 WHERE TxnID = 1 AND Location = '/kernel/v2.6/27-rc1-git6/include/asm-arm/uaccess.h'/*!*/;
--------------------------------------------------------------------------------
[12 Aug 2008 18:48]
Michael McLagan
Next time it blows up, I'll include the relevant relay log section, sorry bout that!
[12 Aug 2008 19:50]
Michael McLagan
I set up command to query the server status every 60 +/- seconds,
for i in `seq 0 1440`;
do
date; uptime; echo 'show slave status\G;' | mysql -vvv; sleep 60;
done > /tmp/monitor
The relevant output is below. binlog files have been uploaded, per request.
--------------------------------------------------------------------------------
Tue Aug 12 15:31:12 EDT 2008
15:31:12 up 83 days, 20:31, 3 users, load average: 5.95, 5.74, 6.05
Slave_IO_State: Queueing master event to the relay log
Connect_Retry: 60
Master_Log_File: bin.023197
Read_Master_Log_Pos: 4
Relay_Log_File: relay-bin.000089
Relay_Log_Pos: 98
Relay_Master_Log_File: bin.022975
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 20971459
Seconds_Behind_Master: 380729
1 row in set (36.29 sec)
Tue Aug 12 15:32:48 EDT 2008
15:32:48 up 83 days, 20:33, 3 users, load average: 5.26, 5.63, 5.98
Slave_IO_State: Queueing master event to the relay log
Connect_Retry: 60
Master_Log_File: bin.023198
Read_Master_Log_Pos: 20971459
Relay_Log_File: relay-bin.000091
Relay_Log_Pos: 857677
Relay_Master_Log_File: bin.022976
Slave_IO_Running: Yes
Slave_SQL_Running: No
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 '' at line 1' on query. Default database: 'mysql'. Query: 'UPDATE log_20080808.wgt Sû '
Skip_Counter: 0
Exec_Master_Log_Pos: 857537
Seconds_Behind_Master: NULL
1 row in set (28.79 sec)
--------------------------------------------------------------------------------
[12 Aug 2008 20:32]
Michael McLagan
I've uploaded the relevant files for this example too. I'll leave it in your collective hands, but you can see that the problem is rather frequent. :(
Master_Log_File: bin.023125
Read_Master_Log_Pos: 8148801
Relay_Log_File: relay-bin.000007
Relay_Log_Pos: 619898
Relay_Master_Log_File: bin.022978
Slave_IO_Running: Yes
Slave_SQL_Running: No
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 '' at line 1' on query. Default database: 'mysql'. Query: 'UPDATE advert.counter SET Value=Value+1 WHERE Object'
Skip_Counter: 0
Exec_Master_Log_Pos: 619758
[13 Aug 2008 6:04]
Sveta Smirnova
Thank you for the feedback. > I've uploaded the relevant files for this example too. What is the name of files you uploaded?
[16 Aug 2008 22:13]
Michael McLagan
This event looks different:
Relay_Log_File: relay-bin.001177
Relay_Log_Pos: 1945923
Relay_Master_Log_File: bin.023923
Slave_IO_Running: Yes
Slave_SQL_Running: No
Last_Errno: 0
Last_Error: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.
Skip_Counter: 0
Exec_Master_Log_Pos: 1945783
Relay_Log_Space: 1915471661
Seconds_Behind_Master: NULL
I uploaded another file with the relevant log files, similarly named to the others. I also included a listing of the log files stored in the mysql directory, hopefully that will provide some insight.
[17 Aug 2008 7:48]
Sveta Smirnova
Thank you for the uploaded files. We got them and trying to find how debug why relay logs are getting corrupted in your case.
[21 Aug 2008 2:00]
James Day
Michael, "I have just installed 5.0.67 on our slave server. Unfortunately, I have to report that the problem referenced in bug #26489 is not resolved, yet. ... MySQL 5.0.51a on master, 5.0.67 on slave." Please confirm that your master is really still running 5.0.51a. Bug #26489 is in the master part of the server, not the slave part. So if you haven't upgraded your master you aren't yet using the bug fix. James Day, MySQL Senior Support Engineer
[23 Aug 2008 6:20]
Michael McLagan
Yes, the master was running 5.0.51a. It was stopped again jsut now, so I downed the master, installed 5.0.67 and brought it back online, restarting the slave processes. I'll submit further comments if/when it fails again.
[25 Aug 2008 19:11]
Michael McLagan
After upgrading the server, the following is the result:
Master_Log_File: bin.025104
Read_Master_Log_Pos: 12483557
Relay_Log_File: relay-bin.000151
Relay_Log_Pos: 709294
Relay_Master_Log_File: bin.024746
Slave_IO_Running: Yes
Slave_SQL_Running: No
Last_Errno: 0
Last_Error: Query caused different errors on master and slave. Error on master: 'Invalid error code' (34304), Error on slave: '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 'b²
' at line 1' (1064). Default database: ''. Query: 'b²
'
Skip_Counter: 0
Exec_Master_Log_Pos: 709154
Seconds_Behind_Master: NULL
Relevant log files uploaded, named in sequence, as before. It appears that the server's operating version did not make a difference in the outcome, replication still trying to execute what appears to be random data from an improperly flushed/saved buffer.
[6 Oct 2008 7:13]
Susanne Ebrecht
Which character sets is your master/slave are using?
[7 Nov 2008 0:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
