MySQL Bugs: #47983: rpl_extraColmaster_myisam failed in PB2 with "Found warnings!!"

Bug #47983	rpl_extraColmaster_myisam failed in PB2 with "Found warnings!!"
Submitted:	12 Oct 2009 0:57	Modified:	15 Mar 2010 4:22
Reporter:	Luis Soares	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Tests: Replication	Severity:	S3 (Non-critical)
Version:	5.1.40	OS:	MacOS (all CPUs)
Assigned to:	Luis Soares	CPU Architecture:	Any

Description:
Test case failed in PB2.

Failure data:

Where 	Build 	Test 	Run 	Suite 	Case 	Mode 	When
mysql-6.0-codebase-bugfixing
573075	tree-max-win-x86-zip
573102 loki02	test-max-win_ws2008-x86
573670 tyr26	ps_row	rpl	rpl_extraColmaster_myisam	None	2009-10-10 14:37:44

Failure Symptom:

rpl.rpl_extraColmaster_myisam            [ fail ]  Found warnings/errors in server log file!
        Test ended at 2009-10-10 19:58:33
file_name	line
H:/pb2/test/sb_2-814437-1255182695.83/mysql-6.0.14-alpha-win-x86-test/mysql-test/var-ps_row/log/mysqld.2.err	091010 20:58:27 [Warning] Slave I/O: Get master SERVER_ID failed with error: Lost connection to MySQL server during query, Error_code: 2013
^ Found warnings!!
ok
mysqltest: Logging to ''.
mysqltest: Results saved in ''.
mysqltest: Connecting to server localhost:19281 (socket H:/pb2/test/sb_2-814437-1255182695.83/mysql-6.0.14-alpha-win-x86-test/mysql-test/var-ps_row/tmp/mysqld.2.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from '.\include\check-warnings.test' ...
mysqltest: ... Done processing test commands.
mysqltest: Test has succeeded!

 - saving 'H:/pb2/test/sb_2-814437-1255182695.83/mysql-6.0.14-alpha-win-x86-test/mysql-test/var-ps_row/log/rpl.rpl_extraColmaster_myisam/' to 'H:/pb2/test/sb_2-814437-1255182695.83/mysql-6.0.14-alpha-win-x86-test/mysql-test/var-ps_row/log/rpl.rpl_extraColmaster_myisam/'

Retrying test, attempt(2/3)...

How to repeat:
Failure:

http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&test_failure_id=2378174

Push:

http://pb2.norway.sun.com/web.py?template=push_details&push=573075

Suggested fix:
n/a

See also BUG#47743.

rpl_extraColmaster_innodb fails with similar symptom:

rpl.rpl_extraColmaster_innodb            [ fail ]  Found warnings/errors in server log file!
        Test ended at 2009-10-12 17:49:07
mysqltest: Logging to ''.
mysqltest: Results saved in ''.
mysqltest: Connecting to server localhost:13001 (socket /Volumes/hd2/pb2/test/sb_0-815154-1255357187.65/tmp/cBSbNx9E3A/mysqld.2.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-warnings.test' ...
file_name	line
/Volumes/hd2/pb2/test/sb_0-815154-1255357187.65/mysql-5.5.0-beta-osx10.6-i386-test/mysql-test/var/log/mysqld.2.err	091012 18:48:43 [Warning] Slave I/O: Get master clock failed with error: Lost connection to MySQL server during query, Error_code: 2013
^ Found warnings!!
mysqltest: ... Done processing test commands.
mysqltest: Test has succeeded!
ok

 - saving '/Volumes/hd2/pb2/test/sb_0-815154-1255357187.65/mysql-5.5.0-beta-osx10.6-i386-test/mysql-test/var/log/rpl.rpl_extraColmaster_innodb/' to '/Volumes/hd2/pb2/test/sb_0-815154-1255357187.65/mysql-5.5.0-beta-osx10.6-i386-test/mysql-test/var/log/rpl.rpl_extraColmaster_innodb/'

Retrying test, attempt(2/3)...

DETAILS
=======

Where 	Build 	Test 	Run 	Suite 	Case 	Mode 	When
mysql-next-mr
573410	binary-max-macosx10.6-i386-tar-gz
573506 slid01	test-max-macosx10.6-i386
577933 slid02	rpl_binlog_row	rpl	rpl_extraColmaster_innodb	None	2009-10-10 18:02:51

http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&test_failure_id=2381646

Happened in the build of 5.1.40 for both tests "rpl_extraColmaster_myisam" (68 occurrences) and "rpl_extraColmaster_innodb" (59 occurrences).
All these failures happened on Mac OS X: 10.4 and 10.5, PPC and x86, 32 and 64 bit.
Of all runs on these platforms (including retries), 510 passed and 415 failed.

Judging from the symptom, I'm not sure whether this is a server fault or a MTR fault:
The complaint is about "warnings found", and a close-to-final line reads
   mysqltest: Test has succeeded!
so why is it marked as a failing test?

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

3159 Luis Soares	2009-11-04
      BUG#47743: rpl.rpl_log_pos fails sporadically
      BUG#47983: rpl_extraColmaster_myisam failed in PB2 with "Found
      warnings!!"
      
      BUG 45214 fixed the case when get_master_version_and_clock
      function, used by the slave, would not report errors. The slave
      now detects them and if related to transient network failures, it
      prints some warnings and retries to connect. On the other hand,
      if not network related, it just gives up and fails.
      
      As such, sometimes, in PB2, the slave comes across some transient
      communication issues between master and slave, while calling
      get_master_version_and_clock, causing warnings print outs to the
      error log. Nevertheless, in such cases slave retries to connect,
      in which it succeeds, and the test case continues as it normally
      would. But then, at the end of a successful test run, MTR checks
      the error log, finds the unexpected warnings and considers them
      harmful. This causes MTR to report error and, consequently, PB2
      to report a failing test.
      
      We fix this by adding to the global warnings suppress list the
      warnings related to transient network failures only, which are
      reported while in function get_master_version_and_clock.

Queued in mysql-5.1-bugteam and mysql-pe.

Pushed into 5.1.42 (revid:joro@sun.com-20091202080033-mndu4sxwx19lz2zs) (version source revid:kristofer.pettersson@sun.com-20091109223504-xvwgsdqiyuve6frt) (merge vers: 5.1.41) (pib:13)

Changes in test code only; closed without further action.

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

Pushed into 5.5.0-beta (revid:alik@sun.com-20091216082430-s0gtzibcgkv4pqul) (version source revid:alexey.kopytov@sun.com-20091124081906-6pqi7e7sajimog71) (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)

Closed. See my previous comment.

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)

Closed. See my previous comments.