MySQL Bugs: #46697: Table name in error message is not populated

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

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

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.

Perhaps the solution is to make it clear that what is being printed is the error message format.

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.

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.

Queued in mysql-5.1-bugteam, mysql-5.5-bugteam, mysql-trunk-bugfixing.

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)

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)

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)

I've asked Paul to handle documentation of this bugfix, since he's already taking care of the related Docs bug.

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)