Open
Description
This intermittent failures happens in both scheduled 4.x and master builds. This seems to indicate Vert.x pooling of connections (in v5) is not the cause of the issue.
The error looks like:
2024-10-28T05:05:13.7614199Z [ERROR] io.vertx.oracleclient.test.tck.OracleConnectionTest.testConnectNoLeak -- Time elapsed: 1.120 s <<< ERROR!
2024-10-28T05:05:13.7615768Z io.vertx.oracleclient.OracleException:
2024-10-28T05:05:13.7618122Z ORA-12516: Cannot connect to database. Listener at host localhost port 32769 does not have a protocol handler for TCP ready or registered for service FREEPDB1. (CONNECTION_ID=uYQ6BIcUQIuXB8PS8TuipA==)
2024-10-28T05:05:13.7622685Z https://docs.oracle.com/error-help/db/ora-12516/
Its is preceded by several occurrences of this error:
2024-10-21T04:09:40.6228654Z Running io.vertx.oracleclient.test.tck.OracleConnectionTest
2024-10-21T04:09:50.8631843Z Oct 21, 2024 4:09:50 AM oracle.jdbc.driver.PhysicalConnection connect
2024-10-21T04:09:50.8633822Z INFO: entering args (oracle.jdbc.datasource.impl.OracleDataSource$1@4deb2d65)
2024-10-21T04:09:50.8635133Z Oct 21, 2024 4:09:50 AM oracle.net.ns.NSProtocol connect
2024-10-21T04:09:50.8636295Z INFO: traceId=68A3522.
2024-10-21T04:09:50.8689778Z Oct 21, 2024 4:09:50 AM oracle.net.ns.NSProtocol establishConnection
2024-10-21T04:09:50.8690865Z INFO: Session Attributes:
2024-10-21T04:09:50.8691540Z sdu=8192, tdu=2097152
2024-10-21T04:09:50.8692988Z nt: host=localhost, port=32769, socketOptions={0=YES, 1=NO, 17=0, 18=false, 2=0, 20=true, 38=TLS, 23=40, 24=50, 40=false, 25=0}
2024-10-21T04:09:50.8694438Z socket=Socket[unconnected]
2024-10-21T04:09:50.8697331Z 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=()}
2024-10-21T04:09:50.8703566Z connection options=[host=localhost port=32769 protocol=TCP service_name=FREEPDB1 addr=(ADDRESS=(PROTOCOL=TCP)(HOST=localhost)(PORT=32769)) conn_data=(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(PORT=32769)(HOST=127.0.0.1)(HOSTNAME=localhost))(CONNECT_DATA=(CID=(PROGRAM=ForkedBooter)(HOST=fv-az1198-739)(USER=runner))(SERVICE_NAME=FREEPDB1))) done=true]
2024-10-21T04:09:50.8706788Z onBreakReset=false, dataEOF=false, negotiatedOptions=0x0, connected=false
2024-10-21T04:09:50.8708103Z TTIINIT enabled=false, TTC cookie enabled=false
2024-10-21T04:09:50.8708718Z
2024-10-21T04:09:50.8709357Z Oct 21, 2024 4:09:50 AM oracle.net.ns.NSProtocol configureSessionAttsAno
2024-10-21T04:09:50.8710483Z INFO: traceId=68A3522, anoEnabled=true.
2024-10-21T04:09:50.8711692Z Oct 21, 2024 4:09:50 AM oracle.net.ns.NSProtocolNIO handleOutboundTimeoutInterrupt
2024-10-21T04:09:50.8712913Z INFO: Connection establishment interrupted externally, exiting.
2024-10-21T04:09:50.8714170Z Oct 21, 2024 4:09:50 AM oracle.jdbc.driver.PhysicalConnection connect
2024-10-21T04:09:50.8715294Z INFO: throwing
2024-10-21T04:09:50.8748965Z java.sql.SQLRecoverableException: ORA-17002: I/O error: Socket read interrupted, Authentication lapse 0 ms.
2024-10-21T04:09:50.8750658Z https://docs.oracle.com/error-help/db/ora-17002/
2024-10-21T04:09:50.8751926Z at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1658)
2024-10-21T04:09:50.8754102Z at oracle.jdbc.driver.T4CConnection.handleLogonInterruptedIOException(T4CConnection.java:1519)
2024-10-21T04:09:50.8755930Z at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1132)
2024-10-21T04:09:50.8801493Z at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:1178)
2024-10-21T04:09:50.8803469Z at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:105)
2024-10-21T04:09:50.8804939Z at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:886)
2024-10-21T04:09:50.8806452Z at oracle.jdbc.datasource.impl.OracleDataSource.getPhysicalConnection(OracleDataSource.java:707)
2024-10-21T04:09:50.8808669Z at oracle.jdbc.datasource.impl.OracleDataSource.getConnection(OracleDataSource.java:381)
2024-10-21T04:09:50.8931354Z at oracle.jdbc.datasource.impl.OracleDataSource.getConnectionInternal(OracleDataSource.java:2206)
2024-10-21T04:09:50.8933127Z at oracle.jdbc.datasource.impl.OracleDataSource$1.build(OracleDataSource.java:1915)
2024-10-21T04:09:50.8934767Z at oracle.jdbc.datasource.impl.OracleDataSource$1.build(OracleDataSource.java:1849)
2024-10-21T04:09:50.8936525Z at io.vertx.oracleclient.impl.OracleConnectionFactory.lambda$connect$0(OracleConnectionFactory.java:75)
2024-10-21T04:09:50.8938239Z at io.vertx.oracleclient.impl.Helper$SQLBlockingCodeHandler.handle(Helper.java:306)
2024-10-21T04:09:50.9213845Z at io.vertx.oracleclient.impl.Helper$SQLBlockingCodeHandler.handle(Helper.java:298)
2024-10-21T04:09:50.9291664Z at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$4(ContextImpl.java:199)
2024-10-21T04:09:50.9293145Z at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:270)
2024-10-21T04:09:50.9294479Z at io.vertx.core.impl.ContextImpl$1.execute(ContextImpl.java:215)
2024-10-21T04:09:50.9295525Z at io.vertx.core.impl.WorkerTask.run(WorkerTask.java:56)
2024-10-21T04:09:50.9296873Z at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2024-10-21T04:09:50.9298617Z at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2024-10-21T04:09:50.9300167Z at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2024-10-21T04:09:50.9301452Z at java.base/java.lang.Thread.run(Thread.java:840)
2024-10-21T04:09:50.9302683Z Caused by: java.io.IOException: Socket read interrupted, Authentication lapse 0 ms.
2024-10-21T04:09:50.9304079Z at oracle.jdbc.driver.T4CConnection.handleLogonIOException(T4CConnection.java:1653)
2024-10-21T04:09:50.9305188Z ... 21 more
2024-10-21T04:09:50.9306395Z Caused by: java.io.InterruptedIOException: Socket read interrupted
2024-10-21T04:09:50.9307753Z at oracle.net.nt.TimeoutSocketChannel.doBlockedRead(TimeoutSocketChannel.java:612)
2024-10-21T04:09:50.9309117Z at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:536)
2024-10-21T04:09:50.9310479Z at oracle.net.ns.NSProtocolNIO.doSocketRead(NSProtocolNIO.java:1224)
2024-10-21T04:09:50.9311656Z at oracle.net.ns.NIOPacket.readNIOPacket(NIOPacket.java:436)
2024-10-21T04:09:50.9312849Z at oracle.net.ns.NSProtocolNIO.negotiateConnection(NSProtocolNIO.java:216)
2024-10-21T04:09:50.9314156Z at oracle.net.ns.NSProtocol.connect(NSProtocol.java:352)
2024-10-21T04:09:50.9315484Z at oracle.jdbc.driver.T4CConnection.connectNetworkSessionProtocol(T4CConnection.java:3411)
2024-10-21T04:09:50.9317029Z at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1016)
2024-10-21T04:09:50.9318048Z ... 19 more
2024-10-21T04:09:50.9318320Z