Io exception: Broken pipe
Eduardo Teixeira
pool. We have a project that accesses a remote Oracle database using the
WebLogic connection pool (Oracle thin driver version 8.1.6.2.0). We talk to
this remote database through stored procedures stored in the remote database
(obviously, but it is always good to emphasize the procedures to avoid
misunderstandings :-)). Every time the remote database is shutdown and
re-started we get an "Oracle database.Io exception: Broken pipe". The
WebLogic database pool becomes unusable since all attempts to access the
database though WebLogic java code using the database pool raises this
exception. The only way to fix this is re-starting the WebLogic server. We
have set the Weblogic Refresh period to 15 minutes, the test table name to
"SYS.DUAL", enabled the TestConnectionsOnReserve and
TestConnectionsOnRelease features and this does not seem to fix the problem
either.
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.