Commons Dbcp
  1. Commons Dbcp
  2. DBCP-244

Connection socket hangs sporadically in DBCP 1.2.2 but not 1.2.1

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: 1.2.2
    • Fix Version/s: 1.3
    • Labels:
      None
    • Environment:

      Fedora Core 3, MySQL 4.1.22. with the latest driver (5.07). Exceptions only occur in the "job processing" JVM, which sits idle for long periods of time and occasionally wakes up to interact with the database.

      Description

      I think I've traced an exception to DBCP's code.

      Communication with the database is hanging sporadically in a production environment. If I don't set the socketTimeout property on the underlying connection, it will hang forever. With the socketTimeout property, I get the following exception:

      -------
      com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:

        • BEGIN NESTED EXCEPTION **

      java.net.SocketTimeoutException
      MESSAGE: Read timed out

      STACKTRACE:

      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:113)
      at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
      at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
      at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1994)
      at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2411)
      at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916)
      at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
      at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
      at com.mysql.jdbc.Connection.execSQL(Connection.java:3250)
      at com.mysql.jdbc.Statement.executeUpdate(Statement.java:1355)
      at com.mysql.jdbc.Statement.executeUpdate(Statement.java:1270)
      at org.apache.commons.dbcp.DelegatingStatement.executeUpdate(DelegatingStatement.java:228)
      ...
      -------

      It always happens in an infrequently used JVM (not an app server handling frequent connections). So it's likely the offending connection was asleep for a long time before the exception occurs.

      I've confirmed that this issue only occurs using 1.2.2 and not 1.2.1. I've been looking through the changelogs but can't find anything that would cause this behavior.

      Does somebody familiar with the codebase have any idea what change (1.2.1->1.2.2) could be causing this behavior?

      Thanks

        Issue Links

          Activity

          Hide
          Phil Steitz added a comment - - edited

          Can you share the dbcp configuration that you are using? Also, are you using DBCP 1.2.2 + Pool 1.3 and DBCP 1.2.1 + pool 1.2?

          Show
          Phil Steitz added a comment - - edited Can you share the dbcp configuration that you are using? Also, are you using DBCP 1.2.2 + Pool 1.3 and DBCP 1.2.1 + pool 1.2?
          Hide
          ori added a comment -

          Thanks for the quick reply.

          The problem occurs when using DBCP 1.2.2 + Pool 1.3.

          It does not occur with DBCP 1.2.1 + Pool 1.2. It also does not occur with DBCP 1.2.1 + Pool 1.3.

          I have not tested DBCP 1.2.2. + Pool 1.2, but the above configurations indicate the issue is with DBCP 1.2.2 only.

          Here is the configuation:

          defaultAutoCommit=true
          driverClassName=com.mysql.Driver
          maxActive=300
          maxIdle=30
          minIdle=5
          initialSize=5
          maxWait=15000
          removeAbandoned=false
          logAbandoned=false
          connectionProperties=autoReconnect=true;jdbcCompliantTruncation=false;socketTimeout=360000

          Show
          ori added a comment - Thanks for the quick reply. The problem occurs when using DBCP 1.2.2 + Pool 1.3. It does not occur with DBCP 1.2.1 + Pool 1.2. It also does not occur with DBCP 1.2.1 + Pool 1.3. I have not tested DBCP 1.2.2. + Pool 1.2, but the above configurations indicate the issue is with DBCP 1.2.2 only. Here is the configuation: defaultAutoCommit=true driverClassName=com.mysql.Driver maxActive=300 maxIdle=30 minIdle=5 initialSize=5 maxWait=15000 removeAbandoned=false logAbandoned=false connectionProperties=autoReconnect=true;jdbcCompliantTruncation=false;socketTimeout=360000
          Hide
          Phil Steitz added a comment -

          Since config for these is not listed and both are turned off by default, I assume you are not using the idle object evictor or pooling prepared statements. Can you post the code that a) creates the connection b) creates the statement c) executes the update? Can you see anything in the database logs that indicates deadlock / lock contention?

          Show
          Phil Steitz added a comment - Since config for these is not listed and both are turned off by default, I assume you are not using the idle object evictor or pooling prepared statements. Can you post the code that a) creates the connection b) creates the statement c) executes the update? Can you see anything in the database logs that indicates deadlock / lock contention?
          Hide
          ori added a comment - - edited

          Correct--those are the only configuration parameters I specify.

          There is no indication of a lock. Furthermore, there's no indication that the query/update was ever executed. It never shows up in MySQL's "SHOW PROCESSLIST" command.

          This issue can appear on any query/statement without any pattern (MyISAM or InnoDB tables, INSERT or SELECT).

          I use standard JDBC programming practices when accessing statements/connections.

          The DataSource is created once per application like this:

          dataSource = org.apache.commons.dbcp.BasicDataSourceFactory.createDataSource( commonsDbProps );

          Connections are obtained like this:

          dataSource.getConnection();

          All JDBC calls are executed in a try/finally block that closes result sets, statments, and connections immediately after they're used in the finally block (in that order).

          I'm confident that I'm not misusing any APIs.

          The fact that I can eliminate this issue by switching to another version of DBCP would indicate my application code and database setup are not the problem (but I could be wrong).

          I think the most important clue we have is that I'm using the exact same setup on my Tomcat server with DBCP 1.2.2 and have never experienced this issue. That server is under heavy load all the time so Connections never sit idle (up to 2.5M dynamic pageviews per day).

          The JVM having the issues is running Quartz, a scheduling library (like cron jobs but in Java) so it can sit idle for a few hours, then wake up and access the database, then sleep again.

          Show
          ori added a comment - - edited Correct--those are the only configuration parameters I specify. There is no indication of a lock. Furthermore, there's no indication that the query/update was ever executed. It never shows up in MySQL's "SHOW PROCESSLIST" command. This issue can appear on any query/statement without any pattern (MyISAM or InnoDB tables, INSERT or SELECT). I use standard JDBC programming practices when accessing statements/connections. The DataSource is created once per application like this: dataSource = org.apache.commons.dbcp.BasicDataSourceFactory.createDataSource( commonsDbProps ); Connections are obtained like this: dataSource.getConnection(); All JDBC calls are executed in a try/finally block that closes result sets, statments, and connections immediately after they're used in the finally block (in that order). I'm confident that I'm not misusing any APIs. The fact that I can eliminate this issue by switching to another version of DBCP would indicate my application code and database setup are not the problem (but I could be wrong). I think the most important clue we have is that I'm using the exact same setup on my Tomcat server with DBCP 1.2.2 and have never experienced this issue. That server is under heavy load all the time so Connections never sit idle (up to 2.5M dynamic pageviews per day). The JVM having the issues is running Quartz, a scheduling library (like cron jobs but in Java) so it can sit idle for a few hours, then wake up and access the database, then sleep again.
          Hide
          Phil Steitz added a comment -

          Need to resolve this prior to 1.3

          Show
          Phil Steitz added a comment - Need to resolve this prior to 1.3
          Hide
          Ronald Iwema added a comment -

          I have the same issue with the same characteristics.

          Using:

          Windows2003,
          MySQL 5.0.51a
          Apache Tomcat 5.5.25
          DBCP: 1.2.2
          Pool: 1.3

          The server is not frequently used, and I have no problems when using DBCP 1.2.1

          Show
          Ronald Iwema added a comment - I have the same issue with the same characteristics. Using: Windows2003, MySQL 5.0.51a Apache Tomcat 5.5.25 DBCP: 1.2.2 Pool: 1.3 The server is not frequently used, and I have no problems when using DBCP 1.2.1
          Hide
          Phil Steitz added a comment - - edited

          One possibility is that this change in behavior is caused by the change to address DBCP-102. In 1.2.1, PoolableConnectionFactory's activate method always did
          conn.setAutoCommit(_defaultAutoCommit);
          Could be stale / timed out MySQL connections throw (quickly) on this. Pool's borrowObject would swallow this and try to get another connection, moving along. The change to address DBCP-102 was to test the property in before resetting it, because for some drivers this caused a network hit. So in 1.2.2, activate succeeds, the client gets back the stale connection and things don't go south until the connection is used.

          Try adding conn.setAutoCommit(true) immediately after getConnection and before using the connection after wakeup. If this throws an exception, then the hypothesis above is correct.

          Show
          Phil Steitz added a comment - - edited One possibility is that this change in behavior is caused by the change to address DBCP-102 . In 1.2.1, PoolableConnectionFactory's activate method always did conn.setAutoCommit(_defaultAutoCommit); Could be stale / timed out MySQL connections throw (quickly) on this. Pool's borrowObject would swallow this and try to get another connection, moving along. The change to address DBCP-102 was to test the property in before resetting it, because for some drivers this caused a network hit. So in 1.2.2, activate succeeds, the client gets back the stale connection and things don't go south until the connection is used. Try adding conn.setAutoCommit(true) immediately after getConnection and before using the connection after wakeup. If this throws an exception, then the hypothesis above is correct.
          Hide
          Andrus Adamchik added a comment -

          I am observing a similar behavior with MySQL 5.0, dbcp-1.2.1, pool-1.2.... Also no visible deadlock in a thread dump. It happens once every few weeks, but usually simultaneously on multiple applications, so I suspect it is caused by temporary network outages... The problem of course is that the pool never recovers.

          Stuck threads look like this:

          btpool0-873" prio=10 tid=0x01001c50 nid=0x26a3 runnable [0x679fc000..0x679ffaf0]
          at java.net.SocketInputStream.socketRead0(Native Method)
          at java.net.SocketInputStream.read(SocketInputStream.java:129)
          at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
          at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
          at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)

          • locked <0xab4f6b20> (a com.mysql.jdbc.util.ReadAheadInputStream)
            at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1902)
            at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2351)
            at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2862)
            at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1571)
            at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1124)
          • locked <0xac8430b0> (a java.lang.Object)
            at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:676)
            at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1030)
          • locked <0xac8430b0> (a java.lang.Object)
          • locked <0xa69343f0> (a com.mysql.jdbc.ServerPreparedStatement)
            at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:92)
            at org.apache.cayenne.access.jdbc.SelectAction.performAction(SelectAction.java:72)

          DBCP pool is wrapped in a Cayenne decorator, but this is still a DBCP pool with the following settings:

          cayenne.dbcp.maxActive=8
          cayenne.dbcp.minIdle=1
          cayenne.dbcp.maxIdle=4
          cayenne.dbcp.validationQuery=select 1 from nhldb.division limit 1;
          cayenne.dbcp.testWhileIdle=true

          Can't even say that DBCP is here to blame, but still figured I provide this data point.

          Show
          Andrus Adamchik added a comment - I am observing a similar behavior with MySQL 5.0, dbcp-1.2.1, pool-1.2.... Also no visible deadlock in a thread dump. It happens once every few weeks, but usually simultaneously on multiple applications, so I suspect it is caused by temporary network outages... The problem of course is that the pool never recovers. Stuck threads look like this: btpool0-873" prio=10 tid=0x01001c50 nid=0x26a3 runnable [0x679fc000..0x679ffaf0] at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188) locked <0xab4f6b20> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1902) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2351) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2862) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1571) at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1124) locked <0xac8430b0> (a java.lang.Object) at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:676) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1030) locked <0xac8430b0> (a java.lang.Object) locked <0xa69343f0> (a com.mysql.jdbc.ServerPreparedStatement) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:92) at org.apache.cayenne.access.jdbc.SelectAction.performAction(SelectAction.java:72) DBCP pool is wrapped in a Cayenne decorator, but this is still a DBCP pool with the following settings: cayenne.dbcp.maxActive=8 cayenne.dbcp.minIdle=1 cayenne.dbcp.maxIdle=4 cayenne.dbcp.validationQuery=select 1 from nhldb.division limit 1; cayenne.dbcp.testWhileIdle=true Can't even say that DBCP is here to blame, but still figured I provide this data point.
          Hide
          Andrus Adamchik added a comment -

          > dbcp.testWhileIdle=true

          One correction to my previous comment - I think the setting above has no effect, since "timeBetweenEvictionRunsMillis" is not set.

          Show
          Andrus Adamchik added a comment - > dbcp.testWhileIdle=true One correction to my previous comment - I think the setting above has no effect, since "timeBetweenEvictionRunsMillis" is not set.
          Hide
          ori added a comment -

          Phil,

          I've tried your suggestion for about seven days in the live environment with no luck so far.

          Looking at the source code, it seems like an excellent guess. But I have not been able to induce the exception.

          Show
          ori added a comment - Phil, I've tried your suggestion for about seven days in the live environment with no luck so far. Looking at the source code, it seems like an excellent guess. But I have not been able to induce the exception.
          Hide
          ori added a comment -

          Phil,

          In response to your suggestion on Feb 1 2008, I can now confirm that this is not the case.

          All connections were obtained using the code below. The exception was thrown later on a SELECT query.

          public static Connection getConnection()
          throws SQLException

          { Connection conn = dataSource.getConnection(); conn.setAutoCommit(true); return conn; }

          Caused by: com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:

            • BEGIN NESTED EXCEPTION **

          java.net.SocketTimeoutException
          MESSAGE: Read timed out

          STACKTRACE:

          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:113)
          at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
          at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
          at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1994)
          at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2464)
          at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916)
          at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:885)
          at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1360)
          at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2369)
          at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:451)
          at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2076)
          at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1451)
          at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1787)
          at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
          at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
          at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1448)
          at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
          ...
          [my application code]

          Show
          ori added a comment - Phil, In response to your suggestion on Feb 1 2008, I can now confirm that this is not the case. All connections were obtained using the code below. The exception was thrown later on a SELECT query. public static Connection getConnection() throws SQLException { Connection conn = dataSource.getConnection(); conn.setAutoCommit(true); return conn; } – Caused by: com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception: BEGIN NESTED EXCEPTION ** java.net.SocketTimeoutException MESSAGE: Read timed out STACKTRACE: 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:113) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1994) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2464) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:885) at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1360) at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:2369) at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:451) at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2076) at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:1451) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1787) at com.mysql.jdbc.Connection.execSQL(Connection.java:3256) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1448) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93) ... [my application code]
          Hide
          Carl Gould added a comment -

          I'm seeing this too. I get one thread with the following dump (see below) and then the rest all block on

          org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294)

          This is on Windows Server 2003 Standard Ed, Java 1.5.0_11, DBCP 1.2.2, Pool 1.4 MySQL Connector/J 5.0.4

          We used DBCP 1.2.1 for years, and never saw this. It seems to happen after a network drop between DBCP and the database.

          Of course, we upgraded to DBCP 1.2.2 to fix the bug in 1.2.1 that caused the pool to leak connections when the underlying connection closed itself due to socket error and then the framework didn't catch the "already closed" exception...

          Anyhow, I digress, the stack trace of the blocked thread is:

          java.net.SocketInputStream.socketRead0(Native Method)
          java.net.SocketInputStream.read(Unknown Source)
          com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
          com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
          com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
          com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1910)
          com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:501)
          com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:971)
          com.mysql.jdbc.Connection.createNewIO(Connection.java:2670)
          com.mysql.jdbc.Connection.(Connection.java:1531)
          com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
          org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38)
          org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294)
          org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:974)
          org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:84)
          org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
          org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
          ...[ application code ]

          Show
          Carl Gould added a comment - I'm seeing this too. I get one thread with the following dump (see below) and then the rest all block on org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294) This is on Windows Server 2003 Standard Ed, Java 1.5.0_11, DBCP 1.2.2, Pool 1.4 MySQL Connector/J 5.0.4 We used DBCP 1.2.1 for years, and never saw this. It seems to happen after a network drop between DBCP and the database. Of course, we upgraded to DBCP 1.2.2 to fix the bug in 1.2.1 that caused the pool to leak connections when the underlying connection closed itself due to socket error and then the framework didn't catch the "already closed" exception... Anyhow, I digress, the stack trace of the blocked thread is: java.net.SocketInputStream.socketRead0(Native Method) java.net.SocketInputStream.read(Unknown Source) com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113) com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160) com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188) com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1910) com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:501) com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:971) com.mysql.jdbc.Connection.createNewIO(Connection.java:2670) com.mysql.jdbc.Connection.(Connection.java:1531) com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266) org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38) org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:294) org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:974) org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:84) org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96) org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880) ...[ application code ]
          Hide
          Mark Thomas added a comment -

          I'm not familiar enough with the changes from 1.2.1 to 1.2.2 to identify the change that caused this. However, the 1.2.2 behaviour is not unexpected. The database, or possibly a firewall, is closing the unused connections.

          Use of a validation query should prevent the exceptions.

          I can only speculate that the 1.2.1 code kept something open that perhaps it shouldn't and that was sufficient to keep the connection alive.

          I am closing this as invalid on the grounds that the observed behaviour is as expected.

          Show
          Mark Thomas added a comment - I'm not familiar enough with the changes from 1.2.1 to 1.2.2 to identify the change that caused this. However, the 1.2.2 behaviour is not unexpected. The database, or possibly a firewall, is closing the unused connections. Use of a validation query should prevent the exceptions. I can only speculate that the 1.2.1 code kept something open that perhaps it shouldn't and that was sufficient to keep the connection alive. I am closing this as invalid on the grounds that the observed behaviour is as expected.
          Hide
          ori added a comment -

          Mark I was using a validation query and still saw this.

          It's a real bug.

          But it's very difficult to hunt down. It may be an interaction specific to the MySQL driver.

          Show
          ori added a comment - Mark I was using a validation query and still saw this. It's a real bug. But it's very difficult to hunt down. It may be an interaction specific to the MySQL driver.
          Hide
          Mark Thomas added a comment -

          Re-opening based on previous comment.

          Can you still reproduce this?

          Show
          Mark Thomas added a comment - Re-opening based on previous comment. Can you still reproduce this?
          Hide
          Mark Thomas added a comment -

          A couple more questions.

          1. Are you sure you were using a validation query? None of your previous configuration information included validation query settings. What settings are you using?

          2. When the connection is idle is it idle in the pool or has been been obtained but not used for a while?

          And a couple of shots in the dark:

          3. Does it still happen with autoReconnect=false?

          4. Does it still happen with the latest mySQL driver?

          Show
          Mark Thomas added a comment - A couple more questions. 1. Are you sure you were using a validation query? None of your previous configuration information included validation query settings. What settings are you using? 2. When the connection is idle is it idle in the pool or has been been obtained but not used for a while? And a couple of shots in the dark: 3. Does it still happen with autoReconnect=false? 4. Does it still happen with the latest mySQL driver?
          Hide
          ori added a comment -

          I wasn't using the validation query when I reported my initial setup but I later added it to see if it would fix the issue. It did not.

          1. Yes I am sure.

          2.
          url=....autoReconnect=true;jdbcCompliantTruncation=false;socketTimeout=360000

          defaultAutoCommit=true
          driverClassName=com.mysql.Driver
          maxActive=500
          maxIdle=30
          minIdle=5
          initialSize=5
          maxWait=8000
          removeAbandoned=false
          logAbandoned=false
          poolPreparedStatements=false
          maxOpenPreparedStatements=50
          validationQuery=SELECT 1

          3. Not sure, I've always used autoReconnect. It's tough for me to test without because I cannot replicate this issue easily and I have since moved on to a different configuration. But at the time I was able to isolate it to the switch from DBCP 1.2.1->1.2.2. and it drove me crazy.

          4. Again, I'm not sure. It may be resolved. Because my setup has changed since than I cannot provide any more information.

          You can safely leave this issue closed for now and I'll definitely keep posting information if I can.

          Show
          ori added a comment - I wasn't using the validation query when I reported my initial setup but I later added it to see if it would fix the issue. It did not. 1. Yes I am sure. 2. url=....autoReconnect=true;jdbcCompliantTruncation=false;socketTimeout=360000 defaultAutoCommit=true driverClassName=com.mysql.Driver maxActive=500 maxIdle=30 minIdle=5 initialSize=5 maxWait=8000 removeAbandoned=false logAbandoned=false poolPreparedStatements=false maxOpenPreparedStatements=50 validationQuery=SELECT 1 3. Not sure, I've always used autoReconnect. It's tough for me to test without because I cannot replicate this issue easily and I have since moved on to a different configuration. But at the time I was able to isolate it to the switch from DBCP 1.2.1->1.2.2. and it drove me crazy. 4. Again, I'm not sure. It may be resolved. Because my setup has changed since than I cannot provide any more information. You can safely leave this issue closed for now and I'll definitely keep posting information if I can.
          Hide
          Mark Thomas added a comment -

          OK, I am resolving this as can't reproduce. If it surfaces again, feel free to reopen.

          Show
          Mark Thomas added a comment - OK, I am resolving this as can't reproduce. If it surfaces again, feel free to reopen.
          Hide
          Alexey Sergeev added a comment -

          The probem is reproducibe - that's for sure!
          To reach the problem you need to reconfigure MySQL server a little. I.e. update my.ini (on Windows) or my.cnf (on Linux) and set idle conection timeout to smaller value:

          [mysqld]
          ...
          # use one minute timeout
          wait_timeout=60 
          ...
          

          Default value is 8 hours so it is not so eacsy to reproduce "broken pipe" error so easy (not so feasible).

          So if you run you application (with commons-dbcp-1.2.2.jar) on mysql configured in this way you will be able to get the exception ().

          I've tried to use additional properties like maxOpenPreparedStatements, validationQuery nd etc. But it does NOT help!

          But one this that works ALWAYS - is using commons-dbcp-1.2.1.jar.

          So guys, could you fix this REAL problem and provide new release?! Or at least explayn what has been changed in new DBCP and how exacly it could be properly configured?

          Show
          Alexey Sergeev added a comment - The probem is reproducibe - that's for sure! To reach the problem you need to reconfigure MySQL server a little. I.e. update my.ini (on Windows) or my.cnf (on Linux) and set idle conection timeout to smaller value: [mysqld] ... # use one minute timeout wait_timeout=60 ... Default value is 8 hours so it is not so eacsy to reproduce "broken pipe" error so easy (not so feasible). So if you run you application (with commons-dbcp-1.2.2.jar) on mysql configured in this way you will be able to get the exception (). I've tried to use additional properties like maxOpenPreparedStatements, validationQuery nd etc. But it does NOT help! But one this that works ALWAYS - is using commons-dbcp-1.2.1.jar. So guys, could you fix this REAL problem and provide new release?! Or at least explayn what has been changed in new DBCP and how exacly it could be properly configured?
          Hide
          tangjie added a comment -

          I have the same problem, I'm using Sql Server 2005, the latest DBCP1.4 common-pool 1.54, the Sql Server's JDBC can not provide socketTime timeout, so I occasionally hang the connection, resulting in procedural paralysis, I Anxious,
          maxActive = 150
          maxIdle = 150
          minIdle = 0
          initialSize = 0
          maxWait = 30000
          removeAbandoned = false
          logAbandoned = false
          validationQuery = SELECT 1
          testOnBorrow = true
          testWhileIdle = false
          timeBetweenEvictionRunsMillis = 60000
          numTestsPerEvictionRun =- 2
          minEvictableIdleTimeMillis = 120000

          Show
          tangjie added a comment - I have the same problem, I'm using Sql Server 2005, the latest DBCP1.4 common-pool 1.54, the Sql Server's JDBC can not provide socketTime timeout, so I occasionally hang the connection, resulting in procedural paralysis, I Anxious, maxActive = 150 maxIdle = 150 minIdle = 0 initialSize = 0 maxWait = 30000 removeAbandoned = false logAbandoned = false validationQuery = SELECT 1 testOnBorrow = true testWhileIdle = false timeBetweenEvictionRunsMillis = 60000 numTestsPerEvictionRun =- 2 minEvictableIdleTimeMillis = 120000
          Hide
          Phil Steitz added a comment -

          @tangile: What exactly do you mean by "procedural paralysis?" Do you mean that the thread waiting on the hung socket stalls, or other threads as well are blocked? If the latter, can you attach a thread dump?

          Show
          Phil Steitz added a comment - @tangile: What exactly do you mean by "procedural paralysis?" Do you mean that the thread waiting on the hung socket stalls, or other threads as well are blocked? If the latter, can you attach a thread dump?
          Hide
          tangjie added a comment -

          "pool-1-thread-149" prio=10 tid=0x00002aac442f5800 nid=0x65a3 runnable [0x000000004884b000]
          java.lang.Thread.State: RUNNABLE
          at java.net.SocketInputStream.socketRead0(Native Method)
          at java.net.SocketInputStream.read(SocketInputStream.java:129)
          at com.microsoft.sqlserver.jdbc.TDSChannel.read(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(Unknown Source)
          at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(Unknown Source)
          at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSCommand.execute(Unknown Source)
          at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(Unknown Source)

          • locked <0x00002aab7ddeb8c8> (a com.microsoft.sqlserver.jdbc.SQLServerConnection)
            at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(Unknown Source)
          • locked <0x00002aab7ddec1d8> (a com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement)
            at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(Unknown Source)
            at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(Unknown Source)
            at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
            at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
          Show
          tangjie added a comment - "pool-1-thread-149" prio=10 tid=0x00002aac442f5800 nid=0x65a3 runnable [0x000000004884b000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.microsoft.sqlserver.jdbc.TDSChannel.read(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSCommand.execute(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(Unknown Source) locked <0x00002aab7ddeb8c8> (a com.microsoft.sqlserver.jdbc.SQLServerConnection) at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(Unknown Source) locked <0x00002aab7ddec1d8> (a com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement) at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(Unknown Source) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
          Hide
          tangjie added a comment -

          the connection hang forever.

          Show
          tangjie added a comment - the connection hang forever.
          Hide
          tangjie added a comment -

          pool-1-thread-247" prio=10 tid=0x00002aac48112000 nid=0x7155 runnable [0x000000005bf3b000]
          java.lang.Thread.State: RUNNABLE
          at java.net.SocketInputStream.socketRead0(Native Method)
          at java.net.SocketInputStream.read(SocketInputStream.java:129)
          at com.microsoft.sqlserver.jdbc.TDSChannel.read(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(Unknown Source)
          at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(Unknown Source)
          at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(Unknown Source)
          at com.microsoft.sqlserver.jdbc.TDSCommand.execute(Unknown Source)
          at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(Unknown Source)

          • locked <0x00002aab80b55d30> (a com.microsoft.sqlserver.jdbc.SQLServerConnection)
            at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(Unknown Source)
          • locked <0x00002aab80b55e18> (a com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement)
            at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(Unknown Source)
            at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.execute(Unknown Source)
            at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
            at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
          Show
          tangjie added a comment - pool-1-thread-247" prio=10 tid=0x00002aac48112000 nid=0x7155 runnable [0x000000005bf3b000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.microsoft.sqlserver.jdbc.TDSChannel.read(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(Unknown Source) at com.microsoft.sqlserver.jdbc.TDSCommand.execute(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(Unknown Source) locked <0x00002aab80b55d30> (a com.microsoft.sqlserver.jdbc.SQLServerConnection) at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(Unknown Source) locked <0x00002aab80b55e18> (a com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement) at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(Unknown Source) at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.execute(Unknown Source) at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172) at org.apache.commons.dbcp.DelegatingPreparedStatement.execute(DelegatingPreparedStatement.java:172)
          Hide
          tangjie added a comment -

          I have no other way I can change one of the other sql server 2005 JDBC driver, JTDS, so that you can set the socket timeout

          Show
          tangjie added a comment - I have no other way I can change one of the other sql server 2005 JDBC driver, JTDS, so that you can set the socket timeout

            People

            • Assignee:
              Unassigned
              Reporter:
              ori
            • Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development