Bug #14471 Relay bin log file corruption
Submitted: 29 Oct 2005 18:08 Modified: 2 Oct 2006 12:28
Reporter: Stephane PAQUOT Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.0.15 OS:Windows (Windows)
Assigned to: Assigned Account CPU Architecture:Any

[29 Oct 2005 18:08] Stephane PAQUOT
Description:
Hi

I am working with MySQL 5.0.15 in a replication system : the MySQL server DBA_T1_MYS is the master server and the MySQL server DBA_T2_MYS is the slave server.

Suddenly, the command SHOW SLAVE STATUS told me that the parameter relay-log-space-limit=100M was reached :

mysql> show slave status \G;
*************************** 1. row ***************************
             Slave_IO_State: Waiting for the slave SQL thread to free enough rel
ay log space
                 ...
                 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: 'cgcam'. Query: 'INSERT IN
TO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00, 15.22, C
☻☺'

051024 15:20:18 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
051024 15:20:19 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'blog_DBA_T1_MYS.000029' position 45404
051024 15:20:21 [ERROR] Slave: 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: 'cgcam'. Query: 'INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00, 15.22, C', Error_code: 1064
051024 15:20:21 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'blog_DBA_T1_MYS.000029' position 45228
051024 15:20:21 [Note] Slave: connected to master 'DBA_T2_MYS_maint@CGC:40102',replication resumed in log 'blog_DBA_T1_MYS.000029' at position 45404

When I ran the command mysqlbinlog on the relay log file relay_DBA_T2_M
YS.000075, I got the following special characters at position 45371 :

#051024 15:18:45 server id 1  end_log_pos 45228         Query   thread_id=2
exec_time=0     error_code=0
SET TIMESTAMP=1130159925;
INSERT INTO t_bck_cpt_ope VALUES (53, 1, 7, 13, '2004-02-14', '2004-02-16', 0.00
, 19.50, 'Gilles Evolutif 14/02/2004');
# at 45371
#051024 15:18:45 server id 1  end_log_pos 45404         Query   thread_id=2
exec_time=0     error_code=0
SET TIMESTAMP=1130159925;
INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00,
 15.22, C☻☺   └   ¦Æ    ☻       ;
# at 45547
#051024 15:20:23 server id 2  end_log_pos 45597         Rotate to relay_DBA_T2_M
YS.000076  pos: 4
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

The relay log file relay_DBA_T2_MYS.000075 seems corrupted.

In the binary log of the master server, all is ok :

mysqlbinlog C:\dba\mysql\DBA_T1_MYS\binlogs\blog_DBA_T
1_MYS.000029 --start-position=45228 --stop-position=45586

# at 45228
#051024 15:18:45 server id 1  end_log_pos 45404         Query   thread_id=2
exec_time=0     error_code=0
use cgcam;
SET TIMESTAMP=1130159925;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.uniq
ue_checks=1;
SET @@session.sql_mode=0;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.
collation_server=8;
INSERT INTO t_bck_cpt_ope VALUES (54, 1, 7, 0, '2004-02-14', '2004-02-16', 0.00,15.22, 'HIDDEN INFO 1');
# at 45404
#051024 15:18:45 server id 1  end_log_pos 45586         Query   thread_id=2
exec_time=0     error_code=0
SET TIMESTAMP=1130159925;
INSERT INTO t_bck_cpt_ope VALUES (55, 1, 7, 10, '2004-02-17', '2004-02-18', 0.00, 18.60, 'HIDDEN INFO 2');
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

To solve the problem, the insert statement has been executed manually agains the slave server and the replication system has been restarted with the command SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1 before the command START SLAVE.

How to repeat:
Unable to repeat the corruption on a relay log file

Suggested fix:
To solve the problem, the insert statement has been executed manually agains the slave server and the replication system has been restarted with the command SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1 before the command START SLAVE.
[31 Oct 2005 11:50] MySQL Verification Team
Hello Stephane,

Thank you for the report, but we really need a repeatable test case the for bug report to reproduce and then fix this problem.
[2 Nov 2005 22:43] Stephane PAQUOT
Hello Victoria,

I'm sorry, it is very difficult to repeat the case. Since the last corruption in the relay log file relay_DBA_T2_MYS.000075, the problem did not occur again with the same stress test (108000 insertions).
It is very interesting to notice that MySQL decided to make a rotation of the relay log just after the corruption.
I understand if you close this case as it is not reproductible.
[6 Nov 2005 9:38] Valeriy Kravchuk
Please, reopen this bug report in case of new similar failure. May be, it was some kind of network failure that lead to corruption.
[7 Dec 2005 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".
[31 Aug 2006 19:46] Lars Thalmann
Please consider using 'mysqldump --hexdump' to show which characters
are being wrongly encoded.
[31 Aug 2006 20:16] Sveta Smirnova
Null characters are escaped by \{null character itself} instead of  correct \0.
[5 Sep 2006 11:29] Stephane PAQUOT
As I could not provide a reproductible case last year in December 2005, I have dumped the table, truncated this one and reloaded this table from the backup. No issue has been reported with this reload by the replication system. So I'm not able to give you the mysqldump with --hexdump option to give you the initial status with encoding when the issue occured, I'm really sorry. Further more, I have upgraded to version 5.0.24a. I can build a 5.0.15 system with replication to try to reproduce this encoding issue if you wish.
[28 Sep 2006 22:52] Andrei Elkin
Sveta, after reading support documents i don't think this old bug really match your current issue. And to back this up:

1. in the old bug manifests as a sudden reaching relay-log-space-limit, with a show slave status reporting the offending query; there is mentioning on rotation  log event also.
2. there is even no evindence of a common part betten old and new cases. The old reporter provided the original of the query as it was in master binlog, which is different from 
what appeared in relay-log of slave. But in new case, there is no master's version. This makes answering to the customer's question why this "scrumbling" happens hardly possible.

I suggest to close this bug, to file a new bug and ask the customer to provide the original  master's statement.
[2 Oct 2006 12:28] Sveta Smirnova
As Andrei requested opened new bug #22889 for 4.0 issue and returned status to "No feedback" for this one.