Metrics vertx_pool_queue_pending doesn't decrease after connection loss#1530
Merged
Conversation
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 <tsegismont@gmail.com>
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 io.vertx.testing.unit@5.0.1-SNAPSHOT/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 io.vertx.testing.unit@5.0.1-SNAPSHOT/io.vertx.ext.unit.junit.VertxUnitRunner.invokeTestMethod(VertxUnitRunner.java:95)
2025-06-18T08:12:53.8436414Z at io.vertx.testing.unit@5.0.1-SNAPSHOT/io.vertx.ext.unit.junit.VertxUnitRunner.lambda$invokeExplosively$0(VertxUnitRunner.java:114)
2025-06-18T08:12:53.8437841Z at io.vertx.testing.unit@5.0.1-SNAPSHOT/io.vertx.ext.unit.impl.TestContextImpl.run(TestContextImpl.java:90)
2025-06-18T08:12:53.8439166Z at io.vertx.testing.unit@5.0.1-SNAPSHOT/io.vertx.ext.unit.junit.VertxUnitRunner.invokeExplosively(VertxUnitRunner.java:130)
2025-06-18T08:12:53.8440505Z at io.vertx.testing.unit@5.0.1-SNAPSHOT/io.vertx.ext.unit.junit.VertxUnitRunner$1.evaluate(VertxUnitRunner.java:84)
2025-06-18T08:12:53.8444504Z at io.vertx.testing.unit@5.0.1-SNAPSHOT/io.vertx.ext.unit.junit.VertxUnitRunner$2.evaluate(VertxUnitRunner.java:196)
2025-06-18T08:12:53.8446923Z at io.vertx.testing.unit@5.0.1-SNAPSHOT/io.vertx.ext.unit.junit.VertxUnitRunner$3.evaluate(VertxUnitRunner.java:211)
2025-06-18T08:12:53.8448011Z at junit@4.13.1/org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
2025-06-18T08:12:53.8449021Z at junit@4.13.1/org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
2025-06-18T08:12:53.8449969Z at junit@4.13.1/org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
2025-06-18T08:12:53.8451715Z at junit@4.13.1/org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
2025-06-18T08:12:53.8453107Z at junit@4.13.1/org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
2025-06-18T08:12:53.8453868Z at junit@4.13.1/org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
2025-06-18T08:12:53.8454674Z at junit@4.13.1/org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
2025-06-18T08:12:53.8455502Z at junit@4.13.1/org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
2025-06-18T08:12:53.8456341Z at junit@4.13.1/org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
2025-06-18T08:12:53.8457153Z at junit@4.13.1/org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
2025-06-18T08:12:53.8457997Z at junit@4.13.1/org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
2025-06-18T08:12:53.8458761Z at junit@4.13.1/org.junit.rules.RunRules.evaluate(RunRules.java:20)
2025-06-18T08:12:53.8459749Z at junit@4.13.1/org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
2025-06-18T08:12:53.8460722Z at junit@4.13.1/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 com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.driver.T4CConnection.handleLogonNetException(T4CConnection.java:1615)
2025-06-18T08:13:13.5098226Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:1137)
2025-06-18T08:13:13.5099436Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:1178)
2025-06-18T08:13:13.5100955Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:105)
2025-06-18T08:13:13.5102218Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:886)
2025-06-18T08:13:13.5103600Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.datasource.impl.OracleDataSource.getPhysicalConnection(OracleDataSource.java:707)
2025-06-18T08:13:13.5105399Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.datasource.impl.OracleDataSource.getConnection(OracleDataSource.java:381)
2025-06-18T08:13:13.5106849Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.datasource.impl.OracleDataSource.getConnectionInternal(OracleDataSource.java:2206)
2025-06-18T08:13:13.5108381Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.datasource.impl.OracleDataSource$1.build(OracleDataSource.java:1915)
2025-06-18T08:13:13.5109766Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.datasource.impl.OracleDataSource$1.build(OracleDataSource.java:1849)
2025-06-18T08:13:13.5111178Z at io.vertx.sql.client.oracle@5.0.1-SNAPSHOT/io.vertx.oracleclient.impl.OracleConnectionFactory.lambda$connect$0(OracleConnectionFactory.java:68)
2025-06-18T08:13:13.5112048Z at io.vertx.sql.client.oracle@5.0.1-SNAPSHOT/io.vertx.oracleclient.impl.Helper$SQLBlockingCodeHandler.call(Helper.java:306)
2025-06-18T08:13:13.5112745Z at io.vertx.core@5.0.1-SNAPSHOT/io.vertx.core.impl.ExecuteBlocking$1.execute(ExecuteBlocking.java:36)
2025-06-18T08:13:13.5113324Z at io.vertx.core@5.0.1-SNAPSHOT/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 io.netty.common@4.2.2.Final/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 com.oracle.database.jdbc@23.4.0.24.05/oracle.net.ns.NSProtocolNIO.createRefusePacketException(NSProtocolNIO.java:915)
2025-06-18T08:13:13.5121187Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.net.ns.NSProtocolNIO.handleConnectPacketResponse(NSProtocolNIO.java:461)
2025-06-18T08:13:13.5122401Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.net.ns.NSProtocolNIO.negotiateConnection(NSProtocolNIO.java:269)
2025-06-18T08:13:13.5123712Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.net.ns.NSProtocol.connect(NSProtocol.java:352)
2025-06-18T08:13:13.5124855Z at com.oracle.database.jdbc@23.4.0.24.05/oracle.jdbc.driver.T4CConnection.connectNetworkSessionProtocol(T4CConnection.java:3411)
2025-06-18T08:13:13.5126233Z at com.oracle.database.jdbc@23.4.0.24.05/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 <tsegismont@gmail.com>
Fails on Oracle Signed-off-by: Thomas Segismont <tsegismont@gmail.com>
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
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