java.sql.SQLRecoverableException: IO 错误: Socket closed

傷城~ 2022-08-06 07:29 218阅读 0赞

今天weblogic的alllog日志报了很多socket closed的错误。

**\#\#\# Cause: org.hibernate.exception.JDBCConnectionException: IO 错误: Socket closed**

at com.gg.corm.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:23) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:104) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:95) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:59) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.sproc.core.base.dao.MyBatisDAO$6.execute(MyBatisDAO.java:241) ~\[sproc-core-1.3.1-20141225.jar:1.3.1-20141225\]  
at org.hibernate.jdbc.WorkExecutor.executeWork(WorkExecutor.java:54) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.internal.SessionImpl$2.accept(SessionImpl.java:1936) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.internal.SessionImpl$2.accept(SessionImpl.java:1933) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.coordinateWork(JdbcCoordinatorImpl.java:211) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.internal.SessionImpl.doWork(SessionImpl.java:1954) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.internal.SessionImpl.doWork(SessionImpl.java:1940) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at com.gg.sproc.core.base.dao.MyBatisDAO.getObject(MyBatisDAO.java:236) ~\[sproc-core-1.3.1-20141225.jar:1.3.1-20141225\]  
... 75 common frames omitted  
**Caused by: org.hibernate.exception.JDBCConnectionException: IO 错误: Socket closed**  
at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:131) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementProxyHandler.java:129) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
at com.sun.proxy.$Proxy250.execute(Unknown Source) ~\[na:na\]  
at com.gg.corm.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:56) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:70) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at sun.reflect.GeneratedMethodAccessor197.invoke(Unknown Source) ~\[na:na\]  
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~\[na:1.7.0\_40\]  
at java.lang.reflect.Method.invoke(Method.java:606) ~\[na:1.7.0\_40\]  
at com.gg.corm.plugin.Plugin.invoke(Plugin.java:59) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.sun.proxy.$Proxy234.query(Unknown Source) ~\[na:na\]  
at com.gg.corm.executor.SimpleExecutor.doQuery(SimpleExecutor.java:69) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:267) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.executor.BaseExecutor.query(BaseExecutor.java:141) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.executor.CachingExecutor.query(CachingExecutor.java:105) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.executor.CachingExecutor.query(CachingExecutor.java:81) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
at com.gg.corm.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:101) ~\[gg-top-corm-3.1.2-20141209.jar:na\]  
... 85 common frames omitted  
**Caused by: java.sql.SQLRecoverableException: IO 错误: Socket closed**  
at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:897) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1167) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1289) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3594) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3695) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1378) ~\[ojdbc6.jar:11.2.0.3.0\]  
at weblogic.jdbc.wrapper.PreparedStatement.execute(PreparedStatement.java:101) ~\[weblogic.server.merged.jar:12.1.2.0.0\]  
at sun.reflect.GeneratedMethodAccessor695.invoke(Unknown Source) ~\[na:na\]  
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~\[na:1.7.0\_40\]  
at java.lang.reflect.Method.invoke(Method.java:606) ~\[na:1.7.0\_40\]  
at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementProxyHandler.java:122) ~\[com.gg.top.thirdparty-hibernate-core-4.1.9.Final.jar:4.1.9.Final\]  
... 100 common frames omitted  
Caused by: java.net.SocketException: Socket closed  
at java.net.SocketInputStream.socketRead0(Native Method) ~\[na:1.7.0\_40\]  
at java.net.SocketInputStream.read(SocketInputStream.java:152) ~\[na:1.7.0\_40\]  
at java.net.SocketInputStream.read(SocketInputStream.java:122) ~\[na:1.7.0\_40\]  
at oracle.net.ns.Packet.receive(Packet.java:300) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.net.ns.DataPacket.receive(DataPacket.java:106) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:315) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.net.ns.NetInputStream.read(NetInputStream.java:260) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.net.ns.NetInputStream.read(NetInputStream.java:185) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.net.ns.NetInputStream.read(NetInputStream.java:102) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:531) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207) ~\[ojdbc6.jar:11.2.0.3.0\]  
at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:884) ~\[ojdbc6.jar:11.2.0.3.0\]

... 110 common frames omitted

**再检查server日志，发现在alllog中报socket closed错误的时段：**

\#\#\#\#<2015-1-5 上午11时37分22秒 CST> <Info> <JDBC> <scgg15140> <appServer> <\[ACTIVE\] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1420429042060> <BEA-001128> <**Connection for pool "ggDataSource" has been closed**.>   
\#\#\#\#<2015-1-5 上午11时38分32秒 CST> <Info> <JDBC> <scgg15140> <appServer> <\[ACTIVE\] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1420429112057> <BEA-001128> <Connection for pool "ggDataSource" has been closed.>   
\#\#\#\#<2015-1-5 上午11时38分52秒 CST> <Info> <JDBC> <scgg15140> <appServer> <\[ACTIVE\] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1420429132057> <BEA-001128> <Connection for pool "ggDataSource" has been closed.>   
\#\#\#\#<2015-1-5 上午11时51分32秒 CST> <Info> <JDBC> <scgg15140> <appServer> <\[ACTIVE\] ExecuteThread: '13' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1420429892057> <BEA-001128> <Connection for pool "ggDataSource" has been closed.>

连接池关闭，连接池为甚关闭呢？在此时间段只有一条SQL报错，为什么不是大规模的报错呢？

与一名开发人员反馈，说每次都可以出现，于是找他重现。在16点到17点重现了，但在17点到18点又重现不了，我无意识的看了两个时段的AWR报告，发现有报错时段的SQL执行时37s，没有报错时段的SQL执行是2s。

我怀疑与非活动连接超时这个参数有关系，于是找了一个功能为120s的，做了个测试：

<table>     
 <tbody> 
  <tr> 
   <td>非活动连接超时</td> 
   <td>等待多少秒后报错</td> 
  </tr> 
  <tr> 
   <td align="right">1 &nbsp; &nbsp; &nbsp;</td> 
   <td>20s</td> 
  </tr> 
  <tr> 
   <td align="right">5 &nbsp; &nbsp; &nbsp;</td> 
   <td>16s</td> 
  </tr> 
  <tr> 
   <td align="right">10 &nbsp; &nbsp;&nbsp;</td> 
   <td>40s</td> 
  </tr> 
  <tr> 
   <td align="right">15 &nbsp; &nbsp;&nbsp;</td> 
   <td>不报错，等待120s后功能出来了</td> 
  </tr> 
  <tr> 
   <td align="right">&nbsp; 30 &nbsp; &nbsp;&nbsp;</td> 
   <td>同上</td> 
  </tr> 
  <tr> 
   <td align="right">50 &nbsp; &nbsp;&nbsp;</td> 
   <td>同上</td> 
  </tr> 
 </tbody> 
</table>

**总结：治标的调大非活动连接超时这个参数，治本的方法是调优SQL。**

A leaked connection is a connection that was not properly returned to the connection pool in the data source. To automatically recover leaked connections, you can specify a value for `Inactive Connection Timeout`on the JDBC Data Source: Configuration: Connection Pool page in the Administration Console. When you set a value for `Inactive Connection Timeout,` WebLogic Server forcibly returns a connection to the data source when there is no activity on a reserved connection for the number of seconds that you specify. When set to `0` (the default value), this feature is turned off.