Tuesday, June 24, 2014

java.sql.SQLRecoverableException: IO Error: Connection reset


I have come across below error during Oracle Agile Managed Server deployment (Agile 9.3.3). When trying to startup the Managed server which is using Weblogic12c, it didn’t startup and found below error in logfile.

Your environment has been set.
AgileAuthenticationProviderImpl.initialize
log4j:WARN No appenders could be found for logger (com.agile.util.sql.OracleConnectionImpl).
log4j:WARN Please initialize the log4j system properly.
java.sql.SQLRecoverableException: IO Error: Connection reset
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:467)
at oracle.jdbc.driver.PhysicalConnection.<init>(PhysicalConnection.java:546)
at oracle.jdbc.driver.T4CConnection.<init>(T4CConnection.java:236)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
at oracle.jdbc.pool.OracleDataSource.getPhysicalConnection(OracleDataSource.java:280)
at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:207) at
oracle.jdbc.pool.OracleConnectionPoolDataSource.getPhysicalConnection(OracleConnectionPool Data Source.java:139) at oracle.jdbc.pool.OracleConnectionPoolDataSource.getPooledConnection (Oracle ConnectionPool Data Source.java:88) at........ com.bea.common.security.internal.service.LoginModuleWrapper$1.run(LoginModuleWrapper.java:110)
at java.security.AccessController.doPrivileged(Native Method) at com.bea.common.security.internal.service.LoginModuleWrapper.login(LoginModuleWrapper.java:106)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at javax.security.auth.login.LoginContext.invoke(LoginContext.java:762)
at javax.security.auth.login.LoginContext.access$000(LoginContext.java:203)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:690)
at javax.security.auth.login.LoginContext$4.run(LoginContext.java:688)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.login.LoginContext.invokePriv(LoginContext.java:687)
at javax.security.auth.login.LoginContext.login(LoginContext.java:595) at com.bea.common.security.internal.service.JAASLoginServiceImpl.login(JAASLoginServiceImpl.java:113)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606) at com.bea.common.security.internal.utils.Delegator$ProxyInvocationHandler.invoke(Delegator.java:57)
at com.sun.proxy.$Proxy13.login(Unknown Source) at weblogic.security.service.internal.WLSJAASLoginServiceImpl$ServiceImpl.login(WLSJAASLoginServiceImpl.java:89) at com.bea.common.security.internal.service.JAASAuthenticationServiceImpl.authenticate(JAASAuthenticationServiceImpl.java:82)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606) at com.bea.common.security.internal.utils.Delegator$ProxyInvocationHandler.invoke(Delegator.java:57)
at com.sun.proxy.$Proxy34.authenticate(Unknown Source) at weblogic.security.service.WLSJAASAuthenticationServiceWrapper.authenticate(WLSJAASAuthenticationServiceWrapper.java:40) at weblogic.security.service.PrincipalAuthenticator.authenticate(PrincipalAuthenticator.java:338) at weblogic.security.service.CommonSecurityServiceManagerDelegateImpl.doBootAuthorization(CommonSecurityServiceManagerDelegateImpl.
java:930) at weblogic.security.service.CommonSecurityServiceManagerDelegateImpl. initialize(CommonSecurityServiceManagerDelegateImpl.java:1054) at
weblogic.security.service.SecurityServiceManager.initialize(SecurityServiceManager.java:873)
at weblogic.security.SecurityService.start(SecurityService.java:148)
at weblogic.t3.srvr.SubsystemRequest.run(SubsystemRequest.java:64)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:256)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:221)
Caused by: java.net.SocketException: Connection reset
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118)
at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
at oracle.net.ns.DataPacket.send(DataPacket.java:210)
at oracle.net.ns.NetOutputStream.flush(NetOutputStream.java:230)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:312)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket (T4CSocketInputStreamWrapper. java:124) at oracle.jdbc.driver.T4CSocketInputStream Wrapper.read(T4CSocketInputStreamWrapper.java:80)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOSESSKEY(T4CTTIoauthenticate.java:404)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:385)
... 59 more
java.sql.SQLRecoverableException: IO Error: Connection reset

You will also see below error in the log file, but these errors will mislead you

<Jun 19, 2014 2:13:44 PM PDT> <Critical> <Security> <BEA-090402> <Authentication denied: Boot identity not valid; The user name and/or password from the boot identity file (boot.properties) is not valid. The boot identity may have been changed since the boot identity file was created. Please edit and update the boot identity file with the proper values of username and password. The first time the updated boot identity file is used to start the server, these new values are encrypted.>

<Jun 19, 2014 2:13:44 PM PDT> <Critical> <WebLogicServer> <BEA-000386> <Server subsystem failed. Reason: weblogic.security.SecurityInitializationException: Authentication denied: Boot identity not valid; The user name and/or password from the boot identity file (boot.properties) is not valid. The boot identity may have been changed since the boot identity file was created. Please edit and update the boot identity file with the proper values of username and password. The first time the updated boot identity file is used to start the server, these new values are encrypted.
...(CommonSecurityServiceManagerDelegateImpl.java:960) at weblogic.security.service.CommonSecurityServiceManagerDelegateImpl.initialize(CommonSecurityServiceManagerDelegateImpl.java:1054) at weblogic.security.service.SecurityServiceManager.initialize(SecurityServiceManager.java:873)
at weblogic.security.SecurityService.start(SecurityService.java:148)
at weblogic.t3.srvr.SubsystemRequest.run(SubsystemRequest.java:64)
Truncated. see log file for complete stacktrace
Caused By: javax.security.auth.login.LoginException: java.lang.ExceptionInInitializerError
 at com.agile.admin.security.weblogic.WLSLoginModule.login
(WLSLoginModule.java:193) at com.bea.common.security.internal.service.LoginModuleWrapper$1.run(LoginModuleWrapper. java: 110 at java.security.AccessController.doPrivileged(Native Method)
at com.bea.common.security.internal.service.LoginModuleWrapper.login(LoginModuleWrapper .java:106) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)


Findings/troubleshooting

1. When trying to startup the Managed server the weblogic taking more time than expected

2. If you read the highlight error then you will understand what the exact cause for this error is “java.sql.SQLRecoverableException: IO Error: Connection reset”.

3. Found below warning in alert<sid>.log
WARNING: inbound connection timed out (ORA-3136)

4. The userid/password is correct

By looking the above findings it seems that weblogic taking more time and it was not able to connect to the database and timed out with ORA-3136 error. It looks like inbound connection timeout occurred.

Proposed Solution: I have changed the SQLNET.INBOUND_CONNECT_TIMEOUT from default (60 sec) value to 0(indefinite).

After changing the parameter the weblogic Instance comes online without any issues.

It looks like there is bug in Weblogic due to which it is not able to connect to database with in the specified time. Still troubleshooting to find the root cause, if I find anything will try to update in the post.

Regards,
Satishbabu Gunukula, Oracle ACE
http://www.oracleracexpert.com

12 comments:

  1. We have a similar issue occurring at our Clinic. We are vendored through Cerner, an outside company that provides us with the tools to manage our electronic medical record system. This is the error output from our server. Any ideas?
    Thu Oct 02 12:48:03 CDT 2014 INFO com.cerner.system.jdbc.metadriver.MetaDriverManager [com.cerner.system.cache.sensor.polling.PollingSensor-Coding.Extension-thread-1] - [Connection is eligible for retry for data source mhmk1 after a timeout of 2,000ms.]
    java.sql.SQLException: IO Error: Connection reset
    at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:467)
    at oracle.jdbc.driver.PhysicalConnection.(PhysicalConnection.java:546)
    at oracle.jdbc.driver.T4CConnection.(T4CConnection.java:236)
    at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:32)
    at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:521)
    at oracle.jdbc.pool.OracleDataSource.getPhysicalConnection(OracleDataSource.java:280)
    at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:207)
    at oracle.jdbc.pool.OracleConnectionPoolDataSource.getPhysicalConnection(OracleConnectionPoolDataSource.java:139)
    at oracle.jdbc.pool.OracleConnectionPoolDataSource.getPooledConnection(OracleConnectionPoolDataSource.java:88)
    at oracle.jdbc.pool.OracleImplicitConnectionCache.makeCacheConnection(OracleImplicitConnectionCache.java:1598)
    at oracle.jdbc.pool.OracleImplicitConnectionCache.makeOneConnection(OracleImplicitConnectionCache.java:515)
    at oracle.jdbc.pool.OracleImplicitConnectionCache.getCacheConnection(OracleImplicitConnectionCache.java:475)
    at oracle.jdbc.pool.OracleImplicitConnectionCache.getConnection(OracleImplicitConnectionCache.java:357)
    at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:395)
    at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:179)
    at oracle.jdbc.pool.OracleDataSource.getConnection(OracleDataSource.java:157)
    at com.cerner.system.jdbc.metadriver.MetaDriverManager.createRawConnection(MetaDriverManager.java:409)
    at com.cerner.system.jdbc.metadriver.MetaDriverManager.createRaw(MetaDriverManager.java:288)
    at com.cerner.system.jdbc.ConnectionManager.getTransacted(ConnectionManager.java:91)
    at com.cerner.system.jdbc.ConnectionManager.getTransacted(ConnectionManager.java:127)
    at com.cerner.system.code.gladiator.cache.jdbc.BaseGladiatorJDBCInterrogator$TransactedActionImpl.interrogateByLogicalCnt(BaseGladiatorJDBCInterrogator.java:135)

    ReplyDelete
  2. Second part of log files:
    at com.cerner.system.code.gladiator.cache.jdbc.BaseGladiatorJDBCInterrogator$TransactedActionImpl.run(BaseGladiatorJDBCInterrogator.java:99)
    at com.cerner.system.code.gladiator.cache.jdbc.BaseGladiatorJDBCInterrogator$TransactedActionImpl.run(BaseGladiatorJDBCInterrogator.java:82)
    at com.cerner.system.transaction.TransactionManager.runInNewTransaction(TransactionManager.java:292)
    at com.cerner.system.transaction.TransactionManager.doTransactedRetry(TransactionManager.java:249)
    at com.cerner.system.transaction.TransactionManager.doTransactedRetry(TransactionManager.java:171)
    at com.cerner.system.cache.interrogator.jdbc.TransactedActionBaseInterrogator.discover(TransactedActionBaseInterrogator.java:206)
    at com.cerner.system.code.gladiator.cache.CodeSystemInterrogator.discover(CodeSystemInterrogator.java:84)
    at com.cerner.system.cache.sensor.polling.AbstractPollingSensor$InterrogatorProxy.discover(AbstractPollingSensor.java:934)
    at com.cerner.system.cache.sensor.polling.AbstractPollingSensor.poll(AbstractPollingSensor.java:497)
    at com.cerner.system.cache.sensor.polling.PollingSensor$Poller$PollerAction.run(PollingSensor.java:86)
    at com.cerner.system.cache.sensor.polling.PollingSensor$Poller$PollerAction.run(PollingSensor.java:84)
    at java.security.AccessController.doPrivileged(AccessController.java:224)
    at javax.security.auth.Subject.doAs(Subject.java:495)
    at com.cerner.system.cache.sensor.polling.PollingSensor$Poller.run(PollingSensor.java:74)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:453)
    at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:329)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:162)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:110)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:193)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:217)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:898)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:920)
    at java.lang.Thread.run(Thread.java:736)
    Caused by: java.net.SocketException: Connection reset
    at java.net.SocketInputStream.read(SocketInputStream.java:180)
    at oracle.net.ns.Packet.receive(Packet.java:300)
    at oracle.net.ns.NSProtocol.connect(NSProtocol.java:296)
    at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1102)
    at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:320)
    ... 43 more

    ReplyDelete
  3. make sure export /dev/urandom is being used rather than /dev/random. Good article here.

    ReplyDelete
  4. There is no word of condolence who lost their mother.This is painful and world most hardest thing to accept who lost their mother.Though there is no word of sympathy but you can sent condolence message to show your support and empathy.

    ReplyDelete
  5. Tummy without any flab is dream for most of the people,because they didn't know how to burn this flab in sort time,We suggest to join gyms in kolkata where professional trainer trained you to get the shape.

    ReplyDelete
  6. افضل الخدمات الخاصة باعمال نقل العفش مع الفك والتركيب في الطائف تقدمها افضل شركة نقل عفش بالطائف وهي تعتبر من افضل الشركات المتخصصة في اعمال نقل الاثاث بواسطة فريق عمل مميز ومحترف وسيارات نقل عفش حديثة ومجهزة لأعمال شركات نقل الاثاث بالطائف مقفلة ومبطنة من الداخل وستحصل على افضل خدمات شركات نقل العفش بالطائف باحترافية عالية وبالضمان من افضل شركة نقل عفش الطائف المتميزة والمؤهلة

    ReplyDelete