More fun with IDP V2 and the database backed storage service

[Wessel, Keith]

All,

Wondering if there's some type of JNDI parameter or low-level driver parameter that effects how long a Tomcat DB connection pool will wait for a connection. Something happened this morning that, as far as I can tell, shouldn't.

We had a SAN failure that took down our Oracle database. I'd expect that, finding no connections in the pool with maxWait=1000, Tomcat would have returned no connections available and the DB-backed storage service would have gone on its merry way. Instead, it caused Tomcat to hang for longer than the mod_jk connection timeout in Apache which resulted in gateway timeout errors to users after clicking the login button.

Because the Oracle server was totally down, we had connections timing out instead of just refused. I think that confused things. My theory is that the low-level Oracle driver was causing the delay and, for whatever reason, the connection pool logic which should have caused things to proceed without a database didn't have a chance to fire. Is there a parameter to control how long a network connection will wait before returning connection timed out? Here's the log snippet:

08:11:58.201 - ERROR [net.clareitysecurity.shibboleth.db.SessionObjectDAOImpl:296] [session=] -
org.hibernate.exception.GenericJDBCException: Cannot open connection
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:426) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326) ~[hibernate3.jar:3.2.5.ga]
at net.clareitysecurity.shibboleth.db.SessionObjectDAOImpl.openSession(SessionObjectDAOImpl.java:343) [db-storage-service-1.1.3.jar:na]
at net.clareitysecurity.shibboleth.db.SessionObjectDAOImpl.getCsIdpSession(SessionObjectDAOImpl.java:278) [db-storage-service-1.1.3.jar:na]
at net.clareitysecurity.shibboleth.db.SessionObjectDAOImpl.getSession(SessionObjectDAOImpl.java:162) [db-storage-service-1.1.3.jar:na]
at net.clareitysecurity.shibboleth.storage.DbStorageService.getPersistent(DbStorageService.java:245) [db-storage-service-1.1.3.jar:na]
at net.clareitysecurity.shibboleth.storage.DbStorageService.get(DbStorageService.java:297) [db-storage-service-1.1.3.jar:na]
at edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl.getSession(SessionManagerImpl.java:143) [shibboleth-identityprovider-2.4.2.jar:na]
at edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl.getSession(SessionManagerImpl.java:33) [shibboleth-identityprovider-2.4.2.jar:na]
at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.getUserSession(IdPSessionFilter.java:172) [shibboleth-identityprovider-2.4.2.jar:na]
at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:79) [shibboleth-identityprovider-2.4.2.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.41]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.41]
at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52) [shibboleth-common-1.4.2.jar:na]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina.jar:6.0.41]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:6.0.41]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219) [catalina.jar:6.0.41]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina.jar:6.0.41]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina.jar:6.0.41]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:6.0.41]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina.jar:6.0.41]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) [catalina.jar:6.0.41]
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190) [tomcat-coyote.jar:6.0.41]
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:311) [tomcat-coyote.jar:6.0.41]
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:776) [tomcat-coyote.jar:6.0.41]
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:705) [tomcat-coyote.jar:6.0.41]
at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:898) [tomcat-coyote.jar:6.0.41]
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) [tomcat-coyote.jar:6.0.41]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_60]
Caused by: org.apache.tomcat.dbcp.dbcp.SQLNestedException: Cannot create PoolableConnectionFactory (The Network Adapter could not establish the connection)
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:1549) ~[tomcat-dbcp.jar:6.0.41]
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.createDataSource(BasicDataSource.java:1388) ~[tomcat-dbcp.jar:6.0.41]
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044) ~[tomcat-dbcp.jar:6.0.41]
at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69) ~[hibernate3.jar:3.2.5.ga]
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423) ~[hibernate3.jar:3.2.5.ga]
... 31 common frames omitted
Caused by: java.sql.SQLException: The Network Adapter could not establish the connection
at oracle.jdbc.driver.SQLStateMapping.newSQLException(SQLStateMapping.java:70) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.DatabaseError.newSQLException(DatabaseError.java:133) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:199) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:480) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:413) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:508) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:203) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:33) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:510) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at org.apache.tomcat.dbcp.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38) ~[tomcat-dbcp.jar:6.0.41]
at org.apache.tomcat.dbcp.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:582) ~[tomcat-dbcp.jar:6.0.41]
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.validateConnectionFactory(BasicDataSource.java:1556) ~[tomcat-dbcp.jar:6.0.41]
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.createPoolableConnectionFactory(BasicDataSource.java:1545) ~[tomcat-dbcp.jar:6.0.41]
... 35 common frames omitted
Caused by: oracle.net.ns.NetException: The Network Adapter could not establish the connection
at oracle.net.nt.ConnStrategy.execute(ConnStrategy.java:328) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.net.resolver.AddrResolution.resolveAndExecute(AddrResolution.java:421) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.net.ns.NSProtocol.establishConnection(NSProtocol.java:630) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.net.ns.NSProtocol.connect(NSProtocol.java:206) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:966) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:292) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
... 43 common frames omitted
Caused by: java.net.ConnectException: Connection timed out
at java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:1.7.0_60]
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) ~[na:1.7.0_60]
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) ~[na:1.7.0_60]
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) ~[na:1.7.0_60]
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[na:1.7.0_60]
at java.net.Socket.connect(Socket.java:579) ~[na:1.7.0_60]
at java.net.Socket.connect(Socket.java:528) ~[na:1.7.0_60]
at java.net.Socket.<init>(Socket.java:425) ~[na:1.7.0_60]
at java.net.Socket.<init>(Socket.java:208) ~[na:1.7.0_60]
at oracle.net.nt.TcpNTAdapter.connect(TcpNTAdapter.java:127) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.net.nt.ConnOption.connect(ConnOption.java:126) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
at oracle.net.nt.ConnStrategy.execute(ConnStrategy.java:306) ~[ojdbc6.jar:Oracle JDBC Driver version - "11.1.0.7.0-Production"]
... 48 common frames omitted

Thanks for any help,
Keith