Exception on closing a pooled connection
Brought to you by:
ickzon
Menu
▾
▴
#564 Exception on closing a pooled connection
Problem: I'm receiving the following exception in my tomcat web application:
"java.sql.SQLException: I/O Error: Stream 1 attempting to read when no request has been sent"
Note: See full stack trace at end of bug report.
Summary: I'm using c3p0 for connection pooling configured via hibernate/c3p0.properties. The included stack trace shows no activity from server start to the exception thrown (this was on a test machine). I'm also seeing the exception in environments that see minimal, single-user load, though not at the time the exception occurs. The root exception seems to be thrown by jtds code: net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:707).
I receive this exception every few days, typically when the app has zero activity. I'm guessing it's caused by the ordinary maintenance performed by c3p0's connection pool, making sure existing connections are fresh.
In an effort to provide a more useful bug report and perhaps see what the issue was, I added some custom logging code so I could send along the data that was present when the error occurred.
I changed ResponseStream getPacket to log the current data it was processing if there was an exception and the rethrow it:
try {
buffer = socket.getNetPacket(streamId, buffer);
} catch (IOException t) {
log.info("jtds-error getPacket(): Error during read. bufferPtr: " + bufferPtr + ", bufferLen: " + bufferLen);
log.info("jtds-error getPacket(): Contents of buffer: " + new String(buffer));
Logger.logPacket(streamId, true, buffer);
throw t;
}
The output looks like this:
Begin Error Output
2008-05-17 12:54:51,263 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.jdbc.ResponseStream] (ResponseStream.java:483) - jtds-error getPacket(): Error during read. bufferPtr: 26, bufferLen: 35
2008-05-17 12:54:51,264 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.jdbc.ResponseStream] (ResponseStream.java:484) - jtds-error getPacket(): Contents of buffer: # 5 � � � 4a � � � � � �
2008-05-17 12:54:51,265 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.util.Logger] (Logger.java:85) - jtds-error: ----- Stream #1 read last Reply packet
2008-05-17 12:54:51,266 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.util.Logger] (Logger.java:85) - jtds-error:
2008-05-17 12:54:51,266 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.util.Logger] (Logger.java:85) - jtds-error: 0: 04 01 00 23 00 35 01 00 81 01 00 00 00 09 00 AF | # 5 |
2008-05-17 12:54:51,267 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.util.Logger] (Logger.java:85) - jtds-error: 16: 01 00 09 04 D0 00 34 01 61 00 FD 10 00 C1 00 00 | 4 a |
2008-05-17 12:54:51,268 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.util.Logger] (Logger.java:85) - jtds-error: 32: 00 00 00 | |
2008-05-17 12:54:51,268 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [net.sourceforge.jtds.util.Logger] (Logger.java:85) - jtds-error:
End Error Output
Platform: Linux, several variants of the 2.6.x kernel
JTDS: 1.2.2
c3p0: c3p0-0.9.1.2.jar
hibernate: version 3.2.4.sp1, May 18, 2007
RDBMS: Microsoft SQL Server 2005, version: 09.00.3054
In the event that this is potentially a pool configuration issue, I'm including some of the relevant configuration options:
Begin hibernate.properties
hibernate.bytecode.use_reflection_optimizer=true
hibernate.connection.driver_class=com.p6spy.engine.spy.P6SpyDriver
hibernate.connection.driver_class=net.sourceforge.jtds.jdbc.Driver
hibernate.connection.url=jdbc:jtds:sqlserver://@database.server@:@database.port@/@database.name@
hibernate.connection.username=@database.user@
hibernate.connection.password=@database.password@
hibernate.c3p0.min_size=2
hibernate.c3p0.max_size=10
time out connections that haven't been used in 9 minutes. sql server times out connections that are 10 minutes old.
hibernate.c3p0.timeout=540
hibernate.c3p0.max_statements=50
hibernate.dialect = org.hibernate.dialect.SQLServerDialect
End hibernate.properties
Begin c3p0.properties
c3p0.automaticTestTable=MATCH_CONNECTION_TEST
test idle connections every eight minutes. connections are timed out every 9 minutes, but this should prevent that.
c3p0.idleConnectionTestPeriod=480
c3p0.testConnectionOnCheckin=true
c3p0.testConnectionOnCheckout=true
End c3p0.properties
Begin stack trace
2008-01-24 17:12:37,868 INFO [main] [org.apache.catalina.startup.Catalina] (Catalina.java:560) - Server startup in 33808 ms
2008-01-26 22:08:03,490 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [com.mchange.v2.c3p0.impl.NewPooledConnection] (NewPooledConnection.java:725) - [c3p0] Exceptions occurred while trying to close a PooledConnection's resources normally.
2008-01-26 22:08:03,585 INFO [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [com.mchange.v2.c3p0.impl.NewPooledConnection] (NewPooledConnection.java:735) - [c3p0] NewPooledConnection close Exception.
java.sql.SQLException: I/O Error: Stream 1 attempting to read when no request has been sent
at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2307)
at net.sourceforge.jtds.jdbc.TdsCore.clearResponseQueue(TdsCore.java:728)
at net.sourceforge.jtds.jdbc.ConnectionJDBC2.releaseTds(ConnectionJDBC2.java:1903)
at net.sourceforge.jtds.jdbc.JtdsStatement.close(JtdsStatement.java:853)
at com.mchange.v2.c3p0.impl.NewPooledConnection.cleanupUncachedStatements(NewPooledConnection.java:651)
at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:539)
at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:234)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:470)
at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:964)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
Caused by: java.io.IOException: Stream 1 attempting to read when no request has been sent
at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:707)
at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2202)
... 9 more
2008-01-26 22:08:03,689 WARN [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] [com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask] (BasicResourcePool.java:972) - Failed to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@1
afdbbb
java.sql.SQLException: Some resources failed to close properly while closing com.mchange.v2.c3p0.impl.NewPooledConnection@1afdbbb
at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:571)
at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:234)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:470)
at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:964)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
2008-01-26 22:08:03,799 WARN [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1] [com.mchange.v1.db.sql.ResultSetUtils] (ResultSetUtils.java:48) - ResultSet close FAILED.
java.sql.SQLException: Invalid state, the Statement object is closed.
at net.sourceforge.jtds.jdbc.JtdsStatement.checkOpen(JtdsStatement.java:220)
at net.sourceforge.jtds.jdbc.JtdsStatement.getConnection(JtdsStatement.java:1204)
at net.sourceforge.jtds.jdbc.JtdsResultSet.getConnection(JtdsResultSet.java:421)
at net.sourceforge.jtds.jdbc.JtdsResultSet.close(JtdsResultSet.java:482)
at com.mchange.v2.c3p0.impl.NewProxyResultSet.close(NewProxyResultSet.java:2999)
at com.mchange.v1.db.sql.ResultSetUtils.attemptClose(ResultSetUtils.java:41)
at com.mchange.v2.c3p0.impl.DefaultConnectionTester.activeCheckConnection(DefaultConnectionTester.java:111)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.testPooledConnection(C3P0PooledConnectionPool.java:374)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishIdleResource(C3P0PooledConnectionPool.java:310)
at com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask.run(BasicResourcePool.java:1999)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)
End stack trace
This is a duplicate of bug [2008550].