Bug #54086 Server crashing when connector/J testsuite run against it
Submitted: 29 May 2010 18:46 Modified: 23 Sep 2010 8:41
Reporter: Erica Moss Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: General Severity:S1 (Critical)
Version:mysql-5.5.3-m3-winx64 OS:Windows (server 2003 x64)
Assigned to: Alexander Soklakov CPU Architecture:Any
Tags: connector/J crash

[29 May 2010 18:46] Erica Moss
Description:
The Connector/J test testsuite\regression\StatementRegressionTest.java

is hanging when run against this server version due to the server crashing.  Earlier releases of connector J have been tried and had the same issues, and the test has been tried against other server versions and has run without issue.  There appear to be roughly 200 individual test cases in this suite and there isn't a way to run them individually, so I'm not clear which case is causing the crash.

Below is a thread dump from the JVM and attached is the query log from the server.  The issue happens every time and the results and logs are the same.

The server is running as a windows service and after the test hangs waiting for response the status of the service is "stopped".

test:
    [mkdir] Created dir: C:\CONNECTOR_TESTS\connector-java\5.1\branch_5_1\build\junit
     [echo] Running unit tests against jdbc:mysql://localhost/test?user=root&password=mypass with jvm java
    [mkdir] Created dir: C:\CONNECTOR_TESTS\connector-java\5.1\branch_5_1\build\junit\unitregress
    [mkdir] Created dir: C:\CONNECTOR_TESTS\connector-java\5.1\branch_5_1\build\junit\unitregress\report
    [junit] Running testsuite.regression.StatementRegressionTest
Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_15-b04 mixed mode):

"Thread-11" daemon prio=6 tid=0x000000000044cac0 nid=0x6f8 runnable [0x0000000007a9f000..0x0000000007a9fb60]
        at java.io.FileInputStream.readBytes(Native Method)
        at java.io.FileInputStream.read(FileInputStream.java:177)
        at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:92)
        at java.lang.Thread.run(Thread.java:595)

"Thread-10" daemon prio=6 tid=0x000000000044cd70 nid=0x5e0 runnable [0x000000000799f000..0x000000000799f7e0]
        at java.io.FileInputStream.readBytes(Native Method)
        at java.io.FileInputStream.read(FileInputStream.java:194)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
        - locked <0x0000000010133278> (a java.io.BufferedInputStream)
        at java.io.FilterInputStream.read(FilterInputStream.java:90)
        at org.apache.tools.ant.taskdefs.StreamPumper.run(StreamPumper.java:92)
        at java.lang.Thread.run(Thread.java:595)

"RMI TCP Accept-0" daemon prio=6 tid=0x000000000044b290 nid=0x670 runnable [0x0000000005b7f000..0x0000000005b7fae0]

        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
        - locked <0x0000000011c58288> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:450)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
        at java.lang.Thread.run(Thread.java:595)

"Timer-0" daemon prio=6 tid=0x000000000044afe0 nid=0x210 in Object.wait() [0x0000000005a7f000..0x0000000005a7fb60]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000011c58520> (a java.util.TaskQueue)
        at java.lang.Object.wait(Object.java:474)
        at java.util.TimerThread.mainLoop(Timer.java:483)
        - locked <0x0000000011c58520> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=6 tid=0x000000000044ad30 nid=0x7ec runnable [0x0000000000000000..0x00000000000000
00]

"CompilerThread1" daemon prio=10 tid=0x0000000004f55f00 nid=0x7a0 waiting on condition [0x0000000000000000..0x00000
000057ae9b0]

"CompilerThread0" daemon prio=10 tid=0x0000000004f55c30 nid=0xa14 waiting on condition [0x0000000000000000..0x00000
000056aea70]

"AdapterThread" daemon prio=10 tid=0x0000000004f55960 nid=0xb24 waiting on condition [0x0000000000000000..0x0000000
000000000]

"Signal Dispatcher" daemon prio=10 tid=0x000000000044aa80 nid=0x6e8 waiting on condition [0x0000000000000000..0x000
0000000000000]

"Finalizer" daemon prio=8 tid=0x000000000044a7d0 nid=0x75c in Object.wait() [0x00000000053af000..0x00000000053af9e0
]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000011c588a0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
        - locked <0x0000000011c588a0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x000000000044a520 nid=0x6a8 in Object.wait() [0x00000000052af000..0x0000000
0052afae0]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000011c58970> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x0000000011c58970> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x000000000044a270 nid=0xba0 runnable [0x000000000012e000..0x000000000012fa00]
        at java.lang.ProcessImpl.waitFor(Native Method)
        at org.apache.tools.ant.taskdefs.Execute.waitFor(Execute.java:549)
        at org.apache.tools.ant.taskdefs.Execute.execute(Execute.java:480)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.executeAsForked(JUnitTask.java:1021)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(JUnitTask.java:817)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTask.execute(JUnitTask.java:780)
        at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:288)
        at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:105)
        at org.apache.tools.ant.Task.perform(Task.java:348)
        at org.apache.tools.ant.Target.execute(Target.java:357)
        at org.apache.tools.ant.Target.performTasks(Target.java:385)
        at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1329)
        at org.apache.tools.ant.Project.executeTarget(Project.java:1298)
        at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41)
        at org.apache.tools.ant.Project.executeTargets(Project.java:1181)
        at org.apache.tools.ant.Main.runBuild(Main.java:698)
        at org.apache.tools.ant.Main.startAnt(Main.java:199)
        at org.apache.tools.ant.launch.Launcher.run(Launcher.java:257)
        at org.apache.tools.ant.launch.Launcher.main(Launcher.java:104)

"VM Thread" prio=10 tid=0x00000000004514f0 nid=0x128 runnable

"VM Periodic Task Thread" prio=10 tid=0x0000000000451610 nid=0x8fc waiting on condition

How to repeat:
to run the java tests install jdk 1.5 and 1.6
install apache ant
set the value of env var ANT_HOME to the ant dir
set the value of env var JAVA_HOME to jdk 1.5

Start the individual failing suite in a manner similar to this passing in the correct paths

ant "-Dcom.mysql.jdbc.testsuite.url=jdbc:mysql://localhost/test?us
er=root&password=mypass" "-Dcom.mysql.jdbc.java6.java=C:/Program Files/Java/jdk1.6.0_10/bin/java.exe" "-Dcom.mysql.
jdbc.java6.javac=C:/Program Files/Java/jdk1.6.0_10/bin/javac.exe" "-Dcom.mysql.jdbc.java6.rtjar=C:/Program Files/Ja
va/jdk1.6.0_10/jre/lib/rt.jar" -Dtest=testsuite.regression.StatementRegressionTest test

If necessary the connectors/server test platform which is already set up to run it may be used for debugging.
[29 May 2010 18:50] Erica Moss
query log leading to crash

Attachment: query log (application/octet-stream, text), 349.32 KiB.

[30 May 2010 10:44] MySQL Verification Team
Hi Eric! Please upload the mysql server error log so we might see crash related info. does drop table crash?
[31 May 2010 5:47] Tonci Grgin
Eric, please do run StatementRegressionTest from Eclipse where you can choose test by test.
[3 Jun 2010 5:06] MySQL Verification Team
i doubt this bug is verified sufficiently...
[18 Jun 2010 8:42] Tonci Grgin
Eric, I suggest you to try outside VM (real box) as I can not repeat the crash... My guess would be that something in VM timed out. Now, we are all aware what all can go wrong here but still.

Log from the test that fails for you:
100618 10:39:11	    5 Connect	root@localhost on test
		    5 Query	/* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name = 'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name = 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name = 'character_set_connection' OR Variable_name = 'character_set' OR Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR Variable_name = 'transaction_isolation' OR Variable_name = 'character_set_results' OR Variable_name = 'timezone' OR Variable_name = 'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name = 'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR Variable_name = 'init_connect'
		    5 Query	/* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SELECT @@session.auto_increment_increment
		    5 Query	SHOW COLLATION
		    5 Query	SET character_set_results = NULL
		    5 Query	SET autocommit=1
		    5 Query	SET sql_mode='STRICT_TRANS_TABLES'
		    5 Query	SELECT VERSION()
		    5 Query	DROP TABLE IF EXISTS t1
		    5 Query	CREATE  TABLE t1 (id INTEGER, x INTEGER) ENGINE = INNODB
		    5 Query	DROP TABLE IF EXISTS t2
		    5 Query	CREATE  TABLE t2 (id INTEGER, x INTEGER) ENGINE = INNODB
		    5 Query	INSERT INTO t1 VALUES (0, 0)
		    5 Query	SET autocommit=0
		    5 Query	SELECT * FROM t1 WHERE id=0 FOR UPDATE
		    6 Connect	root@localhost on test
		    6 Query	/* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name = 'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name = 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name = 'character_set_connection' OR Variable_name = 'character_set' OR Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR Variable_name = 'transaction_isolation' OR Variable_name = 'character_set_results' OR Variable_name = 'timezone' OR Variable_name = 'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name = 'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR Variable_name = 'init_connect'
		    6 Query	/* mysql-connector-java-5.1.13 ( Revision: mark.matthews@oracle.com-20100615210030-3r8bsc9bv0efe6gv ) */SELECT @@session.auto_increment_increment
		    6 Query	SHOW COLLATION
		    6 Query	SET character_set_results = NULL
		    6 Query	SET autocommit=1
		    6 Query	SET sql_mode='STRICT_TRANS_TABLES'
		    6 Query	SET autocommit=0
		    6 Query	INSERT INTO t2 VALUES (1, 0)
		    6 Query	SELECT * FROM t2 WHERE id=0 FOR UPDATE
		    6 Query	INSERT INTO t2 VALUES (1, 0)
		    6 Query	INSERT INTO t2 VALUES (2, 0)
		    6 Query	UPDATE t1 SET x=2 WHERE id=0
100618 10:39:42	    5 Query	INSERT INTO t1 VALUES (0, 0)
		    5 Query	SET autocommit=1
		    6 Quit	
		    5 Query	DROP TABLE IF EXISTS t1
		    5 Query	DROP TABLE IF EXISTS t2
		    5 Quit
[18 Jun 2010 8:43] Tonci Grgin
Error log (I did the shutdown after successful test):
100618 10:33:48 [Note] Buffered information: Performance schema disabled (reason: start parameters).

100618 10:33:48 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use Windows interlocked functions
100618 10:33:49  InnoDB: highest supported file format is Barracuda.
100618 10:33:49 InnoDB Plugin 1.0.6 started; log sequence number 44278
100618 10:33:49 [Note] Event Scheduler: Loaded 0 events
100618 10:33:49 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: ready for connections.
Version: '5.5.3-m3-community-log'  socket: ''  port: 5530  MySQL Community Server (GPL)
100618 10:40:08 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: Normal shutdown

100618 10:40:08 [Note] Event Scheduler: Purging the queue. 0 events
100618 10:40:08  InnoDB: Starting shutdown...
100618 10:40:09  InnoDB: Shutdown completed; log sequence number 50780
100618 10:40:09 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: Shutdown complete
[18 Jun 2010 8:56] Tonci Grgin
And finally, the test itself, testDeadlockBatchBehavior() completes correctly, ie. exception is thrown where expected, junit run completes:

the part that breaks intentionally:
	new Thread() {
		public void run() {
			try {
			deadlockStmt.addBatch("INSERT INTO t2 VALUES (1, 0)");
			deadlockStmt.addBatch("INSERT INTO t2 VALUES (2, 0)");
			deadlockStmt.addBatch("UPDATE t1 SET x=2 WHERE id=0");
			deadlockStmt.executeBatch();
			} catch (SQLException sqlEx) {
					sqlEx.printStackTrace();
			}
		}
		}.run();

The part right after that executes (as can be seen in log):
		this.stmt.executeUpdate("INSERT INTO t1 VALUES (0, 0)");
[18 Jun 2010 14:18] Mark Matthews
There's definitely something strange going on here. On my machine (Mac OS/X SL), the current 5.5 release hangs indefinitely on this test.
[18 Jun 2010 14:24] Tonci Grgin
Whatever it is it's not repeatable on *proper* box :-) Joke aside, Eric, please attach server error log if not complete crash dump... Without that we can not proceed.
[18 Jun 2010 16:22] MySQL Verification Team
I tried 5.5.3 x64 + c/j 5.1.3 rev 945 on windows as Eric suggested.  But the testsuite gets to a point then appears to hang, and the reason is this:

| Sleep   |  747 |                   | NULL                    |
| Sleep   |  745 |                   | NULL                    |
| Sleep   |  745 |                   | NULL                    |
| Sleep   |  743 |                   | NULL                    |
| Sleep   |  739 |                   | NULL                    |
| Query   |  688 | Waiting for table | DROP TABLE IF EXISTS t1 |
| Sleep   |  688 |                   | NULL                    |

Some other transaction holds locks on the table t1, so we observe expected waiting:

---TRANSACTION 4173, not started, OS thread id 1804
MySQL thread id 137, query id 3444 127.0.0.1 root Waiting for table
DROP TABLE IF EXISTS t1
---TRANSACTION 4174, ACTIVE 829 sec, OS thread id 2576
5 lock struct(s), heap size 1216, 5 row lock(s), undo log entries 3
MySQL thread id 138, query id 3441 127.0.0.1 root

This looks like a bug in the tests. There's no evidence of server crash here.
If manually ran "kill 138" the testsuite continues.
[18 Jun 2010 17:44] Mark Matthews
Shane,

I see the issue now, at least with the testsuite (and have fixed the semantics so that the test will at least pass). However, I've also seen that the testsuite will stay lodged in this state essentially forever, and even when terminating the application, the two deadlocked connections will remain this way, essentially forever until human intervention, well...intervenes and KILLs one or the other.

Does the MDL code do no deadlock detection, or timeout? Or is it supposed to, and it's just broken?
[18 Jun 2010 18:11] MySQL Verification Team
Works after specifying "lock-wait-timeout=55" in my.ini the testsuite finished but failed testBug39956 "The used table type doesn't support AUTO_INCREMENT...."  

http://dev.mysql.com/doc/refman/5.5/en/server-system-variables.html#sysvar_lock_wait_timeo...

Maybe the testsuite should set this variable dynamically on >=5.5.3 and deal with the error??
[28 Jun 2010 13:41] Tonci Grgin
Guys, could it be engine-related? I see no reference to engine used. I did test on MyISAM, all went fine.
[18 Jul 2010 23:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[23 Aug 2010 8:41] Tonci Grgin
Eric?
[23 Sep 2010 23:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".