Bug #46697 Table name in error message is not populated
Submitted: 13 Aug 2009 13:43 Modified: 6 Jan 2011 14:39
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.0, 5.1, 5.4.4 OS:Any
Assigned to: Luis Soares CPU Architecture:Any
Triage: Triaged: D4 (Minor)

[13 Aug 2009 13:43] Elena Stepanova
Description:
If slave SQL thread aborts due to different errors on master and slave, when the query on master failed with error 1146, the error message shown in slave status and slave error log contains a table name template (%-.192s.%-.192s) instead of the real name:

Query caused different errors on master and slave.     Error on master: 'Table '%-.192s.%-.192s' doesn't exist' (1146), Error on slave: 'no error' (0). Default database: 'test'. Query: 'insert into tbl1_broken_err_msg values (1)'

This can make investigation of the problem tricky if many tables are involved.

How to repeat:
# The test is for 5.1 and above
# t/rpl_broken_err_msg.test

--source include/master-slave.inc

--disable_result_log

set global binlog_format = statement;
connect (m,127.0.0.1,root,,test,$MASTER_MYPORT,);
connect (s,127.0.0.1,root,,test,$SLAVE_MYPORT,);

connection m;

use test;
--disable_warnings
drop table if exists tbl1_broken_err_msg;
drop trigger if exists trig_broken_err_msg;
--enable_warnings
create table tbl1_broken_err_msg ( i int ) engine = MyISAM;
create trigger trig_broken_err_msg after insert on tbl1_broken_err_msg 
	for each row insert into tbl2_broken_err_msg values (new.i);

connection s;
create table tbl2_broken_err_msg ( i int ) engine = MyISAM;

connection m;
--error 1146
insert into tbl1_broken_err_msg values (1);

connection s;
--real_sleep 1
let $err_msg = query_get_value(show slave status, 'Last_SQL_Error', 1);

--echo # Error message: $err_msg
[17 Nov 2010 18:38] Davi Arnaut
The print in replication code does not perform formatting on the error message. For example:

Query caused different errors on master and slave. \
Error on master: '%s' (%d), Error on slave: '%s' (%d). \
Default database: '%s'. Query: '%s'",
ER_SAFE(expected_error),

define ER_SAFE(X) (((X) >= ER_ERROR_FIRST && (X) <= ER_ERROR_LAST) ? ER(X) : "Invalid error code")

So, it just takes the error code and prints the format of the message associated with it. I don't think its possible to fix this. Only the error code is transported from the master to the slave. If the error code does not happen on the slave, it's not possible to know what was the error message on the master

 Anyway, this is not exactly error related, better check with replication guys.
[18 Nov 2010 10:53] Davi Arnaut
Perhaps the solution is to make it clear that what is being printed is the error message format.
[3 Dec 2010 17:18] 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/125986

3512 Luis Soares	2010-12-03
      BUG#46697: Table name in error message is not populated
      
      When a query fails with a different error on the slave,
      the sql thread outputs a message (M) containing:
      
        1. the error message format for the master error code
        2. the master error code
        3. the error message for the slave's error code
        4. the slave error code
      
      Given that the slave has no information on the error message
      itself that the master outputs, it can only print its own
      version of the message format (but stripped from the 
      additional data if the message format requires). This may
      confuse users.
      
      To fix this we augment the slave's message (M) to explicitly
      state that the master's message is actually an error message 
      format, the one associated with the given master error code 
      and that the slave server knows about.
[14 Dec 2010 17:34] 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/126817

3523 Luis Soares	2010-12-14 [merge]
      BUG#46697
      
      Autmoerging into latest mysql-5.1-bugteam.
[14 Dec 2010 17:41] Luis Soares
Queued in mysql-5.1-bugteam, mysql-5.5-bugteam, mysql-trunk-bugfixing.
[17 Dec 2010 12:49] Bugs System
Pushed into mysql-5.1 5.1.55 (revid:georgi.kodinov@oracle.com-20101217124435-9imm43geck5u55qw) (version source revid:luis.soares@oracle.com-20101214173345-191y2ctyqny1biv5) (merge vers: 5.1.55) (pib:24)
[17 Dec 2010 12:53] Bugs System
Pushed into mysql-5.5 5.5.9 (revid:georgi.kodinov@oracle.com-20101217124733-p1ivu6higouawv8l) (version source revid:luis.soares@oracle.com-20101214173540-vp8vwkdz7pgzpi58) (merge vers: 5.5.8) (pib:24)
[17 Dec 2010 12:56] Bugs System
Pushed into mysql-trunk 5.6.1 (revid:georgi.kodinov@oracle.com-20101217125013-y8pb3az32rtbplc9) (version source revid:mats.kindahl@oracle.com-20101215103340-a0wp0yq8t4byel1o) (merge vers: 5.6.1) (pib:24)
[4 Jan 2011 3:47] Jon Stephens
I've asked Paul to handle documentation of this bugfix, since he's already taking care of the related Docs bug.
[6 Jan 2011 14:39] Paul Dubois
Noted in 5.1.55, 5.5.9 changelogs.

Previously, when a statement failed with a different error on the
slave than on the master, the slave SQL thread displayed a message
containing: 

* The error message for the master error code
* The master error code
* The error message for the slaves error code
* The slave error code

However, the slave has no information with which to fill in any print
format specifiers for the master message, so it actually displayed
the message format string. To make it clearer that the slave is not 
displaying the actual message as it appears on the master, the slave
now indicates that the master part of the output is the message
format, not the actual message. For example, previously the slave
displayed information like this:
            
Error: "Query caused different errors on master and slave. Error on
master: 'Duplicate entry '%-.192s' for key %d' (1062), Error on
slave: 'no error' (0). Default database: 'test'. Query: 'insert into
t1 values(1),(2)'" (expected different error codes on master and
slave) 

Now the slave displays this:

Error: "Query caused different errors on master and slave. Error on
master: message format='Duplicate entry '%-.192s' for key %d' error 
code=1062 ; Error on slave: actual message='no error', error code=0.
Default database: 'test'. Query: 'insert into t1 values(1),(2)'"
(expected different error codes on master and slave)