Comments (9)
xsalefter
commented on September 23, 2024
Copy of gist for travis profile:
2022-11-16T10:17:17.7499862Z 2022-11-16T10:17:17.748+0000 [main] INFO KillbillTestSuite - *** Starting test org.killbill.billing.util.audit.dao.TestDefaultAuditDao:testRetrieveAuditsViaHistory
2022-11-16T10:17:17.7500898Z 2022-11-16T10:17:17.748+0000 [main] INFO KillbillTestSuite - ***************************************************************************************************
2022-11-16T10:17:17.7501628Z 2022-11-16T10:17:17.748+0000 [main] INFO org.killbill.queue.DBBackedQueue - DBBackedQueue-bus_events Initialized mode=STICKY_POLLING
2022-11-16T10:17:17.7502457Z 2022-11-16T10:17:17.748+0000 [main] INFO org.killbill.queue.DefaultReaper - BusReaper: Starting... reapThresholdMillis=600000, schedulePeriodMillis=180000
2022-11-16T10:17:17.7503315Z 2022-11-16T10:17:17.748+0000 [main] INFO org.killbill.queue.DefaultQueueLifecycle - bus_events: Starting...
2022-11-16T10:17:17.7504174Z 2022-11-16T10:17:17.748+0000 [bus_events-lifecycle-completion-th-1] INFO org.killbill.queue.DefaultQueueLifecycle - bus_events: Completion thread bus_events-lifecycle-completion-th-1 [461] starting
2022-11-16T10:17:17.7505113Z 2022-11-16T10:17:17.748+0000 [bus_events-lifecycle-completion-th-2] INFO org.killbill.queue.DefaultQueueLifecycle - bus_events: Completion thread bus_events-lifecycle-completion-th-2 [462] starting
2022-11-16T10:17:17.7506026Z 2022-11-16T10:17:17.749+0000 [bus_events-lifecycle-dispatcher-th-1] INFO org.killbill.queue.DefaultQueueLifecycle - bus_events: Dispatching thread bus_events-lifecycle-dispatcher-th-1 [463] starting
2022-11-16T10:17:17.9729309Z 2022-11-16T10:17:17.953+0000 [bus_events-th] INFO org.killbill.billing.api.TestApiListener - Got TagDefinitionInternalEvent event DefaultUserTagDefinitionCreationEvent{tagDefinition=DefaultTagDefinition{name='71e6d', description='f4793', controlTag=false, applicableObjectTypes=[ACCOUNT]}, tagDefinitionId=2795adc5-35cd-46f3-8342-eb3c470aa61c}
2022-11-16T10:17:18.1731161Z 2022-11-16T10:17:18.152+0000 [bus_events-th] INFO org.killbill.billing.api.TestApiListener - Got TagInternalEvent event DefaultUserTagCreationEvent{objectId=fca659b9-b0f3-4997-8990-a8e9a2d970bd, tagId=45156ab2-633f-46b1-8d44-5e1699b2fa59, objectType=ACCOUNT, tagDefinition=DefaultTagDefinition{name='71e6d', description='f4793', controlTag=false, applicableObjectTypes=[ACCOUNT]}}
2022-11-16T10:17:48.2607080Z 2022-11-16T10:17:48.256+0000 [main] ERROR jdbc.audit - null. DataSource.getConnection()
2022-11-16T10:17:48.2607740Z java.sql.SQLException: Login timeout
2022-11-16T10:17:48.2608333Z at org.h2.jdbcx.JdbcConnectionPool.getConnection(JdbcConnectionPool.java:216)
2022-11-16T10:17:48.2608976Z at net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy.getConnection(DataSourceSpy.java:147)
2022-11-16T10:17:48.2659122Z at org.killbill.billing.DBTestingHelper$RetryableDataSource.getConnection(DBTestingHelper.java:130)
2022-11-16T10:17:48.2659663Z at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:40)
2022-11-16T10:17:48.2660094Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:230)
2022-11-16T10:17:48.2660374Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:227)
2022-11-16T10:17:48.2660773Z at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:35)
2022-11-16T10:17:48.2661166Z at org.skife.jdbi.v2.DBI.open(DBI.java:227)
2022-11-16T10:17:48.2661456Z at org.skife.jdbi.v2.DBI.open(DBI.java:219)
2022-11-16T10:17:48.2661842Z at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.getHandle(OnDemandHandleDing.java:42)
2022-11-16T10:17:48.2662316Z at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.retain(OnDemandHandleDing.java:50)
2022-11-16T10:17:48.2662744Z at org.skife.jdbi.v2.sqlobject.SqlObject.invoke(SqlObject.java:177)
2022-11-16T10:17:48.2663202Z at org.skife.jdbi.v2.sqlobject.SqlObjectInterceptor.intercept(SqlObjectInterceptor.java:44)
2022-11-16T10:17:48.2663820Z at org.killbill.billing.util.dao.NonEntitySqlDao$ByteBuddy$1yDc6aB2.getHistoryRecordIdIdMappingsForTablesWithoutAccountRecordId(Unknown Source)
2022-11-16T10:17:48.2664470Z at org.killbill.billing.util.audit.dao.DefaultAuditDao.lambda$buildAuditLogsFromModelDao$0(DefaultAuditDao.java:120)
2022-11-16T10:17:48.2664964Z at org.killbill.commons.utils.collect.Iterators$1.transform(Iterators.java:79)
2022-11-16T10:17:48.2665685Z at org.killbill.commons.utils.collect.TransformedIterator.next(TransformedIterator.java:40)
2022-11-16T10:17:48.2666197Z at org.killbill.commons.utils.collect.Iterators.toUnmodifiableList(Iterators.java:96)
2022-11-16T10:17:48.2666722Z at org.killbill.billing.util.audit.DefaultAccountAuditLogs.<init>(DefaultAccountAuditLogs.java:49)
2022-11-16T10:17:48.2667324Z at org.killbill.billing.util.audit.dao.DefaultAuditDao.getAuditLogsForAccountRecordId(DefaultAuditDao.java:81)
2022-11-16T10:17:48.2668112Z at org.killbill.billing.util.audit.dao.TestDefaultAuditDao.testRetrieveAuditsViaHistory(TestDefaultAuditDao.java:69)
2022-11-16T10:17:48.2668673Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2022-11-16T10:17:48.2669173Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
2022-11-16T10:17:48.2669719Z at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2022-11-16T10:17:48.2670178Z at java.base/java.lang.reflect.Method.invoke(Method.java:568)
2022-11-16T10:17:48.2670603Z at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
2022-11-16T10:17:48.2671098Z at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:238)
2022-11-16T10:17:48.2671570Z at org.killbill.billing.GuicyKillbillTestSuite.run(GuicyKillbillTestSuite.java:208)
2022-11-16T10:17:48.2672060Z at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:252)
2022-11-16T10:17:48.2672517Z at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:595)
2022-11-16T10:17:48.2672931Z at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
2022-11-16T10:17:48.2673351Z at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
2022-11-16T10:17:48.2673771Z at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
2022-11-16T10:17:48.2674204Z at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
2022-11-16T10:17:48.2674665Z at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
2022-11-16T10:17:48.2675103Z at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
2022-11-16T10:17:48.2675472Z at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
2022-11-16T10:17:48.2675812Z at org.testng.TestRunner.privateRun(TestRunner.java:764)
2022-11-16T10:17:48.2676140Z at org.testng.TestRunner.run(TestRunner.java:585)
2022-11-16T10:17:48.2676454Z at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
2022-11-16T10:17:48.2676804Z at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
2022-11-16T10:17:48.2677165Z at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
2022-11-16T10:17:48.2677483Z at org.testng.SuiteRunner.run(SuiteRunner.java:286)
2022-11-16T10:17:48.2677836Z at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
2022-11-16T10:17:48.2678219Z at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
2022-11-16T10:17:48.2678573Z at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
2022-11-16T10:17:48.2678922Z at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
2022-11-16T10:17:48.2679235Z at org.testng.TestNG.runSuites(TestNG.java:1069)
2022-11-16T10:17:48.2679523Z at org.testng.TestNG.run(TestNG.java:1037)
2022-11-16T10:17:48.2679886Z at org.apache.maven.surefire.testng.TestNGExecutor.run(TestNGExecutor.java:151)
2022-11-16T10:17:48.2680438Z at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.executeMulti(TestNGDirectoryTestSuite.java:192)
2022-11-16T10:17:48.2681035Z at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.execute(TestNGDirectoryTestSuite.java:93)
2022-11-16T10:17:48.2681555Z at org.apache.maven.surefire.testng.TestNGProvider.invoke(TestNGProvider.java:155)
2022-11-16T10:17:48.2682060Z at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
2022-11-16T10:17:48.2682588Z at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
2022-11-16T10:17:48.2683118Z at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
2022-11-16T10:17:48.2683595Z at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)
2022-11-16T10:17:48.2684298Z 2022-11-16T10:17:48.257+0000 [main] ERROR jdbc.sqlonly - null. DataSource.getConnection()
2022-11-16T10:17:48.2684853Z java.sql.SQLException: Login timeout
2022-11-16T10:17:48.2685289Z at org.h2.jdbcx.JdbcConnectionPool.getConnection(JdbcConnectionPool.java:216)
2022-11-16T10:17:48.2686635Z at net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy.getConnection(DataSourceSpy.java:147)
2022-11-16T10:17:48.2687302Z at org.killbill.billing.DBTestingHelper$RetryableDataSource.getConnection(DBTestingHelper.java:130)
2022-11-16T10:17:48.2688085Z at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:40)
2022-11-16T10:17:48.2688650Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:230)
2022-11-16T10:17:48.2688970Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:227)
2022-11-16T10:17:48.2689447Z at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:35)
2022-11-16T10:17:48.2689914Z at org.skife.jdbi.v2.DBI.open(DBI.java:227)
2022-11-16T10:17:48.2690238Z at org.skife.jdbi.v2.DBI.open(DBI.java:219)
2022-11-16T10:17:48.2690730Z at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.getHandle(OnDemandHandleDing.java:42)
2022-11-16T10:17:48.2691297Z at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.retain(OnDemandHandleDing.java:50)
2022-11-16T10:17:48.2691799Z at org.skife.jdbi.v2.sqlobject.SqlObject.invoke(SqlObject.java:177)
2022-11-16T10:17:48.2692288Z at org.skife.jdbi.v2.sqlobject.SqlObjectInterceptor.intercept(SqlObjectInterceptor.java:44)
2022-11-16T10:17:48.2693186Z at org.killbill.billing.util.dao.NonEntitySqlDao$ByteBuddy$1yDc6aB2.getHistoryRecordIdIdMappingsForTablesWithoutAccountRecordId(Unknown Source)
2022-11-16T10:17:48.2693928Z at org.killbill.billing.util.audit.dao.DefaultAuditDao.lambda$buildAuditLogsFromModelDao$0(DefaultAuditDao.java:120)
2022-11-16T10:17:48.2694506Z at org.killbill.commons.utils.collect.Iterators$1.transform(Iterators.java:79)
2022-11-16T10:17:48.2695004Z at org.killbill.commons.utils.collect.TransformedIterator.next(TransformedIterator.java:40)
2022-11-16T10:17:48.2695602Z at org.killbill.commons.utils.collect.Iterators.toUnmodifiableList(Iterators.java:96)
2022-11-16T10:17:48.2696237Z at org.killbill.billing.util.audit.DefaultAccountAuditLogs.<init>(DefaultAccountAuditLogs.java:49)
2022-11-16T10:17:48.2696874Z at org.killbill.billing.util.audit.dao.DefaultAuditDao.getAuditLogsForAccountRecordId(DefaultAuditDao.java:81)
2022-11-16T10:17:48.2697627Z at org.killbill.billing.util.audit.dao.TestDefaultAuditDao.testRetrieveAuditsViaHistory(TestDefaultAuditDao.java:69)
2022-11-16T10:17:48.2698288Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2022-11-16T10:17:48.2705804Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
2022-11-16T10:17:48.2706422Z at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2022-11-16T10:17:48.2706878Z at java.base/java.lang.reflect.Method.invoke(Method.java:568)
2022-11-16T10:17:48.2707316Z at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
2022-11-16T10:17:48.2707825Z at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:238)
2022-11-16T10:17:48.2708290Z at org.killbill.billing.GuicyKillbillTestSuite.run(GuicyKillbillTestSuite.java:208)
2022-11-16T10:17:48.2708794Z at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:252)
2022-11-16T10:17:48.2709257Z at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:595)
2022-11-16T10:17:48.2709676Z at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
2022-11-16T10:17:48.2710251Z at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
2022-11-16T10:17:48.2710689Z at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
2022-11-16T10:17:48.2711123Z at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
2022-11-16T10:17:48.2711577Z at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
2022-11-16T10:17:48.2712096Z at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
2022-11-16T10:17:48.2712473Z at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
2022-11-16T10:17:48.2712823Z at org.testng.TestRunner.privateRun(TestRunner.java:764)
2022-11-16T10:17:48.2713144Z at org.testng.TestRunner.run(TestRunner.java:585)
2022-11-16T10:17:48.2713469Z at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
2022-11-16T10:17:48.2713822Z at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
2022-11-16T10:17:48.2714175Z at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
2022-11-16T10:17:48.2714512Z at org.testng.SuiteRunner.run(SuiteRunner.java:286)
2022-11-16T10:17:48.2714871Z at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
2022-11-16T10:17:48.2715248Z at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
2022-11-16T10:17:48.2715604Z at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
2022-11-16T10:17:48.2715960Z at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
2022-11-16T10:17:48.2716283Z at org.testng.TestNG.runSuites(TestNG.java:1069)
2022-11-16T10:17:48.2716570Z at org.testng.TestNG.run(TestNG.java:1037)
2022-11-16T10:17:48.2716945Z at org.apache.maven.surefire.testng.TestNGExecutor.run(TestNGExecutor.java:151)
2022-11-16T10:17:48.2717494Z at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.executeMulti(TestNGDirectoryTestSuite.java:192)
2022-11-16T10:17:48.2718091Z at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.execute(TestNGDirectoryTestSuite.java:93)
2022-11-16T10:17:48.2718622Z at org.apache.maven.surefire.testng.TestNGProvider.invoke(TestNGProvider.java:155)
2022-11-16T10:17:48.2719127Z at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
2022-11-16T10:17:48.2719623Z at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
2022-11-16T10:17:48.2720061Z at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
2022-11-16T10:17:48.2720499Z at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)
2022-11-16T10:17:48.2721090Z 2022-11-16T10:17:48.257+0000 [main] ERROR jdbc.sqltiming - null. DataSource.getConnection()
2022-11-16T10:17:48.2721417Z java.sql.SQLException: Login timeout
2022-11-16T10:17:48.2721771Z at org.h2.jdbcx.JdbcConnectionPool.getConnection(JdbcConnectionPool.java:216)
2022-11-16T10:17:48.2722236Z at net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy.getConnection(DataSourceSpy.java:147)
2022-11-16T10:17:48.2722728Z at org.killbill.billing.DBTestingHelper$RetryableDataSource.getConnection(DBTestingHelper.java:130)
2022-11-16T10:17:48.2723321Z at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:40)
2022-11-16T10:17:48.2723747Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:230)
2022-11-16T10:17:48.2724031Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:227)
2022-11-16T10:17:48.2724435Z at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:35)
2022-11-16T10:17:48.2724828Z at org.skife.jdbi.v2.DBI.open(DBI.java:227)
2022-11-16T10:17:48.2725118Z at org.skife.jdbi.v2.DBI.open(DBI.java:219)
2022-11-16T10:17:48.2725505Z at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.getHandle(OnDemandHandleDing.java:42)
2022-11-16T10:17:48.2725987Z at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.retain(OnDemandHandleDing.java:50)
2022-11-16T10:17:48.2726422Z at org.skife.jdbi.v2.sqlobject.SqlObject.invoke(SqlObject.java:177)
2022-11-16T10:17:48.2726880Z at org.skife.jdbi.v2.sqlobject.SqlObjectInterceptor.intercept(SqlObjectInterceptor.java:44)
2022-11-16T10:17:48.2727559Z at org.killbill.billing.util.dao.NonEntitySqlDao$ByteBuddy$1yDc6aB2.getHistoryRecordIdIdMappingsForTablesWithoutAccountRecordId(Unknown Source)
2022-11-16T10:17:48.2728224Z at org.killbill.billing.util.audit.dao.DefaultAuditDao.lambda$buildAuditLogsFromModelDao$0(DefaultAuditDao.java:120)
2022-11-16T10:17:48.2728729Z at org.killbill.commons.utils.collect.Iterators$1.transform(Iterators.java:79)
2022-11-16T10:17:48.2729250Z at org.killbill.commons.utils.collect.TransformedIterator.next(TransformedIterator.java:40)
2022-11-16T10:17:48.2729763Z at org.killbill.commons.utils.collect.Iterators.toUnmodifiableList(Iterators.java:96)
2022-11-16T10:17:48.2730286Z at org.killbill.billing.util.audit.DefaultAccountAuditLogs.<init>(DefaultAccountAuditLogs.java:49)
2022-11-16T10:17:48.2730888Z at org.killbill.billing.util.audit.dao.DefaultAuditDao.getAuditLogsForAccountRecordId(DefaultAuditDao.java:81)
2022-11-16T10:17:48.2731569Z at org.killbill.billing.util.audit.dao.TestDefaultAuditDao.testRetrieveAuditsViaHistory(TestDefaultAuditDao.java:69)
2022-11-16T10:17:48.2732136Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2022-11-16T10:17:48.2732793Z at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
2022-11-16T10:17:48.2733349Z at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2022-11-16T10:17:48.2733811Z at java.base/java.lang.reflect.Method.invoke(Method.java:568)
2022-11-16T10:17:48.2734239Z at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
2022-11-16T10:17:48.2734739Z at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:238)
2022-11-16T10:17:48.2735208Z at org.killbill.billing.GuicyKillbillTestSuite.run(GuicyKillbillTestSuite.java:208)
2022-11-16T10:17:48.2735696Z at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:252)
2022-11-16T10:17:48.2736165Z at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:595)
2022-11-16T10:17:48.2736581Z at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
2022-11-16T10:17:48.2737003Z at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
2022-11-16T10:17:48.2737420Z at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
2022-11-16T10:17:48.2737854Z at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
2022-11-16T10:17:48.2738314Z at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
2022-11-16T10:17:48.2738748Z at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
2022-11-16T10:17:48.2739125Z at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
2022-11-16T10:17:48.2739470Z at org.testng.TestRunner.privateRun(TestRunner.java:764)
2022-11-16T10:17:48.2739798Z at org.testng.TestRunner.run(TestRunner.java:585)
2022-11-16T10:17:48.2740113Z at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
2022-11-16T10:17:48.2740464Z at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
2022-11-16T10:17:48.2740827Z at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
2022-11-16T10:17:48.2741146Z at org.testng.SuiteRunner.run(SuiteRunner.java:286)
2022-11-16T10:17:48.2741499Z at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
2022-11-16T10:17:48.2741874Z at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
2022-11-16T10:17:48.2742225Z at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
2022-11-16T10:17:48.2742573Z at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
2022-11-16T10:17:48.2742891Z at org.testng.TestNG.runSuites(TestNG.java:1069)
2022-11-16T10:17:48.2743179Z at org.testng.TestNG.run(TestNG.java:1037)
2022-11-16T10:17:48.2743547Z at org.apache.maven.surefire.testng.TestNGExecutor.run(TestNGExecutor.java:151)
2022-11-16T10:17:48.2744150Z at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.executeMulti(TestNGDirectoryTestSuite.java:192)
2022-11-16T10:17:48.2744760Z at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.execute(TestNGDirectoryTestSuite.java:93)
2022-11-16T10:17:48.2745276Z at org.apache.maven.surefire.testng.TestNGProvider.invoke(TestNGProvider.java:155)
2022-11-16T10:17:48.2745777Z at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
2022-11-16T10:17:48.2746332Z at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
2022-11-16T10:17:48.2746780Z at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
2022-11-16T10:17:48.2747208Z at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)
2022-11-16T10:17:48.2748363Z 2022-11-16T10:17:48.257+0000 [main] WARN org.killbill.billing.api.AbortAfterFirstFailureListener - !!! Test failure, all other tests will be skipped: [TestResult name=testRetrieveAuditsViaHistory status=FAILURE method=TestDefaultAuditDao.testRetrieveAuditsViaHistory()[pri:0, instance:org.killbill.billing.util.audit.dao.TestDefaultAuditDao@31fa1761] output={null}] !!!
2022-11-16T10:17:48.3958281Z 2022-11-16T10:17:48.353+0000 [bus_events-lifecycle-dispatcher-th-1] ERROR jdbc.audit - null. DataSource.getConnection()
2022-11-16T10:17:48.3959224Z java.sql.SQLException: Login timeout
2022-11-16T10:17:48.3959814Z at org.h2.jdbcx.JdbcConnectionPool.getConnection(JdbcConnectionPool.java:216)
2022-11-16T10:17:48.3960625Z at net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy.getConnection(DataSourceSpy.java:147)
2022-11-16T10:17:48.3961366Z at org.killbill.billing.DBTestingHelper$RetryableDataSource.getConnection(DBTestingHelper.java:130)
2022-11-16T10:17:48.3962034Z at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:40)
2022-11-16T10:17:48.3962812Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:230)
2022-11-16T10:17:48.4026744Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:227)
2022-11-16T10:17:48.4027556Z at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:35)
2022-11-16T10:17:48.4028212Z at org.skife.jdbi.v2.DBI.open(DBI.java:227)
2022-11-16T10:17:48.4028706Z at org.skife.jdbi.v2.DBI.open(DBI.java:219)
2022-11-16T10:17:48.4029188Z at org.skife.jdbi.v2.DBI.withHandle(DBI.java:300)
2022-11-16T10:17:48.4029666Z at org.skife.jdbi.v2.DBI.inTransaction(DBI.java:328)
2022-11-16T10:17:48.4216468Z at org.killbill.queue.DBBackedQueue.executeTransaction(DBBackedQueue.java:343)
2022-11-16T10:17:48.4217046Z at org.killbill.queue.DBBackedQueueWithPolling.getReadyEntries(DBBackedQueueWithPolling.java:71)
2022-11-16T10:17:48.4217581Z at org.killbill.bus.DefaultPersistentBus.doDispatchEvents(DefaultPersistentBus.java:232)
2022-11-16T10:17:48.4218123Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.dispatchEvents(DefaultQueueLifecycle.java:335)
2022-11-16T10:17:48.4218646Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable$1.callback(DefaultQueueLifecycle.java:305)
2022-11-16T10:17:48.4219223Z at org.killbill.queue.DefaultQueueLifecycle.withHandlingRuntimeException(DefaultQueueLifecycle.java:367)
2022-11-16T10:17:48.4219761Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.run(DefaultQueueLifecycle.java:301)
2022-11-16T10:17:48.4220234Z at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:49)
2022-11-16T10:17:48.4220722Z at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2022-11-16T10:17:48.4221195Z at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2022-11-16T10:17:48.4221575Z at java.base/java.lang.Thread.run(Thread.java:833)
2022-11-16T10:17:48.4222287Z 2022-11-16T10:17:48.353+0000 [bus_events-lifecycle-dispatcher-th-1] ERROR jdbc.sqlonly - null. DataSource.getConnection()
2022-11-16T10:17:48.4222660Z java.sql.SQLException: Login timeout
2022-11-16T10:17:48.4223012Z at org.h2.jdbcx.JdbcConnectionPool.getConnection(JdbcConnectionPool.java:216)
2022-11-16T10:17:48.4223722Z at net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy.getConnection(DataSourceSpy.java:147)
2022-11-16T10:17:48.4224224Z at org.killbill.billing.DBTestingHelper$RetryableDataSource.getConnection(DBTestingHelper.java:130)
2022-11-16T10:17:48.4224758Z at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:40)
2022-11-16T10:17:48.4225167Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:230)
2022-11-16T10:17:48.4225539Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:227)
2022-11-16T10:17:48.4225947Z at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:35)
2022-11-16T10:17:48.4226336Z at org.skife.jdbi.v2.DBI.open(DBI.java:227)
2022-11-16T10:17:48.4226622Z at org.skife.jdbi.v2.DBI.open(DBI.java:219)
2022-11-16T10:17:48.4226908Z at org.skife.jdbi.v2.DBI.withHandle(DBI.java:300)
2022-11-16T10:17:48.4227213Z at org.skife.jdbi.v2.DBI.inTransaction(DBI.java:328)
2022-11-16T10:17:48.4227612Z at org.killbill.queue.DBBackedQueue.executeTransaction(DBBackedQueue.java:343)
2022-11-16T10:17:48.4228125Z at org.killbill.queue.DBBackedQueueWithPolling.getReadyEntries(DBBackedQueueWithPolling.java:71)
2022-11-16T10:17:48.4228651Z at org.killbill.bus.DefaultPersistentBus.doDispatchEvents(DefaultPersistentBus.java:232)
2022-11-16T10:17:48.4229170Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.dispatchEvents(DefaultQueueLifecycle.java:335)
2022-11-16T10:17:48.4229693Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable$1.callback(DefaultQueueLifecycle.java:305)
2022-11-16T10:17:48.4230252Z at org.killbill.queue.DefaultQueueLifecycle.withHandlingRuntimeException(DefaultQueueLifecycle.java:367)
2022-11-16T10:17:48.4230797Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.run(DefaultQueueLifecycle.java:301)
2022-11-16T10:17:48.4231262Z at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:49)
2022-11-16T10:17:48.4231748Z at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2022-11-16T10:17:48.4232225Z at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2022-11-16T10:17:48.4232592Z at java.base/java.lang.Thread.run(Thread.java:833)
2022-11-16T10:17:48.4233125Z 2022-11-16T10:17:48.353+0000 [bus_events-lifecycle-dispatcher-th-1] ERROR jdbc.sqltiming - null. DataSource.getConnection()
2022-11-16T10:17:48.4233510Z java.sql.SQLException: Login timeout
2022-11-16T10:17:48.4233868Z at org.h2.jdbcx.JdbcConnectionPool.getConnection(JdbcConnectionPool.java:216)
2022-11-16T10:17:48.4234318Z at net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy.getConnection(DataSourceSpy.java:147)
2022-11-16T10:17:48.4234811Z at org.killbill.billing.DBTestingHelper$RetryableDataSource.getConnection(DBTestingHelper.java:130)
2022-11-16T10:17:48.4235346Z at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:40)
2022-11-16T10:17:48.4235757Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:230)
2022-11-16T10:17:48.4236047Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:227)
2022-11-16T10:17:48.4236446Z at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:35)
2022-11-16T10:17:48.4236840Z at org.skife.jdbi.v2.DBI.open(DBI.java:227)
2022-11-16T10:17:48.4237112Z at org.skife.jdbi.v2.DBI.open(DBI.java:219)
2022-11-16T10:17:48.4237404Z at org.skife.jdbi.v2.DBI.withHandle(DBI.java:300)
2022-11-16T10:17:48.4237723Z at org.skife.jdbi.v2.DBI.inTransaction(DBI.java:328)
2022-11-16T10:17:48.4238106Z at org.killbill.queue.DBBackedQueue.executeTransaction(DBBackedQueue.java:343)
2022-11-16T10:17:48.4238612Z at org.killbill.queue.DBBackedQueueWithPolling.getReadyEntries(DBBackedQueueWithPolling.java:71)
2022-11-16T10:17:48.4239144Z at org.killbill.bus.DefaultPersistentBus.doDispatchEvents(DefaultPersistentBus.java:232)
2022-11-16T10:17:48.4239668Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.dispatchEvents(DefaultQueueLifecycle.java:335)
2022-11-16T10:17:48.4240229Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable$1.callback(DefaultQueueLifecycle.java:305)
2022-11-16T10:17:48.4240784Z at org.killbill.queue.DefaultQueueLifecycle.withHandlingRuntimeException(DefaultQueueLifecycle.java:367)
2022-11-16T10:17:48.4241327Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.run(DefaultQueueLifecycle.java:301)
2022-11-16T10:17:48.4241800Z at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:49)
2022-11-16T10:17:48.4242318Z at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2022-11-16T10:17:48.4242788Z at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2022-11-16T10:17:48.4243164Z at java.base/java.lang.Thread.run(Thread.java:833)
2022-11-16T10:17:48.4243865Z 2022-11-16T10:17:48.353+0000 [bus_events-lifecycle-dispatcher-th-1] WARN org.killbill.queue.DefaultQueueLifecycle - bus_events: Thread bus_events-lifecycle-dispatcher-th-1 got DBIException exception:
2022-11-16T10:17:48.4244503Z org.skife.jdbi.v2.exceptions.UnableToObtainConnectionException: java.sql.SQLException: Login timeout
2022-11-16T10:17:48.4244916Z at org.skife.jdbi.v2.DBI.open(DBI.java:251)
2022-11-16T10:17:48.4245196Z at org.skife.jdbi.v2.DBI.open(DBI.java:219)
2022-11-16T10:17:48.4245473Z at org.skife.jdbi.v2.DBI.withHandle(DBI.java:300)
2022-11-16T10:17:48.4245789Z at org.skife.jdbi.v2.DBI.inTransaction(DBI.java:328)
2022-11-16T10:17:48.4246190Z at org.killbill.queue.DBBackedQueue.executeTransaction(DBBackedQueue.java:343)
2022-11-16T10:17:48.4246689Z at org.killbill.queue.DBBackedQueueWithPolling.getReadyEntries(DBBackedQueueWithPolling.java:71)
2022-11-16T10:17:48.4247216Z at org.killbill.bus.DefaultPersistentBus.doDispatchEvents(DefaultPersistentBus.java:232)
2022-11-16T10:17:48.4247744Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.dispatchEvents(DefaultQueueLifecycle.java:335)
2022-11-16T10:17:48.4248266Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable$1.callback(DefaultQueueLifecycle.java:305)
2022-11-16T10:17:48.4248808Z at org.killbill.queue.DefaultQueueLifecycle.withHandlingRuntimeException(DefaultQueueLifecycle.java:367)
2022-11-16T10:17:48.4249348Z at org.killbill.queue.DefaultQueueLifecycle$DispatcherRunnable.run(DefaultQueueLifecycle.java:301)
2022-11-16T10:17:48.4249818Z at org.killbill.commons.concurrent.WrappedRunnable.run(WrappedRunnable.java:49)
2022-11-16T10:17:48.4250291Z at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2022-11-16T10:17:48.4250765Z at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2022-11-16T10:17:48.4251141Z at java.base/java.lang.Thread.run(Thread.java:833)
2022-11-16T10:17:48.4251443Z Caused by: java.sql.SQLException: Login timeout
2022-11-16T10:17:48.4251806Z at org.h2.jdbcx.JdbcConnectionPool.getConnection(JdbcConnectionPool.java:216)
2022-11-16T10:17:48.4252267Z at net.sf.log4jdbc.sql.jdbcapi.DataSourceSpy.getConnection(DataSourceSpy.java:147)
2022-11-16T10:17:48.4293163Z at org.killbill.billing.DBTestingHelper$RetryableDataSource.getConnection(DBTestingHelper.java:130)
2022-11-16T10:17:48.4293707Z at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:40)
2022-11-16T10:17:48.4294126Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:230)
2022-11-16T10:17:48.4294419Z at org.skife.jdbi.v2.DBI$4.execute(DBI.java:227)
2022-11-16T10:17:48.4294818Z at org.killbill.commons.profiling.Profiling.executeWithProfiling(Profiling.java:35)
2022-11-16T10:17:48.4295205Z at org.skife.jdbi.v2.DBI.open(DBI.java:227)
2022-11-16T10:17:48.4295432Z ... 14 more
2022-11-16T10:17:48.5136922Z 2022-11-16T10:17:48.454+0000 [main] ERROR org.killbill.billing.GuicyKillbillTestSuiteWithEmbeddedDB - ********************************************
2022-11-16T10:17:48.5138571Z 2022-11-16T10:17:48.454+0000 [main] ERROR org.killbill.billing.GuicyKillbillTestSuiteWithEmbeddedDB - *** TESTS HAVE FAILED - DUMPING THREADS ****
2022-11-16T10:17:48.5139478Z 2022-11-16T10:17:48.454+0000 [main] ERROR org.killbill.billing.GuicyKillbillTestSuiteWithEmbeddedDB - ********************************************
2022-11-16T10:17:48.5139928Z
2022-11-16T10:17:48.5140931Z 2022-11-16T10:17:48.454+0000 [main] ERROR org.killbill.billing.GuicyKillbillTestSuiteWithEmbeddedDB - "bus_events-th" id=465 state=WAITING
2022-11-16T10:17:48.5142018Z - waiting on <0x0c9d26c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2022-11-16T10:17:48.5142616Z - locked <0x0c9d26c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2022-11-16T10:17:48.5143052Z at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
2022-11-16T10:17:48.5143456Z at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
2022-11-16T10:17:48.5143985Z at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
2022-11-16T10:17:48.5144534Z at [email protected]/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3463)
2022-11-16T10:17:48.5144991Z at [email protected]/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
2022-11-16T10:17:48.5145514Z at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1623)
2022-11-16T10:17:48.5146059Z at [email protected]/java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:435)
2022-11-16T10:17:48.5146536Z at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1062)
2022-11-16T10:17:48.5147021Z at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1122)
2022-11-16T10:17:48.5147486Z at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2022-11-16T10:17:48.5147872Z at [email protected]/java.lang.Thread.run(Thread.java:833)
....
2022-11-16T10:18:18.8600766Z
2022-11-16T10:18:19.3958353Z [INFO]
2022-11-16T10:18:19.3958899Z [INFO] Results:
2022-11-16T10:18:19.3959223Z [INFO]
2022-11-16T10:18:19.3959800Z [ERROR] Failures:
2022-11-16T10:18:19.3961264Z [ERROR] TestDefaultAuditDao>GuicyKillbillTestSuite.run:208->testRetrieveAuditsViaHistory:69 » UnableToObtainConnection java.sql.SQLException: Login timeout
2022-11-16T10:18:19.3962027Z [INFO]
2022-11-16T10:18:19.3962535Z [ERROR] Tests run: 146, Failures: 1, Errors: 0, Skipped: 8
2022-11-16T10:18:19.3963144Z [INFO]
2022-11-16T10:18:19.3995354Z [INFO] ------------------------------------------------------------------------
2022-11-16T10:18:19.3997914Z [INFO] Reactor Summary for killbill 0.23.0-SNAPSHOT:
2022-11-16T10:18:19.3998162Z [INFO]
2022-11-16T10:18:19.3998408Z [INFO] killbill ........................................... SUCCESS [01:16 min]
2022-11-16T10:18:19.4001775Z [INFO] killbill-api ....................................... SUCCESS [ 18.896 s]
2022-11-16T10:18:19.4002152Z [INFO] killbill-util ...................................... FAILURE [02:48 min]
from killbill.
sbrossie
commented on September 23, 2024
@xsalefter I think the main thing at this point is to understand whether this issue may be related to the testing framework (database) or whether this is unrelated (bad coincidence), and instead something that changed in our CI environment.
Couple of thoughts:
- Could you we use
master(where these change did not happen) to run those tests and check whether we see some similar failures - For
work-for-release-0.23.xbranch, could we try:
- Add debugging to the test (e.g more details with regard to
java.sql.SQLException: Login timeout? - Unplug this test and see if others pass?
- ...
from killbill.
xsalefter
commented on September 23, 2024
Ok, this is what I've done so far:
As I said and we've experience so far, the problem happened randomly. Sometimes, I can reproduce the issue by calling this line several times (almost up to 7 times. Not so reliable way to reproduce an issue, I know):
reset && mvn -Ptravis -Dcheck.skip-dependency=true -Dcheck.skip-dependency-scope=true -Dcheck.skip-dependency-versions=true -Dcheck.skip-duplicate-finder=true -Dcheck.skip-enforcer=true -Dcheck.skip-rat=true -Dcheck.skip-spotbugs=true test verify
Then I intentionally changes H2 database connection pool size from 30 to just 1, locally, to see what happen. (See H2EmbeddedDB line ~125), and then build killbill-commons , and use it in killbill by override it in killbill pom.xml :
<killbill-commons.version>0.25.1-SNAPSHOT</killbill-commons.version>
This way, I can reproduce this issue precisely: Running TestDefaultAuditDao always give me the same problem in the same line (TestDefaultAuditDao.java:69) :
2022-11-18T06:51:20.486+0000 [main] ERROR jdbc.audit - null. DataSource.getConnection()
java.sql.SQLException: Login timeout
....
at org.killbill.billing.util.audit.DefaultAccountAuditLogs.<init>(DefaultAccountAuditLogs.java:49)
at org.killbill.billing.util.audit.dao.DefaultAuditDao.getAuditLogsForAccountRecordId(DefaultAuditDao.java:81)
at org.killbill.billing.util.audit.dao.TestDefaultAuditDao.testRetrieveAuditsViaHistory(TestDefaultAuditDao.java:69)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
....
So this is resource clean up problem. Then I tried to find out which method that exactly causing this problem. It turned out that the problem is inside DefaultAuditDao.getAuditLogsForAccountRecordId(). There's line:
final EntitySqlDao auditSqlDao = transactionalSqlDao.onDemandForStreamingResults(EntitySqlDao.class);
final Iterator<AuditLogModelDao> auditLogsForAccountRecordId = auditSqlDao.getAuditLogsForAccountRecordId(context);
final Iterator<AuditLog> allAuditLogs = buildAuditLogsFromModelDao(auditLogsForAccountRecordId, context);auditLogsForAccountRecordId keeps the connection open, hence other tests cannot use it, and throw exception after sometimes. If I "consume" the iterator, changes code to:
final EntitySqlDao auditSqlDao = transactionalSqlDao.onDemandForStreamingResults(EntitySqlDao.class);
final Iterator<AuditLogModelDao> auditLogsForAccountRecordId = auditSqlDao.getAuditLogsForAccountRecordId(context);
final Iterator<AuditLog> allAuditLogs = buildAuditLogsFromModelDao(Iterators.toUnmodifiableList(auditLogsForAccountRecordId).iterator(), context);The test passed, even with connection pool size = 1.
However, I tried to changes shouldStream property to false in :
public interface AuditSqlDao {
@SqlQuery
@SmartFetchSize(shouldStream = true)
public Iterator<AuditLogModelDao> getAuditLogsForAccountRecordId(@SmartBindBean final InternalTenantContext context);
}
But the problem persist.
I sent PR for killbill-commons to set connection pool size from 30 to 50 here: killbill/killbill-commons#160 . I know that this will not solve the problem properly nor guarantee that the problem will disappear, but perhaps for "quick patch" since everybody PRs are failed now? Or maybe we should use something like final Iterator<AuditLog> allAuditLogs = buildAuditLogsFromModelDao(Iterators.toUnmodifiableList(auditLogsForAccountRecordId).iterator(), context); instead? Or anything else?
from killbill.
pierre
commented on September 23, 2024
auditLogsForAccountRecordIdkeeps the connection open
This is on purpose to enable streaming of data from the database (hence the iterators). It is the responsibility of the caller to consume all entries (which will auto-close the connection).
See
Can you check the code if in a test we forget to close / consume? Or maybe in the code itself (which would be a bug!)?
from killbill.
sbrossie
commented on September 23, 2024
In the code where the issue is seen, it seems like we are consuming all the entries though. But perhaps there is something running before that does not properly close the connection (or does not consume all entries on an Iterator).
from killbill.
xsalefter
commented on September 23, 2024
Today tried to change DefaultAccountAuditLogs#accountAuditLogs data type from List to Iterator, but make other test failed.
I also try to test master branch to make sure that the problem is not from recent changes. And yes, master branch also suffer from the same problem.
from killbill.
xsalefter
commented on September 23, 2024
Ok, this is more what I think happened after some more debugging: There's open connection between:
DefaultAccountDao.getAuditLogsForAccountRecordId(AuditLevel, InternalTenantContext)and,DefaultAccountDao.buildAuditLogsFromModelDao(Iterator, InternalTenantContext).
In DefaultAccountDao.getAuditLogsForAccountRecordId(AuditLevel, InternalTenantContext), there's line:
final EntitySqlDao auditSqlDao = transactionalSqlDao.onDemandForStreamingResults(EntitySqlDao.class);
final Iterator<AuditLogModelDao> auditLogsForAccountRecordId = auditSqlDao.getAuditLogsForAccountRecordId(context);As per-comment, we want to stream the result. Thus we keep connection open.
After line above, we have:
final Iterator<AuditLog> allAuditLogs = buildAuditLogsFromModelDao(auditLogsForTableNameAndAccountRecordId, context);buildAuditLogsFromModelDao() is also database-extensive operation, and if all connection are used, this method would fails. This is probably why we have random failed tests.
Also, the reason why this happened often to H2 while other databases is fine because, in H2, we only set connection pool value = 30. In other DBs, we set it 100, thus they still have free available connection to use.
Still, this not answering why this issue only happened recently.
So far, solution that I think possible:
-
Consume
Iterator<AuditLogModelDao>early, right after we get it from database. We can refactor/review this when start working on the TODO inDefaultAccountAuditLogs. Something like:final EntitySqlDao auditSqlDao = transactionalSqlDao.onDemandForStreamingResults(EntitySqlDao.class); final Iterator<AuditLogModelDao> auditLogsForAccountRecordId = auditSqlDao.getAuditLogsForAccountRecordId(context); // Consume early.. final List<AuditLogModelDao> listAuditLogsForAccountRecordId = Iterators.toUnmodifiableList(auditLogsForAccountRecordId); final Iterator<AuditLog> allAuditLogs = buildAuditLogsFromModelDao(listAuditLogsForAccountRecordId.iterator(), context);
-
Increase H2 connection pool, at least the same as other database.
from killbill.
pierre
commented on September 23, 2024
Nice 🕵️ work... I suggest going for 2. for now, 1. might be hard... Before merging killbill/killbill-commons#160 though, maybe update the comment to point to this ticket, so we have context in the future?
from killbill.
xsalefter
commented on September 23, 2024
@pierre killbill/killbill-commons#160 get updated. However I set maxConnectionPool to 100 instead of 50 to match other DBs connection pool value.
from killbill.
Related Issues (20)
- Difference in behavior for UTC and PST account HOT 2
- Monitor background threads via healthcheck
- Multiple usage invoice items are created on plan change HOT 3
- Invoice plugins not called on commit/void
- Invoice plugins not called on refund HOT 2
- How can you kill this if someone has used all your information and sent this after all my personal accounts I almost broke help please HOT 2
- Encountering Tomcat SSL configuration issue HOT 1
- Subscription/bundle level entitlement status? HOT 2
- Reusing Written Off draft invoice
- Retrieve invoice by number returns incorrect balance for written off invoice HOT 1
- Create Subscription After Successful Payment HOT 2
- Plan Price Changes - Update System Logic
- Relax invoicing rules around additional items received from plugins HOT 2
- Verify behavior of invoicing system with DAILY billing period HOT 3
- Ability to link existing Authorization transaction with an invoice /use it for payment HOT 3
- Ability to better detect or override DBEngine HOT 1
- Capacity Usage Price Override - not supported
- KillBill allows recording a usage with the wrong unit type HOT 1
- Ability to control invoice#id HOT 1
- Invalid catalog passes validation
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from killbill.