We can see in the WebLogic.log when the application was trying to get a
connection pool and the TestOnReserve test was being executed and failing as
we can see below (extracted from the WebLogic.log);
####<Aug 12, 2001 8:56:10 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <This connection will now be refreshed.>
####<Aug 12, 2001 8:56:10 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <Refreshing this bad pool connection failed>
weblogic.common.ResourceException:
Could not create pool connection. The DBMS driver exception was:
java.sql.SQLException: ORA-01034: ORACLE not available
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:114)
at oracle.jdbc.ttc7.TTIoer.processError(TTIoer.java:208)
at oracle.jdbc.ttc7.O3log.receive1st(O3log.java:429)
at oracle.jdbc.ttc7.TTC7Protocol.logon(TTC7Protocol.java:228)
at oracle.jdbc.driver.OracleConnection.<init>(OracleConnection.java:200)
at
oracle.jdbc.driver.OracleDriver.getConnectionInstance(OracleDriver.java:251)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:224)
at
weblogic.jdbc.common.internal.ConnectionEnvFactory.makeConnection(Connection
EnvFactory.java:155)
at
weblogic.jdbc.common.internal.ConnectionEnvFactory.refreshResource(Connectio
nEnvFactory.java:194)
at
weblogic.common.internal.ResourceAllocator.resetThisOne(ResourceAllocator.ja
va:771)
at
weblogic.common.internal.ResourceAllocator.reserve(ResourceAllocator.java:45
9)
at
weblogic.common.internal.ResourceAllocator.reserveUnused(ResourceAllocator.j
ava:355)
at
weblogic.common.internal.ResourceAllocator.trigger(ResourceAllocator.java:99
8)
at
weblogic.time.common.internal.ScheduledTrigger.executeLocally(ScheduledTrigg
er.java:225)
at
weblogic.time.common.internal.ScheduledTrigger.execute(ScheduledTrigger.java
:216)
at weblogic.time.server.ScheduledTrigger.execute(ScheduledTrigger.java:65)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:137)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
at
weblogic.jdbc.common.internal.ConnectionEnvFactory.makeConnection(Connection
EnvFactory.java:169)
at
weblogic.jdbc.common.internal.ConnectionEnvFactory.refreshResource(Connectio
nEnvFactory.java:194)
at
weblogic.common.internal.ResourceAllocator.resetThisOne(ResourceAllocator.ja
va:771)
at
weblogic.common.internal.ResourceAllocator.reserve(ResourceAllocator.java:45
9)
at
weblogic.common.internal.ResourceAllocator.reserveUnused(ResourceAllocator.j
ava:355)
at
weblogic.common.internal.ResourceAllocator.trigger(ResourceAllocator.java:99
8)
at
weblogic.time.common.internal.ScheduledTrigger.executeLocally(ScheduledTrigg
er.java:225)
at
weblogic.time.common.internal.ScheduledTrigger.execute(ScheduledTrigger.java
:216)
at weblogic.time.server.ScheduledTrigger.execute(ScheduledTrigger.java:65)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:137)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
.
.
.
####<Aug 12, 2001 9:11:10 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <A connection from pool clarifyPool was tested during
reserve with a select count(*) from SYS.DUAL and failed:>
####<Aug 12, 2001 9:11:10 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <java.sql.SQLException: No more data to read from
socket
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:114)
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:156)
at oracle.jdbc.dbaccess.DBError.check_error(DBError.java:803)
at oracle.jdbc.ttc7.MAREngine.unmarshalUB1(MAREngine.java:731)
at oracle.jdbc.ttc7.MAREngine.unmarshalSB1(MAREngine.java:690)
at oracle.jdbc.ttc7.Oopen.receive(Oopen.java:103)
at oracle.jdbc.ttc7.TTC7Protocol.open(TTC7Protocol.java:445)
at oracle.jdbc.driver.OracleStatement.<init>(OracleStatement.java:288)
at
oracle.jdbc.driver.OracleConnection.createStatement(OracleConnection.java:31
3)
at weblogic.jdbc.common.internal.ConnectionEnv.test(ConnectionEnv.java:654)
at
weblogic.common.internal.ResourceAllocator.reserve(ResourceAllocator.java:44
4)
at
weblogic.common.internal.ResourceAllocator.reserveUnused(ResourceAllocator.j
ava:355)
at
weblogic.common.internal.ResourceAllocator.trigger(ResourceAllocator.java:99
8)
at
weblogic.time.common.internal.ScheduledTrigger.executeLocally(ScheduledTrigg
er.java:225)
at
weblogic.time.common.internal.ScheduledTrigger.execute(ScheduledTrigger.java
:216)
at weblogic.time.server.ScheduledTrigger.execute(ScheduledTrigger.java:65)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:137)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
.
.
.
####<Aug 12, 2001 9:11:10 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <This connection will now be refreshed.>
####<Aug 12, 2001 9:11:10 AM PDT> <Info> <JDBC Connection Pool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <Connection for pool "clarifyPool" refreshed.>
####<Aug 12, 2001 9:11:10 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <A connection from pool clarifyPool was tested during
reserve with a select count(*) from SYS.DUAL and failed:>
####<Aug 12, 2001 9:11:10 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <java.sql.SQLException: No more data to read from
socket
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:114)
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:156)
at oracle.jdbc.dbaccess.DBError.check_error(DBError.java:803)
at oracle.jdbc.ttc7.MAREngine.unmarshalUB1(MAREngine.java:731)
at oracle.jdbc.ttc7.MAREngine.unmarshalSB1(MAREngine.java:690)
at oracle.jdbc.ttc7.Oopen.receive(Oopen.java:103)
at oracle.jdbc.ttc7.TTC7Protocol.open(TTC7Protocol.java:445)
at oracle.jdbc.driver.OracleStatement.<init>(OracleStatement.java:288)
at
oracle.jdbc.driver.OracleConnection.createStatement(OracleConnection.java:31
3)
at weblogic.jdbc.common.internal.ConnectionEnv.test(ConnectionEnv.java:654)
at
weblogic.common.internal.ResourceAllocator.reserve(ResourceAllocator.java:44
4)
at
weblogic.common.internal.ResourceAllocator.reserveUnused(ResourceAllocator.j
ava:355)
at
weblogic.common.internal.ResourceAllocator.trigger(ResourceAllocator.java:99
8)
at
weblogic.time.common.internal.ScheduledTrigger.executeLocally(ScheduledTrigg
er.java:225)
at
weblogic.time.common.internal.ScheduledTrigger.execute(ScheduledTrigger.java
:216)
at weblogic.time.server.ScheduledTrigger.execute(ScheduledTrigger.java:65)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:137)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
.
.
.
####<Aug 12, 2001 9:11:11 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <This connection will now be refreshed.>
####<Aug 12, 2001 9:11:11 AM PDT> <Info> <JDBC Connection Pool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <Connection for pool "clarifyPool" refreshed.>
####<Aug 12, 2001 9:11:11 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <A connection from pool clarifyPool was tested during
reserve with a select count(*) from SYS.DUAL and failed:>
####<Aug 12, 2001 9:11:11 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <java.sql.SQLException: Closed Connection
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:114)
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:156)
at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:219)
at
oracle.jdbc.driver.OracleConnection.createStatement(OracleConnection.java:31
1)
at weblogic.jdbc.common.internal.ConnectionEnv.test(ConnectionEnv.java:654)
at
weblogic.common.internal.ResourceAllocator.reserve(ResourceAllocator.java:44
4)
at
weblogic.common.internal.ResourceAllocator.reserveUnused(ResourceAllocator.j
ava:355)
at
weblogic.common.internal.ResourceAllocator.trigger(ResourceAllocator.java:99
8)
at
weblogic.time.common.internal.ScheduledTrigger.executeLocally(ScheduledTrigg
er.java:225)
at
weblogic.time.common.internal.ScheduledTrigger.execute(ScheduledTrigger.java
:216)
at weblogic.time.server.ScheduledTrigger.execute(ScheduledTrigger.java:65)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:137)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
At the time these messages above were logged in the WebLogic.log the Oracle
database was probably down (from Aug 12, 2001 8:56:10 AM PDT to Aug 12, 2001
9:11:11 AM PDT). Notice that when the Oracle database was brought up the
database pool was refreshed and no more TestOnReserve failure messages were
logged on the WebLogic.log.
####<Aug 12, 2001 9:11:11 AM PDT> <Info> <JDBC Pool clarifyPool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <This connection will now be refreshed.>
####<Aug 12, 2001 9:11:11 AM PDT> <Info> <JDBC Connection Pool>
<itapp1.autodesk.com> <default> <ExecuteThread: '11' for queue: 'default'>
<system> <> <000000> <Connection for pool "clarifyPool" refreshed.>
####<Aug 13, 2001 9:40:25 AM PDT> <Info> <HTTP> <itapp1.autodesk.com>
<default> <ExecuteThread: '8' for queue: 'default'> <system> <> <101047>
<[WebAppServletContext(2970932,console)] *.html: init>
####<Aug 13, 2001 9:40:25 AM PDT> <Info> <HTTP> <itapp1.autodesk.com>
<default> <ExecuteThread: '8' for queue: 'default'> <system> <> <101047>
<[WebAppServletContext(2970932,console)] *.html: Using standard I/O>
We noticed though that we started to get the "Oracle database.Io exception:
Broken pipe" after Aug 12, 2001 9:11:11 AM (after the Oracle database was
brought up) and before Aug 13, 2001 9:40:25 AM PDT when we have restarted
WebLogic. In between nothing was reported in the WebLogic.log and our
application was constantly having the "Oracle database.Io exception: Broken
pipe" since we were trying to access the database from our java code. Why
would we have the "Oracle database.Io exception: Broken pipe" exceptions if
the Oracle database was up and nothing was reported in the WebLogic.log ?
Please, Are you aware of any issues with WebLogic database connection pools
with the scenario described above ? Is there any other WebLogic settings
that could fix this problem ? Is this an Oracle driver problem ?
Thanks,
Eduardo.