MySQL Bugs: #48216: Replication fails on all slaves after upgrade to 5.0.86 on master

Bug #48216	Replication fails on all slaves after upgrade to 5.0.86 on master
Submitted:	21 Oct 2009 21:12	Modified:	21 Jun 2010 0:42
Reporter:	Kevin Marion	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.0.86, 5.1.41-bzr	OS:	Any (RHEL5, Mac OS X)
Assigned to:	Libing Song	CPU Architecture:	Any
Tags:	5.0.86, bin log, binary log, drop table, drop temporary table, regression, replication, signal 6

Description:

====================================
Issue
====================================
All slaves were upgraded to 5.0.86. Master was upgraded to 5.0.86.

A BASH script is running a report and creating temporary tables. When the process exists the MySQL session, it does not drop the temporary tables and depends on MySQL to drop the temporary tables on session close. This was working in the following versions
# mysql -V (Should have used the command mysqld -V)
mysql Ver 14.12 Distrib 5.0.67, for redhat-linux-gnu (x86_64) using readline 5.1
# mysqld -V
mysqld  Ver 5.0.77-community-log for pc-linux-gnu on i686 (MySQL Community Edition (GPL))

After upgrading to a newer version, replication to the slaves fail.
# mysqld -V
mysqld  Ver 5.0.86-community-log for unknown-linux-gnu on x86_64 (MySQL Community Edition (GPL))

Initially, there were problems attempting to recreate the error thinking it was related to the length of the table name. These attempts were not successful.

The problem now, is that I'm not sure how to get replication going again. Using "SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1;" starts the slave but soon crashes the mysqld process again as the report is run often.

The job causing the problem has been stopped. Fixing the script will be fairly simple now that it is understood what the problem is related to.

====================================
Error Log on Slave
====================================

Error Log reports the following error after upgrade

[... Prior data removed]
091021 15:00:42  InnoDB: Starting shutdown...
091021 15:00:43  InnoDB: Shutdown completed; log sequence number 0 13681783
091021 15:00:43 [Note] /usr/sbin/mysqld: Shutdown complete

091021 15:00:43  mysqld ended

091021 15:00:46  mysqld started
091021 15:00:47  InnoDB: Started; log sequence number 0 13681783
091021 15:00:47 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=mysql-relay-bin' to avoid this problem.
091021 15:00:48 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.0.86-community-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Edition (GPL)
091021 15:00:56 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000847' at position 49836200, relay log './mysql-relay-bin.000179' position: 49836337
091021 15:00:56 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=536870912
read_buffer_size=4194304
max_used_connections=1
max_connections=2000
threads_connected=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 16908288 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0x1005bd60
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
Cannot determine thread, fp=0x41afc098, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
(nil)
New value of fp=0x1005bd60 failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0xfead78e = DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `monitor_silver_us__tbl_dst_2009102067501`,`monitor_silver_us_tbl_src_2009102067501`
thd->thread_id=7
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file

Number of processes running now: 0
091021 15:00:56  mysqld restarted
091021 15:00:57  InnoDB: Started; log sequence number 0 13681783
091021 15:00:57 [Note] Recovering after a crash using mysql-bin
091021 15:00:57 [Note] Starting crash recovery...
091021 15:00:57 [Note] Crash recovery finished.
091021 15:00:57 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=mysql-relay-bin' to avoid this problem.
091021 15:00:57 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.0.86-community-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Edition (GPL)

How to repeat:

====================================
Recreate the Error: Modify as needed
====================================

cat <<-HEREDOC > /tmp/setup.sql
create database namemorethentenchar;
create database test;
GRANT USAGE ON *.* TO devtest@'%' IDENTIFIED BY 'd8Iy3pPl1nBd';
GRANT USAGE ON *.* TO devtest@'localhost' IDENTIFIED BY 'd8Iy3pPl1nBd';
GRANT ALL PRIVILEGES ON namemorethentenchar.* TO devtest@'%';
GRANT ALL PRIVILEGES ON test.* TO devtest@'%';
GRANT ALL PRIVILEGES ON namemorethentenchar.* TO devtest@'localhost';
GRANT ALL PRIVILEGES ON test.* TO devtest@'localhost';
HEREDOC

cat <<-HEREDOC > /tmp/test12.sql
create temporary table test.mytest12a(mynum int);
create temporary table test.mytest12b(mynum int);
HEREDOC

mysql -uroot -p -hlocalhost < /tmp/setup.sql

mysql -udevtest -pd8Iy3pPl1nBd -hlocalhost < /tmp/test12.sql

====================================
Previous Output of mysqlbinlog
# mysqld -V
mysqld Ver 5.0.77-community-log for pc-linux-gnu on i686 (MySQL
Community Edition (GPL))
====================================
Note the statement "DROP /*!40005 TEMPORARY */" identifies the schema name.
====================================

# at 4195
#091021 20:00:00 server id 5 end_log_pos 4302 Query thread_id=32858
exec_time=0 error_code=0
SET TIMESTAMP=1256155200/*!*/;
SET @@session.pseudo_thread_id=32858/*!*/;
create temporary table test.mytest12b(mynum int)
/*!*/;
# at 4302
#091021 20:00:00 server id 5 end_log_pos 4441 Query thread_id=32858
exec_time=0 error_code=0
SET TIMESTAMP=1256155200/*!*/;
SET @@session.pseudo_thread_id=32858/*!*/;
/*!\C utf8 *//*!*/;
SET
@@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS
`test`.`mytest12b`,`test`.`mytest12a`
/*!*/;

====================================
Current Output of mysqlbinlog
# mysqld -V
mysqld Ver 5.0.86-community-log for unknown-linux-gnu on x86_64 (MySQL
Community Edition (GPL))
====================================
Note the statement "DROP /*!40005 TEMPORARY */" does not identify the
schema name but is dependant on a prior "use" statement that is
truncated and incorrect. Should probably be something similar to "use
test/*!*/;"
====================================
# at 2323
#091021 19:42:41 server id 1 end_log_pos 2448 Query thread_id=193
exec_time=0 error_code=0
use tDROP /*!40005 TEMPORARY */ TABLE IF EXISTS
`mytest12b`,`mytest12a`/*!*/;
SET TIMESTAMP=1256154161/*!*/;
SET @@session.pseudo_thread_id=193/*!*/;
/*!\C utf8 *//*!*/;
SET
@@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `mytest12b`,`mytest12a`
/*!*/;
# at 2448
#091021 19:42:52 server id 1 end_log_pos 2491 Rotate to
mysql-bin.000062 pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

This looks like a regression related to the fix for bug #46861.

Confirmed 5.0.83 works correctly when writing the DROP temporary table command to the bin log.

# mysqld -V
mysqld  Ver 5.0.83-community-log for pc-linux-gnu on i686 (MySQL Community Edition (GPL))

I think this needs upgraded to severity S2. If a person performs the actions described in bug #46861, this basically "corrupts" the bin log in the community release of MySQL. If I'm understanding correctly, in case of a server failure, using the bin log to recover wouldn't be possible.

I've already downgraded to 5.0.83 in production (since I know this release doesn't have the issue I'm concerned about) and having to manually re-sync the data to the replication servers as I was unable to use the bin log in the current state from 5.0.86 to recover replication.

Question: Does this issue exist in the most recent Enterprise version?

Verified just as described with recent 5.1.41 from bzr also:

77-52-222-60:5.1 openxs$ bin/mysql -uroot -pmysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.1.41-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create temporary table test.mytest12a(mynum int);
Query OK, 0 rows affected (0.00 sec)

mysql> create temporary table test.mytest12b(mynum int);
Query OK, 0 rows affected (0.01 sec)

mysql> exit
Bye
77-52-222-60:5.1 openxs$ bin/mysqlbinlog -uroot -pmysql var/openxs.000001 
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#091026  6:53:58 server id 1  end_log_pos 106 	Start: binlog v 4, server v 5.1.41-debug-log created 091026  6:53:58 at startup

...

/*!*/;
# file_id: 1 
# at 1890
#091026  9:29:41 server id 1  end_log_pos 2000 	Query	thread_id=2	exec_time=0	error_code=0
SET TIMESTAMP=1256542181/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
create temporary table test.mytest12a(mynum int)
/*!*/;
# at 2000
#091026  9:29:41 server id 1  end_log_pos 2110 	Query	thread_id=2	exec_time=0	error_code=0
SET TIMESTAMP=1256542181/*!*/;
create temporary table test.mytest12b(mynum int)
/*!*/;
# at 2110
#091026  9:30:08 server id 1  end_log_pos 2238 	Query	thread_id=2	exec_time=0	error_code=0
use testDROP /*!40005 TEMPORARY */ TABLE IF EXISTS `mytest12b`,`mytest12a`/*!*/;
SET TIMESTAMP=1256542208/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `mytest12b`,`mytest12a`
/*!*/;
# at 2238
#091026  9:30:17 server id 1  end_log_pos 2345 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1256542217/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
create temporary table test.mytest12a(mynum int)
/*!*/;
# at 2345
#091026  9:30:17 server id 1  end_log_pos 2452 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1256542217/*!*/;
create temporary table test.mytest12b(mynum int)
/*!*/;
# at 2452
#091026  9:30:24 server id 1  end_log_pos 2577 	Query	thread_id=3	exec_time=0	error_code=0
use tDROP /*!40005 TEMPORARY */ TABLE IF EXISTS `mytest12b`,`mytest12a`/*!*/;
SET TIMESTAMP=1256542224/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `mytest12b`,`mytest12a`
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

See possibly-related Bug#48297

Added to Tags: bin log, binary log

Description:
===========
When sessions are closed, any temporary tables of the sessions are dropped and then are binlogged with wrong database names. Because of this, replication fails.

There was an wrong log event which was printed by mysqlbinlog:
===
use tDROP /*!40005 TEMPORARY */ TABLE IF EXISTS
===
`mytest12b`,`mytest12a`/*!*/;
SET TIMESTAMP=1256154161/*!*/;
SET @@session.pseudo_thread_id=193/*!*/;
/*!\C utf8 *//*!*/;
SET
@@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_ser
ver=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `mytest12b`,`mytest12a`
/*!*/;

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/88463

2816 Li-Bing.Song@sun.com	2009-10-28
      BUG#48216 Replication fails on all slaves after upgrade to 5.0.86 on master
      
      When a sessione is closed, all temporary tables of the session are automatically 
      dropped and are binlogged. But it will be binlogged with wrong database names when
      the length of the temporary tables' database names are greater than the 
      length of the current database name or the current database is not set.
      
      Query_log_event's db_len is forgot to set when Query_log_event's db is set.
      This patch wrote code to set db_len immediately after db has set.

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/89036

2836 Li-Bing.Song@sun.com	2009-11-03
      BUG#48216 Replication fails on all slaves after upgrade to 5.0.86 on master
      
      When a sessione is closed, all temporary tables of the session are automatically 
      dropped and are binlogged. But it will be binlogged with wrong database names when
      the length of the temporary tables' database names are greater than the 
      length of the current database name or the current database is not set.
      
      Query_log_event's db_len is forgot to set when Query_log_event's db is set.
      This patch wrote code to set db_len immediately after db has set.

Pushed into 5.0.88 (revid:joro@sun.com-20091104091355-hpz6dwgkrfmokj3k) (version source revid:li-bing.song@sun.com-20091103090041-zj7nedx6ok5jgges) (merge vers: 5.0.88) (pib:13)

Pushed into 5.1.41 (revid:joro@sun.com-20091104092152-qz96bzlf2o1japwc) (version source revid:kristofer.pettersson@sun.com-20091103162305-08l4gkeuif2ozsoj) (merge vers: 5.1.41) (pib:13)

Documented bugfix in the 5.0.88 and 5.1.41 changelogs as follows:

        When a session was closed on the master, temporary tables
        belonging to that session were logged with the wrong database
        names when either of the following conditions was true:

            The length of the name of the database to which the
            temporary table belonged was greater than the length of the
            current database name.
          
            The current database was not set.

Closed.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091110093407-rw5g8dys2baqkt67) (version source revid:alik@sun.com-20091109080109-7dxapd5y5pxlu08w) (merge vers: 6.0.14-alpha) (pib:13)

Pushed into 5.5.0-beta (revid:alik@sun.com-20091109115615-nuohp02h8mdrz8m2) (version source revid:alik@sun.com-20091105121316-hgdduu5vqdpbawf8) (merge vers: 5.5.0-beta) (pib:13)

Also documented in the 5.5.0 and 6.0.14 changelogs; re-closing.

Noted in 5.1.40sp1 changelog.

Pushed into 5.1.43 (revid:build@mysql.com-20091208092611-pbno5awyb0v38hs7) (version source revid:build@mysql.com-20091208092611-pbno5awyb0v38hs7) (merge vers: 5.1.43) (pib:13)

Already in in 5.1.41 changelog; re-closing.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091216083311-xorsasf5kopjxshf) (version source revid:alik@sun.com-20091215065750-5m04ogppd5l0pol5) (merge vers: 6.0.14-alpha) (pib:14)

Pushed into 5.5.0-beta (revid:alik@sun.com-20091216082430-s0gtzibcgkv4pqul) (version source revid:alik@sun.com-20091211070127-kl8uvlrv9cr11kva) (merge vers: 5.5.0-beta) (pib:14)

Pushed into mysql-next-mr (revid:alik@sun.com-20091216083231-rp8ecpnvkkbhtb27) (version source revid:alik@sun.com-20091212203859-fx4rx5uab47wwuzd) (merge vers: 5.6.0-beta) (pib:14)

Also documented in the 5.6.0 changelog, no other changelog entries required.

Closed.

Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)

Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)

Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)

Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)

No additional changelog entries needed. Setting back to Closed state.

Noted in 5.0.87sp1 changelog.

Pushed into 5.0.91 (revid:build@mysql.com-20100220170835-5kr6ztsg25va7qzz) (version source revid:build@mysql.com-20100220170835-5kr6ztsg25va7qzz) (merge vers: 5.0.91) (pib:16)

Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:joro@sun.com-20100226131646-kpvzk740hxbtaexn) (merge vers: 5.1.45) (pib:16)

Fix already noted in the 5.0.87sp1/5.0.88/5.1.41 changelogs; no new changelog entries required. Re-closing.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100302142746-u1gxdf5yk2bjrq3e) (version source revid:alik@sun.com-20100301095421-4cz64ibem1h2quve) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.3-m2 (revid:alik@sun.com-20100302072233-t3uqgjzdukt1pyhe) (version source revid:alik@sun.com-20100301090215-63o2w2y16go8n53p) (merge vers: 5.5.3-m2) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100302072432-k8xvfkgcggkwgi94) (version source revid:alik@sun.com-20100301094536-2zc4uqyy3os8san7) (pib:16)

Already documented in 5.5.5/6.0.14 changelogs. Re-closing.

5.6.0 changelog entry unneeded.

Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100312135944-t0z8s1da2orvl66x) (version source revid:jonas@mysql.com-20100312115609-woou0te4a6s4ae9y) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)

Pushed into 5.1.44-ndb-6.2.19 (revid:jonas@mysql.com-20100312134846-tuqhd9w3tv4xgl3d) (version source revid:jonas@mysql.com-20100312060623-mx6407w2vx76h3by) (merge vers: 5.1.44-ndb-6.2.19) (pib:16)

Pushed into 5.1.44-ndb-6.3.33 (revid:jonas@mysql.com-20100312135724-xcw8vw2lu3mijrhn) (version source revid:jonas@mysql.com-20100312103652-snkltsd197l7q2yg) (merge vers: 5.1.44-ndb-6.3.33) (pib:16)

5.1-main -> telco merge only; no new changelog entries required. Closed.

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609140708-52rvuyq4q500sxkq) (merge vers: 5.1.45-ndb-6.2.19) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)