Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

java.sql.SQLRecoverableException: ORA-17002: I/O error: Socket write interrupted, Authentication lapse 27 ms. #181

Open
ayrjegan opened this issue Oct 24, 2024 · 1 comment
Open

java.sql.SQLRecoverableException: ORA-17002: I/O error: Socket write interrupted, Authentication lapse 27 ms. #181

ayrjegan opened this issue Oct 24, 2024 · 1 comment

Comments

@ayrjegan
Copy link

We have upgraded the application with ojdbc6 to ojdbc11 with JDK 17. Getting the below exception, though there is no functional impact.

c3p0 version is 0.9.5.5.
With ojdbc6 we don't see this issue.

[WARNING] Failed to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@1308df03
java.sql.SQLException: Some resources failed to close properly while closing com.mchange.v2.c3p0.impl.NewPooledConnection@1308df03
at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:664)
at com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1114)
at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1139)
at com.mchange.v2.resourcepool.BasicResourcePool.removeResource(BasicResourcePool.java:1596)
at com.mchange.v2.resourcepool.BasicResourcePool.removeResource(BasicResourcePool.java:1566)
at com.mchange.v2.resourcepool.BasicResourcePool.access$300(BasicResourcePool.java:44)
at com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1433)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)

Oct 24, 2024 11:37:54 AM oracle.jdbc.driver.PhysicalConnection connect
INFO: entering args (oracle.jdbc.internal.AbstractConnectionBuilder$1@57a6d228)
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol connect
INFO: traceId=4077498.
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol establishConnection
INFO: Session Attributes:
sdu=8192, tdu=2097152
nt: host=127.0.0.1, port=1521, socketOptions={0=YES, 1=NO, 17=0, 18=false, 2=0, 20=true, 38=TLS, 23=40, 24=50, 40=false, 25=0}
socket=Socket[unconnected]
client profile={oracle.net.encryption_types_client=(), oracle.net.crypto_seed=, oracle.net.authentication_services=(), oracle.net.setFIPSMode=false, oracle.net.kerberos5_mutual_authentication=false, oracle.net.encryption_client=ACCEPTED, oracle.net.crypto_checksum_client=ACCEPTED, oracle.net.crypto_checksum_types_client=()}
connection options=[host=127.0.0.1 port=1521 protocol=TCP service_name=XE addr=(ADDRESS=(PROTOCOL=TCP)(HOST=127.0.0.1)(PORT=1521)) conn_data=(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(PORT=1521)(HOST=127.0.0.1))(CONNECT_DATA=(CID=(PROGRAM=MetaDataConfigProcessor)(HOST=sunil7886)(USER=applicationapp))(SERVICE_NAME=XE))) done=true]
onBreakReset=false, dataEOF=false, negotiatedOptions=0x0, connected=false
TTIINIT enabled=false, TTC cookie enabled=false

Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol configureSessionAttsAno
INFO: traceId=4077498, anoEnabled=true.
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocolNIO handleConnectPacketResponse
INFO: Got Resend, SessionTraceId = 4077498
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocolNIO handleOutboundTimeoutInterrupt
INFO: Connection establishment interrupted externally, exiting.
Oct 24, 2024 11:37:54 AM oracle.jdbc.driver.PhysicalConnection connect
INFO: throwing
java.sql.SQLRecoverableException: ORA-17002: I/O error: Socket read interrupted, Authentication lapse 0 ms.
https://docs.oracle.com/error-help/db/ora-17002/
at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1660)
at oracle.jdbc.driver.T4CConnection.handleLogonInterruptedIOException(T4CConnection.java:1521)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1134)
at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:1206)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:105)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:886)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:693)
at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:175)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:220)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1176)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1163)
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1908)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
Caused by: java.io.IOException: Socket read interrupted, Authentication lapse 0 ms.
at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1655)
... 15 more
Caused by: java.io.InterruptedIOException: Socket read interrupted
at oracle.net.nt.TimeoutSocketChannel.doBlockedRead(TimeoutSocketChannel.java:612)
at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:536)
at oracle.net.ns.NSProtocolNIO.doSocketRead(NSProtocolNIO.java:1224)
at oracle.net.ns.NIOPacket.readNIOPacket(NIOPacket.java:436)
at oracle.net.ns.NSProtocolNIO.negotiateConnection(NSProtocolNIO.java:216)
at oracle.net.ns.NSProtocol.connect(NSProtocol.java:352)
at oracle.jdbc.driver.T4CConnection.connectNetworkSessionProtocol(T4CConnection.java:3419)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1018)
... 13 more

Oct 24, 2024 11:37:54 AM oracle.jdbc.diagnostics.Diagnostic dumpDiagnoseFirstFailure
INFO: properties={LOCALE=en_US, DriverVersion=23.5.0.24.07, java.library.path: =:/opt/cloudhsm/lib:/usr/lib/oracle/11.2/client64/lib/::/usr/lib/oracle/11.2/client64/lib/::/usr/lib/oracle/11.2/client64/lib/:/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib, java.class.path: =/opt/application/current/oracle/schema/current/Tools/sqljava/application-meta-data-config-tool.jar, java.version: =17.0.10}.
[WARNING] Thread[C3P0PooledConnectionPoolManager[identityToken->1hgegd2b61gh95as17psnst|764cba]-HelperThread-#2,5,main] -- caught unexpected Exception while executing posted task.
java.lang.IllegalStateException: Timer already cancelled.
at java.base/java.util.Timer.sched(Timer.java:409)
at java.base/java.util.Timer.schedule(Timer.java:205)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:2003)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)

[WARNING] Failed to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@39a2b2cf
java.sql.SQLException: Some resources failed to close properly while closing com.mchange.v2.c3p0.impl.NewPooledConnection@39a2b2cf
at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:664)
at com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1114)
at com.mchange.v2.resourcepool.BasicResourcePool.destroyResource(BasicResourcePool.java:1139)
at com.mchange.v2.resourcepool.BasicResourcePool.removeResource(BasicResourcePool.java:1596)
at com.mchange.v2.resourcepool.BasicResourcePool.removeResource(BasicResourcePool.java:1566)
at com.mchange.v2.resourcepool.BasicResourcePool.access$300(BasicResourcePool.java:44)
at com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1433)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)

Oct 24, 2024 11:37:54 AM oracle.jdbc.driver.PhysicalConnection connect
INFO: entering args (oracle.jdbc.internal.AbstractConnectionBuilder$1@5ca10dd6)
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol connect
INFO: traceId=6DBECF53.
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol establishConnection
INFO: Session Attributes:
sdu=8192, tdu=2097152
nt: host=127.0.0.1, port=1521, socketOptions={0=YES, 1=NO, 17=0, 18=false, 2=0, 20=true, 38=TLS, 23=40, 24=50, 40=false, 25=0}
socket=null
client profile={oracle.net.encryption_types_client=(), oracle.net.crypto_seed=, oracle.net.authentication_services=(), oracle.net.setFIPSMode=false, oracle.net.kerberos5_mutual_authentication=false, oracle.net.encryption_client=ACCEPTED, oracle.net.crypto_checksum_client=ACCEPTED, oracle.net.crypto_checksum_types_client=()}
connection options=[host=127.0.0.1 port=1521 protocol=TCP service_name=XE addr=(ADDRESS=(PROTOCOL=TCP)(HOST=127.0.0.1)(PORT=1521)) conn_data=(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(PORT=1521)(HOST=127.0.0.1))(CONNECT_DATA=(CID=(PROGRAM=MetaDataConfigProcessor)(HOST=sunil7886)(USER=applicationapp))(SERVICE_NAME=XE))) done=true]
onBreakReset=false, dataEOF=false, negotiatedOptions=0xc41, connected=false
TTIINIT enabled=false, TTC cookie enabled=false

Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol configureSessionAttsAno
INFO: traceId=6DBECF53, anoEnabled=true.
Oct 24, 2024 11:37:55 AM oracle.net.ns.NSProtocolNIO handleConnectPacketResponse
INFO: Got Resend, SessionTraceId = 6DBECF53
Oct 24, 2024 11:37:55 AM oracle.net.ns.NSProtocolNIO handleAcceptPacket
INFO: Connection established. Cleared conn strategy stack
Oct 24, 2024 11:37:55 AM oracle.net.ns.NSProtocolNIO sendMarker
INFO: Sending break marker, SessionTraceId = 6DBECF53
Oct 24, 2024 11:37:55 AM oracle.jdbc.driver.PhysicalConnection connect
INFO: throwing
java.sql.SQLRecoverableException: ORA-17002: I/O error: Socket read interrupted, Authentication lapse 27 ms.
https://docs.oracle.com/error-help/db/ora-17002/
at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1660)
at oracle.jdbc.driver.T4CConnection.handleLogonInterruptedIOException(T4CConnection.java:1521)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1134)
at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:1206)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:105)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:886)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:693)
at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:175)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:220)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1176)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1163)
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1908)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
Caused by: java.io.IOException: Socket read interrupted, Authentication lapse 27 ms.
at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1655)
... 15 more
Caused by: java.io.InterruptedIOException: Socket read interrupted
at oracle.net.nt.TimeoutSocketChannel.doBlockedRead(TimeoutSocketChannel.java:612)
at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:536)
at oracle.net.ns.NSProtocolNIO.doSocketRead(NSProtocolNIO.java:1224)
at oracle.net.ns.NIOPacket.readHeader(NIOPacket.java:272)
at oracle.net.ns.NIOPacket.readPacketFromSocketChannel(NIOPacket.java:205)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:148)
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:121)
at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:111)
at oracle.jdbc.driver.T4CMAREngineNIO.prepareForUnmarshall(T4CMAREngineNIO.java:930)
at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:464)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:945)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:408)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTH(T4CTTIoauthenticate.java:530)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTHWithO5Logon(T4CTTIoauthenticate.java:1712)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTH(T4CTTIoauthenticate.java:1459)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTH(T4CTTIoauthenticate.java:1399)
at oracle.jdbc.driver.T4CConnection.authenticateWithPassword(T4CConnection.java:2050)
at oracle.jdbc.driver.T4CConnection.authenticateUserForLogon(T4CConnection.java:1989)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1090)
... 13 more

Oct 24, 2024 11:37:55 AM oracle.jdbc.diagnostics.Diagnostic dumpDiagnoseFirstFailure
INFO: properties={LOCALE=en_US, DriverVersion=23.5.0.24.07, java.library.path: =:/opt/cloudhsm/lib:/usr/lib/oracle/11.2/client64/lib/::/usr/lib/oracle/11.2/client64/lib/::/usr/lib/oracle/11.2/client64/lib/:/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib, java.class.path: =/opt/application/current/oracle/schema/current/Tools/sqljava/application-meta-data-config-tool.jar, java.version: =17.0.10}.
[WARNING] Thread[C3P0PooledConnectionPoolManager[identityToken->1hgegd2b61gh95as17psnst|5bb51241]-HelperThread-#1,5,main] -- caught unexpected Exception while executing posted task.
java.lang.IllegalStateException: Timer already cancelled.
at java.base/java.util.Timer.sched(Timer.java:409)
at java.base/java.util.Timer.schedule(Timer.java:205)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:2003)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)

Oct 24, 2024 11:37:54 AM oracle.jdbc.driver.PhysicalConnection connect
INFO: entering args (oracle.jdbc.internal.AbstractConnectionBuilder$1@febfa4e)
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol connect
INFO: traceId=32E75EE1.
Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol establishConnection
INFO: Session Attributes:
sdu=8192, tdu=2097152
nt: host=127.0.0.1, port=1521, socketOptions={0=YES, 1=NO, 17=0, 18=false, 2=0, 20=true, 38=TLS, 23=40, 24=50, 40=false, 25=0}
socket=null
client profile={oracle.net.encryption_types_client=(), oracle.net.crypto_seed=, oracle.net.authentication_services=(), oracle.net.setFIPSMode=false, oracle.net.kerberos5_mutual_authentication=false, oracle.net.encryption_client=ACCEPTED, oracle.net.crypto_checksum_client=ACCEPTED, oracle.net.crypto_checksum_types_client=()}
connection options=[host=127.0.0.1 port=1521 protocol=TCP service_name=XE addr=(ADDRESS=(PROTOCOL=TCP)(HOST=127.0.0.1)(PORT=1521)) conn_data=(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(PORT=1521)(HOST=127.0.0.1))(CONNECT_DATA=(CID=(PROGRAM=MetaDataConfigProcessor)(HOST=sunil7886)(USER=applicationapp))(SERVICE_NAME=XE))) done=true]
onBreakReset=false, dataEOF=false, negotiatedOptions=0xc41, connected=false
TTIINIT enabled=false, TTC cookie enabled=false

Oct 24, 2024 11:37:54 AM oracle.net.ns.NSProtocol configureSessionAttsAno
INFO: traceId=32E75EE1, anoEnabled=true.
Oct 24, 2024 11:37:55 AM oracle.net.ns.NSProtocolNIO handleConnectPacketResponse
INFO: Got Resend, SessionTraceId = 32E75EE1
Oct 24, 2024 11:37:55 AM oracle.net.ns.NSProtocolNIO handleAcceptPacket
INFO: Connection established. Cleared conn strategy stack
Oct 24, 2024 11:37:55 AM oracle.net.ns.NSProtocolNIO sendMarker
INFO: Sending break marker, SessionTraceId = 32E75EE1
Oct 24, 2024 11:37:55 AM oracle.jdbc.driver.PhysicalConnection connect
INFO: throwing
java.sql.SQLRecoverableException: ORA-17002: I/O error: Socket write interrupted, Authentication lapse 27 ms.
https://docs.oracle.com/error-help/db/ora-17002/
at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1660)
at oracle.jdbc.driver.T4CConnection.handleLogonInterruptedIOException(T4CConnection.java:1521)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1134)
at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:1206)
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:105)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:886)
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:693)
at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:175)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:220)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1176)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1163)
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1908)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
Caused by: java.io.IOException: Socket write interrupted, Authentication lapse 27 ms.
at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1655)
... 15 more
Caused by: java.io.InterruptedIOException: Socket write interrupted
at oracle.net.nt.TimeoutSocketChannel.doBlockedWrite(TimeoutSocketChannel.java:764)
at oracle.net.nt.TimeoutSocketChannel.write(TimeoutSocketChannel.java:692)
at oracle.net.ns.NIOPacket.writeToSocketChannel(NIOPacket.java:373)
at oracle.net.ns.NIONSDataChannel.writeDataToSocketChannel(NIONSDataChannel.java:215)
at oracle.jdbc.driver.T4CMAREngineNIO.flush(T4CMAREngineNIO.java:886)
at oracle.jdbc.driver.T4CMAREngineNIO.prepareForUnmarshall(T4CMAREngineNIO.java:918)
at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:464)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:945)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:408)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTH(T4CTTIoauthenticate.java:530)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTHWithO5Logon(T4CTTIoauthenticate.java:1712)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTH(T4CTTIoauthenticate.java:1459)
at oracle.jdbc.driver.T4CTTIoauthenticate.doOAUTH(T4CTTIoauthenticate.java:1399)
at oracle.jdbc.driver.T4CConnection.authenticateWithPassword(T4CConnection.java:2050)
at oracle.jdbc.driver.T4CConnection.authenticateUserForLogon(T4CConnection.java:1989)
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1090)
... 13 more

Oct 24, 2024 11:37:55 AM oracle.jdbc.diagnostics.Diagnostic dumpDiagnoseFirstFailure
INFO: properties={LOCALE=en_US, DriverVersion=23.5.0.24.07, java.library.path: =:/opt/cloudhsm/lib:/usr/lib/oracle/11.2/client64/lib/::/usr/lib/oracle/11.2/client64/lib/::/usr/lib/oracle/11.2/client64/lib/:/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib, java.class.path: =/opt/application/current/oracle/schema/current/Tools/sqljava/application-meta-data-config-tool.jar, java.version: =17.0.10}.
[WARNING] Thread[C3P0PooledConnectionPoolManager[identityToken->1hgegd2b61gh95as17psnst|5bb51241]-HelperThread-#2,5,main] -- caught unexpected Exception while executing posted task.
java.lang.IllegalStateException: Timer already cancelled.
at java.base/java.util.Timer.sched(Timer.java:409)
at java.base/java.util.Timer.schedule(Timer.java:205)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:2003)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)

Even after upgrading to c3p0-0.10.1.jar along with mchange-commons-java-0.3.1.jar, still issue is there.

There seems to be similar issues reported like the below:
#127 - #127
#169 - #169
#178 - #178
@swaldman
Copy link
Owner 

[WARNING] Failed to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@39a2b2cf
java.sql.SQLException: Some resources failed to close properly while closing

is not of great concern per se.

c3p0 makes a best effort attempt to close any unclosed PreparedStatement, Statement, or ResultSet objects when a PooledConnection is destroyed. This feels like good hygiene, but ultimately the physical Connection will be destroyed, and then these resources should be cleaned up at the driver level. I'd expect to see more specific log messages about the resources failing to close, however. There's lots of noise in these logs about Connection errors at the driver level, but no information about the c3p0-level close Exception. I'd expect these.

In general it's probably worth understanding why there are so many apparent driver-level Exceptions.

A particularly weird bit in these logs are messages like java.lang.IllegalStateException: Timer already cancelled The lifecycle of the timer c3p0 DataSources rely upon should be the life cycle of the pool-backed DataSource, unless your application is reconfiguring the DataSource (which forces a shutdown and reconstruction of pools, including their timers). Reconfiguring the DataSources is expensive, therefore. An application shouldn't be changing DataSource properties on the fly very much.

Might your application be reseting DataSource properties, or calling close() on c3p0 DataSources while clients might still be outstanding? (c3p0 DataSources should usually only be closed on application shutdown.)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@swaldman @ayrjegan