MySQL Bugs: #43761: Connector/NET sometimes hangs instead of obeying command timeout

Bug #43761	Connector/NET sometimes hangs instead of obeying command timeout
Submitted:	19 Mar 2009 21:04	Modified:	9 Sep 2009 9:44
Reporter:	d di (Basic Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Connector / NET	Severity:	S1 (Critical)
Version:	5.2.5.0	OS:	Any
Assigned to:	Vladislav Vaintroub	CPU Architecture:	Any
Tags:	qc

Description:
An important service recently hung for several hours.  A stack trace produced this output:

ESP       EIP     
00e0f0dc 7c90e4f4 [NDirectMethodFrameStandalone: 00e0f0dc] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
00e0f0f4 7a5ff523 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef)
00e0f120 7a5ff401 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags)
00e0f13c 7a5d3798 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32)
00e0f16c 7948eb24 System.IO.BufferedStream.ReadByte()
00e0f174 00a5a37b MySql.Data.MySqlClient.MySqlStream.LoadPacket()
00e0f1a0 00a5a21e MySql.Data.MySqlClient.MySqlStream.OpenPacket()
00e0f1b4 00a5e2b0 MySql.Data.MySqlClient.NativeDriver.ReadResult(UInt64 ByRef, Int64 ByRef)
00e0f1cc 00a5e1e1 MySql.Data.MySqlClient.MySqlDataReader.GetResultSet()
00e0f1e0 00a5df07 MySql.Data.MySqlClient.MySqlDataReader.NextResult()
00e0f21c 00a5cb15 MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(System.Data.CommandBehavior)
00e0f28c 03ff42b5 MySql.Data.MySqlClient.MySqlCommand.ExecuteDbDataReader(System.Data.CommandBehavior)
00e0f290 6525d478 System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader(System.Data.CommandBehavior)
00e0f294 6526649e System.Data.Common.DbDataAdapter.FillInternal(System.Data.DataSet, System.Data.DataTable[], Int32, Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
00e0f2ec 65265fa6 System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet, Int32, Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
00e0f330 65265d8b System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet)

The command timeout that Connector/NET guarantees to the user application is set to 30 seconds, so it is a problem that it hangs for several hours in MySqlStream.LoadPacket() (above).

How to repeat:
There's not enough data to verify if this is really what happened, but here is a test case that demonstrates a likely candidate bug (attached).  Test scenario:

1. Replace the <server>, <user> and <pass> tokens with actual values.
2. Run the test case.
3. Within 60 seconds, null route traffic to/from the server used, to simulate that the connection has been dropped by a firewall.
4. Wait...

The command should time out and control return to the application.  It never does.

Suggested fix:
Switch to non-blocking socket calls in Connector/NET.

test case

Attachment: issue43761.cs (application/octet-stream, text), 723 bytes.

Hi and thanks for your report.

16:16:43  Executing query.
[20.3.2009 17:16:43] - Executing command QUERY with text ='SHOW VARIABLES'
[20.3.2009 17:16:43] - Executing command QUERY with text ='SHOW COLLATION'
[20.3.2009 17:16:43] - Executing command QUERY with text ='SET character_set_results=NULL'
[20.3.2009 17:16:43] - Executing command QUERY with text ='SELECT SLEEP(600)'
16:16:45  Execution finished, no errors reported.

against latest sources in SVN repository... The only difference in code is "logging=True" in my connection string.

Can you try building driver from SVN sources (/branch) and inform me if it helps?

2 seconds after running SELECT I restarted MySQL 5.1.31 x64 server on remote OpenSolaris box but the execution didn't block.

Sorry, as soon as I hit "submit" I saw my error....

Verified as described by disabling the network adapter:
16:24:06  Executing query.
[20.3.2009 17:24:06] - Executing command QUERY with text ='SHOW VARIABLES'
[20.3.2009 17:24:06] - Executing command QUERY with text ='SHOW COLLATION'
[20.3.2009 17:24:06] - Executing command QUERY with text ='SET character_set_results=NULL'
[20.3.2009 17:24:06] - Executing command QUERY with text ='SELECT SLEEP(600)'
A first chance exception of type 'System.Net.Sockets.SocketException' occurred in System.dll
A first chance exception of type 'MySql.Data.MySqlClient.MySqlException' occurred in MySql.Data.dll
A first chance exception of type 'MySql.Data.MySqlClient.MySqlException' occurred in MySql.Data.dll
[20.3.2009 17:25:09] - EXCEPTION: Unable to connect to any of the specified MySQL hosts.

To be checked together with Bug#43760. Simply uncomment remarked lines:
    Console.Out.WriteLine(DateTime.UtcNow.ToLongTimeString() + "  " + "Executing query.");
    cmd.ExecuteNonQuery();
    //cmd.CommandText = "SELECT SLEEP(60);";
    //cmd.ExecuteNonQuery();
    Console.Out.WriteLine(DateTime.UtcNow.ToLongTimeString() + "  " + "Execution finished, no errors reported.");

As can be seen in log provided in Bug#43760, c/NET does obey command timeout but then "killing" connection exits leaving code blocked...

090320 17:43:59    2 Connect	root@QCW2K8.lan on test
	    2 Query	SHOW VARIABLES
	    2 Query	SHOW COLLATION
	    2 Query	SET character_set_results=NULL
	    2 Init DB	test
	    2 Query	SELECT SLEEP(60); DROP TABLE IF EXISTS testbug43760
090320 17:44:09    3 Connect	root@QCW2K8.lan on test
	    3 Query	SHOW VARIABLES
	    3 Query	SHOW COLLATION
	    3 Query	SET character_set_results=NULL
	    3 Init DB	test
	    3 Query	KILL QUERY 2
	    3 Quit

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

757 Vladislav Vaintroub	2009-08-31
      - fixed hanging situation where network connectivity to server is lost 
        (bug#43761) 
        A better fix is planned for 6.2

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

759 Vladislav Vaintroub	2009-08-31 [merge]
      null merge of bug#43761

pushed to 6.1, null merged into trunk (6.2 will have a better solution for timeouts)

An entry was added to the 6.1.2 changelog:

MySQL Connector/NET did not time out correctly. The command timeout was set to 30 secs, but MySQL Connector/NET hung for several hours.