Bug #30854 Tables name show as binary in slave err msg on vm-win2003-64-b
Submitted: 6 Sep 2007 10:50 Modified: 9 Nov 2007 16:36
Reporter: Jonathan Miller Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:mysql-5.1-telco-6.2 OS:Microsoft Windows (vm-win2003-64-b)
Assigned to: Marc Alff CPU Architecture:Any

[6 Sep 2007 10:50] Jonathan Miller
Description:
Reviewing failures in push build on rpl_extraColmaster tests I found the following on vm-win2003-64-b:

*** 876,882 ****
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
--- 876,882 ----
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in 'u�'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
***************
*** 894,900 ****
  Last_IO_Errno	0
  Last_IO_Error	
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;
  
--- 894,900 ----
  Last_IO_Errno	0
  Last_IO_Error	
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in 'u�'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;
  
***************
*** 2016,2022 ****
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
--- 2016,2022 ----
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in 'u�'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
***************
*** 2034,2040 ****
  Last_IO_Errno	0
  Last_IO_Error	
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;
  
--- 2034,2040 ----
  Last_IO_Errno	0
  Last_IO_Error	
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in 'u�'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;

How to repeat:
run test in vm-win2003-64-b:
[7 Sep 2007 2:09] Jonathan Miller
sol10-sparc-a

*** 876,882 ****
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
--- 876,882 ----
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in 'ٽ'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
***************
*** 894,900 ****
  Last_IO_Errno	#
  Last_IO_Error	#
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;
  
--- 894,900 ----
  Last_IO_Errno	#
  Last_IO_Error	#
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in 'ٽ'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;
  
***************
*** 2016,2022 ****
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
--- 2016,2022 ----
  Replicate_Wild_Do_Table	
  Replicate_Wild_Ignore_Table	
  Last_Errno	1054
! Last_Error	Error 'Unknown column 'c7' in '��5'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  Skip_Counter	0
  Exec_Master_Log_Pos	#
  Relay_Log_Space	#
***************
*** 2034,2040 ****
  Last_IO_Errno	#
  Last_IO_Error	#
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in 't15'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;
  
--- 2034,2040 ----
  Last_IO_Errno	#
  Last_IO_Error	#
  Last_SQL_Errno	1054
! Last_SQL_Error	Error 'Unknown column 'c7' in '��5'' on query. Default database: 'test'. Query: 'ALTER TABLE t15 ADD COLUMN c2 DECIMAL(8,2) AFTER c7'
  STOP SLAVE;
  RESET SLAVE;
[24 Oct 2007 9:26] Sven Sandberg
According to Bar, the ugly characters are not letters any character set, so this is probably a memory corruption. The relevant error code is ER_BAD_FIELD_ERROR, and it is probably an Item->name that is corrupted.
[24 Oct 2007 12:54] Sven Sandberg
The test case that fails is called rpl_extraColmaster_innodb.

The bug appears on pushbuild, only in 5.1-telco-6.2 (not 5.1-new-rpl), and only on vm-win2003-64-b. (Not on non-windows or non-64bit, not even Linux with valgrind).   See https://intranet.mysql.com/secure/pushbuild/showdir.pl?dir=mysql-5.1-telco-6.2
[24 Oct 2007 16:50] Marc Alff
Investigating
[25 Oct 2007 0:19] Marc Alff
Analysis:

In sql/sql_table.cc, the following call:
my_error(ER_BAD_FIELD_ERROR, MYF(0), def->change, table->s->table_name);
uses a LEX_STRING structure instead of a const char* parameter.

In 5.1, the LEX_STRING structure has recently changed from
  uint length
to
  size_t length

The sizeof() and alignment of the length attribute has an impact on the alignment of the LEX_STRING structure itself,
which explains why this call *appear* to work on some platforms, and fails on others.

In any case, calling my_error with a LEX_STRING is wrong, since the structure is added by copy on the stack, possibly confusing my_error() for subsequent parameters.
[25 Oct 2007 0:27] Marc Alff
Dirty trick to find (most) of the offending calls:

===== mysql_priv.h 1.545 vs edited =====
2333a2334,2356
> #define DEBUG_PARANOID
>
> #ifdef DEBUG_PARANOID
> #ifdef __cplusplus
> /* won't link if called, fix the call to my_error(). */
> extern int do_not_call_my_error_with_LEX_STRING();
> inline int my_error _VARARGS((int, myf, LEX_STRING, ...))
> { return do_not_call_my_error_with_LEX_STRING(); }
> inline int my_error _VARARGS((int, myf, const char*, LEX_STRING, ...))
> { return do_not_call_my_error_with_LEX_STRING(); }
>
> /* won't link if called, fix the call to push_warning_printf(). */
> extern void do_not_call_push_warning_printf_with_LEX_STRING();
> inline void push_warning_printf(THD *, MYSQL_ERROR::enum_warning_level,
>   uint code, const char *format, LEX_STRING, ...)
> { do_not_call_push_warning_printf_with_LEX_STRING(); }
> inline void push_warning_printf(THD *, MYSQL_ERROR::enum_warning_level,
>   uint code, const char *format, const char*, LEX_STRING, ...)
> { do_not_call_push_warning_printf_with_LEX_STRING(); }
>
> #endif
> #endif
>
[25 Oct 2007 1:01] 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/36312

ChangeSet@1.2598, 2007-10-24 19:01:08-06:00, malff@lambda.hsd1.co.comcast.net. +2 -0
  Bug#30854 (Tables name show as binary in slave err msg on vm-win2003-64-b)
  
  The root cause of this defect is that a call to my_error() is using a
  'LEX_STRING' parameter instead of a 'char*'
  
  This patch fixes the failing calls to my_error(), as well as similar calls
  found during investigation.
  
  This is a compiling bug (see the instrumentation in the bug report), no test cases provided.
[7 Nov 2007 21:59] Bugs System
Pushed into 6.0.4-alpha
[7 Nov 2007 22:01] Bugs System
Pushed into 5.1.23-rc
[9 Nov 2007 16:36] Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Documented bugfix in 5.1.23 and 6.0.4 changelogs.
[19 Dec 2008 11:17] 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/62076

2763 Alfranio Correia	2008-12-19
      Disabled test case rpl_extraColmaster_innodb due to BUG#30854 which
      is apparently fixed. However, there are still failures in pushbuild.
[30 Jan 2009 13:28] Bugs System
Pushed into 6.0.10-alpha (revid:luis.soares@sun.com-20090129165607-wiskabxm948yx463) (version source revid:luis.soares@sun.com-20090129163120-e2ntks4wgpqde6zt) (merge vers: 6.0.10-alpha) (pib:6)