Uploaded image for project: 'Sakai'
  1. Sakai
  2. SAK-38852

Connection leaks lead to SQLTransientConnectionException using Oracle & Terracotta

    Details

    • Type: Bug
    • Status: CLOSED
    • Priority: Major
    • Resolution: Non-Issue
    • Affects Version/s: 11.0
    • Fix Version/s: None
    • Component/s: Kernel
    • Labels:
      None
    • Previous Issue Keys:
      KNL-1437

      Description

      Oracle DB: 12.1.0.2
      ojdbc7-12.1.0.2 (deployed using -p oracle in sakai:deploy)

      HikariCP: 2.4.6
      Two Sakai11 Tomcat servers w/Terracotta enabled (only session replication):

      memory.cluster.enabled=true
      memory.cluster.server.urls.count=2
      memory.cluster.server.urls.1=sakai1-terra.servers.udayton.edu:9510
      memory.cluster.server.urls.2=sakai2-terra.servers.udayton.edu:9510
      memory.cluster.names.count=1
      memory.cluster.names.1=org.sakaiproject.tool.impl.RebuildBreakdownService.cache
      session.cluster.replication=true
      

      Oracle sakai.property settings:

      validationQuery@javax.sql.BaseDataSource=
      defaultTransactionIsolationString@javax.sql.BaseDataSource=
      testOnBorrow@javax.sql.BaseDataSource=false
      

      Note: There are other servers connected to this database, but only the terracotta enabled servers experience this issue.

      HikariCP Configuration (note: pool size is 25, & leakDetectionThreshold is 30000):

      2016-05-20 15:42:37,291  INFO localhost-startStop-1 org.sakaiproject.hikaricp.jdbc.pool.SakaiBasicDataSource - init()
      2016-05-20 15:42:37,291 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - sakai - configuration:
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - autoCommit......................false
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - catalog.........................null
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - connectionInitSql...............null
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - connectionTestQuery.............null
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - dataSource......................null
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - dataSourceClassName.............null
      2016-05-20 15:42:37,300 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................null
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>, prepStmtCacheSqlLimit=2048, useServerPrepStmts=true, cachePrepStmts=true, prepStmtCacheSize=250}
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - driverClassName................."oracle.jdbc.driver.OracleDriver"
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............null
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - initializationFailFast..........true
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - jdbc4ConnectionTest.............false
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - jdbcUrl........................."jdbc:oracle:thin:@<removed>:1521:sktest11"
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........30000
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - maximumPoolSize.................25
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - metricRegistry..................null
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........null
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - minimumIdle.....................10
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - password........................<masked>
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - poolName........................"sakai"
      2016-05-20 15:42:37,301 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - readOnly........................false
      2016-05-20 15:42:37,302 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - registerMbeans..................true
      2016-05-20 15:42:37,302 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - scheduledExecutorService........null
      2016-05-20 15:42:37,302 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - threadFactory...................null
      2016-05-20 15:42:37,302 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - transactionIsolation............null
      2016-05-20 15:42:37,302 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - username........................"sakaiuser"
      2016-05-20 15:42:37,302 DEBUG localhost-startStop-1 com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
      

      Eventually errors like the following occur:

      2016-05-20 15:45:22,049  WARN sakai housekeeper com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for oracle.jdbc.driver.T4CConnection@54c58c2b, stack trace follows
      java.lang.Exception: Apparent connection leak detected
      	at org.sakaiproject.db.impl.BasicSqlService.borrowConnection(BasicSqlService.java:260)
      	at org.sakaiproject.event.impl.ClusterEventTracking.writeBatchEvents(ClusterEventTracking.java:378)
      	at org.sakaiproject.event.impl.ClusterEventTracking.run(ClusterEventTracking.java:570)
      	at java.lang.Thread.run(Thread.java:745)
      

      these mount up until we get an SQLTransientConnectionException:

      2016-05-20 15:47:17,428  WARN org.sakaiproject.event.impl.ClusterEventTracking$$EnhancerBySpringCGLIB$$d42ec2bd org.sakaiproject.event.impl.ClusterEventTracking - org.sakaiproject.event.impl.ClusterEventTracking$$EnhancerBySpringCGLIB$$d42ec2bd@5dbc423.writeBatchEvents: java.sql.SQLTransientConnectionException: sakai - Connection is not available, request timed out after 30001ms.
      java.sql.SQLTransientConnectionException: sakai - Connection is not available, request timed out after 30001ms.
      	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196)
      	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:147)
      	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:99)
      	at org.sakaiproject.db.impl.BasicSqlService.borrowConnection(BasicSqlService.java:260)
      	at org.sakaiproject.event.impl.ClusterEventTracking.writeBatchEvents(ClusterEventTracking.java:400)
      	at org.sakaiproject.event.impl.ClusterEventTracking.run(ClusterEventTracking.java:570)
      	at java.lang.Thread.run(Thread.java:745)
      

      I've attached the full catalina.out (yes, I know that the DB is mal-configured). I've also attached the YourKit snapshot taken of this session.

      Please let me know if there is anything else you need.

      I made a post on the HikariCP google group about this.

        Gliffy Diagrams

          Zeplin

            Attachments

              Issue Links

                Activity

                  People

                  Assignee:
                  k1team KERNEL TEAM (Inactive)
                  Reporter:
                  lcanessa Leonardo Canessa
                  Votes:
                  0 Vote for this issue
                  Watchers:
                  10 Start watching this issue

                    Dates

                    Created:
                    Updated:
                    Resolved:

                      Git Integration