Metrics vertx_pool_queue_pending doesn't decrease after connection loss #1530
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Backported from eclipse-vertx#1529 See eclipse-vertx#1494 SqlConnectionPool must invoke dequeueMetric when a connection fails to be acquired Signed-off-by: Thomas Segismont <[email protected]>
Fails on Oracle 2025-06-18T08:12:53.8427877Z [ERROR] tests.oracleclient.tck.OracleMetricsTest.testConnectionLost -- Time elapsed: 20.07 s <<< ERROR! 2025-06-18T08:12:53.8428800Z java.util.concurrent.TimeoutException: Timed out 2025-06-18T08:12:53.8429660Z at [email protected]/io.vertx.ext.unit.impl.CompletionImpl.await(CompletionImpl.java:73) 2025-06-18T08:12:53.8431163Z at io.vertx.tests.sql.client/io.vertx.tests.sqlclient.tck.MetricsTestBase.testConnectionLost(MetricsTestBase.java:232) 2025-06-18T08:12:53.8432547Z at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) 2025-06-18T08:12:53.8433884Z at java.base/java.lang.reflect.Method.invoke(Method.java:580) 2025-06-18T08:12:53.8434931Z at [email protected]/io.vertx.ext.unit.junit.VertxUnitRunner.invokeTestMethod(VertxUnitRunner.java:95) 2025-06-18T08:12:53.8436414Z at [email protected]/io.vertx.ext.unit.junit.VertxUnitRunner.lambda$invokeExplosively$0(VertxUnitRunner.java:114) 2025-06-18T08:12:53.8437841Z at [email protected]/io.vertx.ext.unit.impl.TestContextImpl.run(TestContextImpl.java:90) 2025-06-18T08:12:53.8439166Z at [email protected]/io.vertx.ext.unit.junit.VertxUnitRunner.invokeExplosively(VertxUnitRunner.java:130) 2025-06-18T08:12:53.8440505Z at [email protected]/io.vertx.ext.unit.junit.VertxUnitRunner$1.evaluate(VertxUnitRunner.java:84) 2025-06-18T08:12:53.8444504Z at [email protected]/io.vertx.ext.unit.junit.VertxUnitRunner$2.evaluate(VertxUnitRunner.java:196) 2025-06-18T08:12:53.8446923Z at [email protected]/io.vertx.ext.unit.junit.VertxUnitRunner$3.evaluate(VertxUnitRunner.java:211) 2025-06-18T08:12:53.8448011Z at [email protected]/org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) 2025-06-18T08:12:53.8449021Z at [email protected]/org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100) 2025-06-18T08:12:53.8449969Z at [email protected]/org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) 2025-06-18T08:12:53.8451715Z at [email protected]/org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103) 2025-06-18T08:12:53.8453107Z at [email protected]/org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63) 2025-06-18T08:12:53.8453868Z at [email protected]/org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) 2025-06-18T08:12:53.8454674Z at [email protected]/org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) 2025-06-18T08:12:53.8455502Z at [email protected]/org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) 2025-06-18T08:12:53.8456341Z at [email protected]/org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) 2025-06-18T08:12:53.8457153Z at [email protected]/org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) 2025-06-18T08:12:53.8457997Z at [email protected]/org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54) 2025-06-18T08:12:53.8458761Z at [email protected]/org.junit.rules.RunRules.evaluate(RunRules.java:20) 2025-06-18T08:12:53.8459749Z at [email protected]/org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) 2025-06-18T08:12:53.8460722Z at [email protected]/org.junit.runners.ParentRunner.run(ParentRunner.java:413) 2025-06-18T08:12:53.8461598Z at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:316) 2025-06-18T08:12:53.8462621Z at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:240) 2025-06-18T08:12:53.8463694Z at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:214) 2025-06-18T08:12:53.8464613Z at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:155) 2025-06-18T08:12:53.8465193Z at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385) 2025-06-18T08:12:53.8465752Z at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162) 2025-06-18T08:12:53.8466255Z at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507) 2025-06-18T08:12:53.8466754Z at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495) 2025-06-18T08:12:53.8467047Z 2025-06-18T08:13:13.5057371Z Jun 18, 2025 8:13:13 AM oracle.jdbc.driver.PhysicalConnection connect 2025-06-18T08:13:13.5065518Z INFO: entering args (oracle.jdbc.datasource.impl.OracleDataSource$1@6a8b05c5) 2025-06-18T08:13:13.5067705Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocol connect 2025-06-18T08:13:13.5068225Z INFO: traceId=1E1826C1. 2025-06-18T08:13:13.5068725Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocol establishConnection 2025-06-18T08:13:13.5069809Z INFO: Session Attributes: 2025-06-18T08:13:13.5070161Z sdu=8192, tdu=2097152 2025-06-18T08:13:13.5071040Z 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} 2025-06-18T08:13:13.5071793Z socket=null 2025-06-18T08:13:13.5073880Z 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=()} 2025-06-18T08:13:13.5076223Z onBreakReset=false, dataEOF=false, negotiatedOptions=0x0, connected=false 2025-06-18T08:13:13.5076905Z TTIINIT enabled=false, TTC cookie enabled=false 2025-06-18T08:13:13.5077253Z 2025-06-18T08:13:13.5077540Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocol configureSessionAttsAno 2025-06-18T08:13:13.5078150Z INFO: traceId=1E1826C1, anoEnabled=true. 2025-06-18T08:13:13.5078754Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocolNIO handleConnectPacketResponse 2025-06-18T08:13:13.5079401Z INFO: Got Refused, SessionTraceId = 1E1826C1 2025-06-18T08:13:13.5080067Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocolNIO establishConnectionAfterRefusePacket 2025-06-18T08:13:13.5081022Z INFO: Outbound interrupt timer cancelled null 2025-06-18T08:13:13.5081604Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocol establishConnection 2025-06-18T08:13:13.5082150Z INFO: Session Attributes: 2025-06-18T08:13:13.5082504Z sdu=8192, tdu=2097152 2025-06-18T08:13:13.5083213Z 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} 2025-06-18T08:13:13.5083954Z socket=null 2025-06-18T08:13:13.5085828Z 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=()} 2025-06-18T08:13:13.5088048Z onBreakReset=false, dataEOF=false, negotiatedOptions=0x0, connected=false 2025-06-18T08:13:13.5088717Z TTIINIT enabled=false, TTC cookie enabled=false 2025-06-18T08:13:13.5089087Z 2025-06-18T08:13:13.5089412Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocolNIO handleConnectPacketResponse 2025-06-18T08:13:13.5090323Z INFO: Got Refused, SessionTraceId = 1E1826C1 2025-06-18T08:13:13.5091316Z Jun 18, 2025 8:13:13 AM oracle.net.ns.NSProtocolNIO establishConnectionAfterRefusePacket 2025-06-18T08:13:13.5092028Z INFO: Outbound interrupt timer cancelled null 2025-06-18T08:13:13.5092622Z Jun 18, 2025 8:13:13 AM oracle.jdbc.driver.PhysicalConnection connect 2025-06-18T08:13:13.5093155Z INFO: throwing 2025-06-18T08:13:13.5094410Z java.sql.SQLRecoverableException: ORA-12514: Cannot connect to database. Service invalidDatabase is not registered with the listener at host localhost port 32769. (CONNECTION_ID=mow8621wRDKG5TmVDKKOKA==) 2025-06-18T08:13:13.5095939Z https://docs.oracle.com/error-help/db/ora-12514/ 2025-06-18T08:13:13.5096950Z at [email protected]/oracle.jdbc.driver.T4CConnection.handleLogonNetException(T4CConnection.java:1615) 2025-06-18T08:13:13.5098226Z at [email protected]/oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1137) 2025-06-18T08:13:13.5099436Z at [email protected]/oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:1178) 2025-06-18T08:13:13.5100955Z at [email protected]/oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:105) 2025-06-18T08:13:13.5102218Z at [email protected]/oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:886) 2025-06-18T08:13:13.5103600Z at [email protected]/oracle.jdbc.datasource.impl.OracleDataSource.getPhysicalConnection(OracleDataSource.java:707) 2025-06-18T08:13:13.5105399Z at [email protected]/oracle.jdbc.datasource.impl.OracleDataSource.getConnection(OracleDataSource.java:381) 2025-06-18T08:13:13.5106849Z at [email protected]/oracle.jdbc.datasource.impl.OracleDataSource.getConnectionInternal(OracleDataSource.java:2206) 2025-06-18T08:13:13.5108381Z at [email protected]/oracle.jdbc.datasource.impl.OracleDataSource$1.build(OracleDataSource.java:1915) 2025-06-18T08:13:13.5109766Z at [email protected]/oracle.jdbc.datasource.impl.OracleDataSource$1.build(OracleDataSource.java:1849) 2025-06-18T08:13:13.5111178Z at [email protected]/io.vertx.oracleclient.impl.OracleConnectionFactory.lambda$connect$0(OracleConnectionFactory.java:68) 2025-06-18T08:13:13.5112048Z at [email protected]/io.vertx.oracleclient.impl.Helper$SQLBlockingCodeHandler.call(Helper.java:306) 2025-06-18T08:13:13.5112745Z at [email protected]/io.vertx.core.impl.ExecuteBlocking$1.execute(ExecuteBlocking.java:36) 2025-06-18T08:13:13.5113324Z at [email protected]/io.vertx.core.impl.WorkerTask.run(WorkerTask.java:57) 2025-06-18T08:13:13.5113895Z at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) 2025-06-18T08:13:13.5114494Z at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) 2025-06-18T08:13:13.5115175Z at [email protected]/io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 2025-06-18T08:13:13.5115711Z at java.base/java.lang.Thread.run(Thread.java:1583) 2025-06-18T08:13:13.5116495Z Caused by: oracle.net.ns.NetException: ORA-12514: Cannot connect to database. Service invalidDatabase is not registered with the listener at host localhost port 32769. (CONNECTION_ID=mow8621wRDKG5TmVDKKOKA==) 2025-06-18T08:13:13.5117693Z https://docs.oracle.com/error-help/db/ora-12514/ 2025-06-18T08:13:13.5119748Z at [email protected]/oracle.net.ns.NSProtocolNIO.createRefusePacketException(NSProtocolNIO.java:915) 2025-06-18T08:13:13.5121187Z at [email protected]/oracle.net.ns.NSProtocolNIO.handleConnectPacketResponse(NSProtocolNIO.java:461) 2025-06-18T08:13:13.5122401Z at [email protected]/oracle.net.ns.NSProtocolNIO.negotiateConnection(NSProtocolNIO.java:269) 2025-06-18T08:13:13.5123712Z at [email protected]/oracle.net.ns.NSProtocol.connect(NSProtocol.java:352) 2025-06-18T08:13:13.5124855Z at [email protected]/oracle.jdbc.driver.T4CConnection.connectNetworkSessionProtocol(T4CConnection.java:3411) 2025-06-18T08:13:13.5126233Z at [email protected]/oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1016) 2025-06-18T08:13:13.5126994Z ... 16 more 2025-06-18T08:13:13.5127176Z 2025-06-18T08:13:13.5127531Z Jun 18, 2025 8:13:13 AM oracle.jdbc.diagnostics.Diagnostic dumpDiagnoseFirstFailure 2025-06-18T08:13:13.5128911Z INFO: properties={LOCALE=en, DriverVersion=23.4.0.24.05, java.library.path: =/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib, java.class.path: =, java.version: =21.0.7}. 2025-06-18T08:13:15.6622033Z [ORACLE] 2025-06-18T08:13:15.077401+00:00 2025-06-18T08:13:15.6623347Z [ORACLE] TABLE SYS.WRP$_REPORTS: ADDED AUTOLIST FRAGMENT SYS_P422 (3) VALUES (( 1467203046, TO_DATE(' 2025-06-16 00:00:00', 'syyyy-mm-dd hh24:mi:ss', 'nls_calendar=gregorian') )) 2025-06-18T08:13:15.6625132Z [ORACLE] TABLE SYS.WRP$_REPORTS_DETAILS: ADDED AUTOLIST FRAGMENT SYS_P423 (3) VALUES (( 1467203046, TO_DATE(' 2025-06-16 00:00:00', 'syyyy-mm-dd hh24:mi:ss', 'nls_calendar=gregorian') )) 2025-06-18T08:13:15.6626932Z [ORACLE] TABLE SYS.WRP$_REPORTS_TIME_BANDS: ADDED AUTOLIST FRAGMENT SYS_P426 (3) VALUES (( 1467203046, TO_DATE(' 2025-06-16 00:00:00', 'syyyy-mm-dd hh24:mi:ss', 'nls_calendar=gregorian') )) 2025-06-18T08:13:21.8199194Z [ERROR] Errors: 2025-06-18T08:13:21.8201259Z [ERROR] OracleMetricsTest>MetricsTestBase.testConnectionLost:232 » Timeout Timed out 2025-06-18T08:13:21.8202285Z [ERROR] Tests run: 262, Failures: 0, Errors: 1, Skipped: 21 Signed-off-by: Thomas Segismont <[email protected]>
Fails on Oracle Signed-off-by: Thomas Segismont <[email protected]>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Backported from #1529