Bug #68141 querytimeout does not work for loadbalanced and failover connections
Submitted: 22 Jan 2013 13:16 Modified: 2 Mar 2022 11:15
Reporter: murat cengiz Email Updates:
Status: Can't repeat Impact on me:
None 
Category:Connector / J Severity:S2 (Serious)
Version:5.1.22 OS:Any
Assigned to: Alexander Soklakov CPU Architecture:Any

[22 Jan 2013 13:16] murat cengiz 
Description:
Setting queryTimeout() seems to have no effect when using loadbalanced or fail-over urls.

I am using a query that takes more than 5s to execute with the following code:

Connection conn = DriverManager.getConnection(url);
PreparedStatement ps = conn.prepareStatement(aLongRunningSql);
ps.setQueryTimeout(2);
ResultSet rs = ps.executeQuery();

Using:
java 1.6
connector/j 5.1.22
url : jdbc:mysql:loadbalance://host1,host2:3306/test?connectTimeout=3000&socketTimeout=5000&loadBalanceBlacklistTimeout=600000

I am expecting the query to fail after 2s with an sql exception, but it fails after 5s due to sockettimeout with an exception that causes the current host to be blacklisted.

The exception is:

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 5,102 milliseconds ago. The last packet sent successfully to the server was 5,006 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3589)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3478)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4019)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)
at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:156)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.executeSql(ConnectorJSocketTimeoutTest.java:73)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.run(ConnectorJSocketTimeoutTest.java:47)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.main(ConnectorJSocketTimeoutTest.java:97)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3036)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3489)
... 11 more
error info : sql state=08S01 error code=0 type=com.mysql.jdbc.exceptions.jdbc4.CommunicationsException cause=java.net.SocketTimeoutException: Read timed out

Looking at the thread dump (somewhere after 2s and before 5s after issuing the query):

"Thread-1" daemon prio=10 tid=0x00007f9308001000 nid=0x30eb waiting for monitor entry [0x00007f9351a73000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.mysql.jdbc.LoadBalancedMySQLConnection.getActiveMySQLConnection(LoadBalancedMySQLConnection.java:51)
- waiting to lock <0x00000007d6ee4760> (a com.mysql.jdbc.JDBC4LoadBalancedMySQLConnection)
at com.mysql.jdbc.LoadBalancedMySQLConnection.getQueryTimeoutKillsConnection(LoadBalancedMySQLConnection.java:592)
at com.mysql.jdbc.StatementImpl$CancelTask$1.run(StatementImpl.java:107)

"MySQL Statement Cancellation Timer" daemon prio=10 tid=0x00007f935c844000 nid=0x30d1 in Object.wait() [0x00007f9351b74000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007d74db358> (a java.util.TaskQueue)
at java.lang.Object.wait(Object.java:485)
at java.util.TimerThread.mainLoop(Timer.java:483)
- locked <0x00000007d74db358> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:462)

"Abandoned connection cleanup thread" daemon prio=10 tid=0x00007f935c0e5800 nid=0x30d0 in Object.wait() [0x00007f935206f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007d6b04278> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x00000007d6b04278> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at com.mysql.jdbc.NonRegisteringDriver$1.run(NonRegisteringDriver.java:93)

"main" prio=10 tid=0x00007f935c00e800 nid=0x30b5 runnable [0x00007f9362121000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <0x00000007d71979a0> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3036)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3489)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3478)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4019)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2734)
- locked <0x00000007d701c998> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.LoadBalancedMySQLConnection.execSQL(LoadBalancedMySQLConnection.java:156)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
- locked <0x00000007d6ee4760> (a com.mysql.jdbc.JDBC4LoadBalancedMySQLConnection)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322)
- locked <0x00000007d6ee4760> (a com.mysql.jdbc.JDBC4LoadBalancedMySQLConnection)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.executeSql(ConnectorJSocketTimeoutTest.java:73)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.run(ConnectorJSocketTimeoutTest.java:47)
at com.acme.util.database.connectionPooling.test.manual.ConnectorJSocketTimeoutTest.main(ConnectorJSocketTimeoutTest.java:97)

The querytimeout thread ("Thread-1") has actually started, but was waiting to lock <0x00000007d6ee4760>, which is already locked by "main" thread issuing the query. But at the time it acquires the lock, it probably is too late.

I have also tried with a fail-over url and got similar results. 

How to repeat:
Connection conn = DriverManager.getConnection(url);
PreparedStatement ps = conn.prepareStatement(aLongRunningSql);
ps.setQueryTimeout(2);
ResultSet rs = ps.executeQuery();

Observe that query fails after 5s, which equals socketTimeout.

Suggested fix:
query timed out successfully with the following changes to CancelTask of StatementImpl; not sure if the changes are correct.

	class CancelTask extends TimerTask {

		long connectionId = 0;
		String origHost = "";
		SQLException caughtWhileCancelling = null;
		StatementImpl toCancel;
		Properties origConnProps = null; 
		String origConnURL = "";
		boolean queryTimeoutKillsConnection = false;
		
		CancelTask(StatementImpl cancellee) throws SQLException {
			connectionId = cancellee.connectionId;
			origHost = connection.getHost();
			toCancel = cancellee;
			origConnProps = new Properties();
			
			Properties props = connection.getProperties();
			
			Enumeration<?> keys = props.propertyNames();
			
			while (keys.hasMoreElements()) {
				String key = keys.nextElement().toString();
				origConnProps.setProperty(key, props.getProperty(key));
			}
			
			origConnURL = connection.getURL();
			
			queryTimeoutKillsConnection = connection.getQueryTimeoutKillsConnection();
		}

		public void run() {

			Thread cancelThread = new Thread() {

				public void run() {
					if (queryTimeoutKillsConnection) {
						try {
							toCancel.wasCancelled = true;
							toCancel.wasCancelledByTimeout = true;
							connection.realClose(false, false, true, 
									new MySQLStatementCancelledException(Messages.getString("Statement.ConnectionKilledDueToTimeout")));
						} catch (NullPointerException npe) {
							// not worth guarding against
						} catch (SQLException sqlEx) {
							caughtWhileCancelling = sqlEx;
						}
					} else {
						Connection cancelConn = null;
						java.sql.Statement cancelStmt = null;
	
						try {
							synchronized (cancelTimeoutMutex) {
								// TODO not sure about connection.duplicate() method..
								try {
									cancelConn = (Connection) DriverManager.getConnection(origConnURL, origConnProps);
									cancelStmt = cancelConn.createStatement();
									cancelStmt.execute("KILL QUERY " + connectionId);
								} catch (NullPointerException npe){
									//Log this? "Failed to connect to " + origConnURL + " and KILL query"
								}
								toCancel.wasCancelled = true;
								toCancel.wasCancelledByTimeout = true;
							}
						} catch (SQLException sqlEx) {
							caughtWhileCancelling = sqlEx;
						} catch (NullPointerException npe) {
							// Case when connection closed while starting to cancel
							// We can't easily synchronize this, because then one thread
							// can't cancel() a running query
	
							// ignore, we shouldn't re-throw this, because the connection's
							// already closed, so the statement has been timed out.
						} finally {
							if (cancelStmt != null) {
								try {
									cancelStmt.close();
								} catch (SQLException sqlEx) {
									throw new RuntimeException(sqlEx.toString());
								}
							}
	
							if (cancelConn != null) {
								try {
									cancelConn.close();
								} catch (SQLException sqlEx) {
									throw new RuntimeException(sqlEx.toString());
								}
							}
							
							toCancel = null;
							origConnProps = null;
							origConnURL = null;
						}
					}
				}
			};

			cancelThread.start();
		}
	}
[24 Jan 2013 19:22] Sveta Smirnova 
Thank you for the report.

Verified as described.

Test case for our test suite:

import testsuite.BaseTestCase;
import java.sql.PreparedStatement;
import java.sql.SQLException;

public class bug68141 extends BaseTestCase {
	
	public bug68141(String name) {
		super(name);
	}

	public static void main(String[] args) {
		junit.textui.TestRunner.run(bug68141.class);
	}

	public void testBug68141() throws Exception {
		try {
			PreparedStatement ps = this.conn.prepareStatement("select sleep(10)");
			ps.setQueryTimeout(2);
			ps.executeQuery();
		} finally {
	    	//closeMemberJDBCResources();
		}
	}
	
}

Run it with -Dcom.mysql.jdbc.testsuite.url="jdbc:mysql:loadbalance://127.0.0.1,127.0.0.1:13000/test?user=root&password=&
[18 Feb 2020 12:54] Filipe Silva 
I'm not observing any issues.

Are you sure the queries aren't being actually canceled due to timeout?
[2 Mar 2022 11:15] Alexander Soklakov 
Posted by developer:
 
This bug is not reproducible with the latest Connector/J 8.0.

Connector/J 5.1 series came to EOL on Feb 9th, 2021, see https://www.mysql.com/support/eol-notice.html, so this bug will not be fixed there.