[CAM-13840] DetermineHistoryLevelCmdTest is unstable

Type: Task
Resolution: Fixed
Priority: L3 - Default
Fix Version/s: 7.16.0, 7.15.6, 7.14.12, 7.13.18, 7.16.0-alpha5
Affects Version/s: None
Component/s: engine
Labels:
- build-failure

Acceptance Criteria (Required on creation):

DetermineHistoryLevelCmdTest doesn't fail randomly in the CI

Hints (Optional):

It looks like the problem occurs when DatabaseHistoryPropertyAutoTest runs first. The test fails consistently on my local machine if I run the two tests in this order.

Log output

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.camunda.bpm.engine.test.api.cfg.DatabaseHistoryPropertyAutoTest
[INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 15.069 s - in org.camunda.bpm.engine.test.api.cfg.DatabaseHistoryPropertyAutoTest
[INFO] Running org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest
[ERROR] Tests run: 4, Failures: 1, Errors: 2, Skipped: 0, Time elapsed: 5.574 s <<< FAILURE! - in org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest
[ERROR] useDefaultLevelAudit(org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest)  Time elapsed: 1.817 s  <<< FAILURE!
org.junit.ComparisonFailure: expected:<HistoryLevel[Audit(name=audit, id=2])> but was:<HistoryLevel[Full(name=full, id=3])>
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest.useDefaultLevelAudit(DetermineHistoryLevelCmdTest.java:73)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
        at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
        at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
        at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
        at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
        at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
        at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
        at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
        at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)

[ERROR] failWhenExistingHistoryLevelIsNotRegistered(org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest)  Time elapsed: 1.95 s  <<< ERROR!
org.camunda.bpm.engine.ProcessEngineException: historyLevel mismatch: configuration says org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest$1@1f235a0a and database says HistoryLevelFull(name=full, id=3)
        at org.camunda.bpm.engine.impl.HistoryLevelSetupCommand.execute(HistoryLevelSetupCommand.java:60)
        at org.camunda.bpm.engine.impl.HistoryLevelSetupCommand.execute(HistoryLevelSetupCommand.java:34)
        at org.camunda.bpm.engine.impl.interceptor.CommandExecutorImpl.execute(CommandExecutorImpl.java:28)
        at org.camunda.bpm.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:110)
        at org.camunda.bpm.engine.impl.interceptor.ProcessApplicationContextInterceptor.execute(ProcessApplicationContextInterceptor.java:70)
        at org.camunda.bpm.engine.impl.interceptor.CommandCounterInterceptor.execute(CommandCounterInterceptor.java:35)
        at org.camunda.bpm.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33)
        at org.camunda.bpm.engine.impl.ProcessEngineImpl.executeSchemaOperations(ProcessEngineImpl.java:149)
        at org.camunda.bpm.engine.impl.ProcessEngineImpl.<init>(ProcessEngineImpl.java:111)
        at org.camunda.bpm.engine.impl.cfg.ProcessEngineConfigurationImpl.buildProcessEngine(ProcessEngineConfigurationImpl.java:992)
        at org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest.failWhenExistingHistoryLevelIsNotRegistered(DetermineHistoryLevelCmdTest.java:102)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
        at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
        at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
        at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
        at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
        at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
        at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
        at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
        at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)

[ERROR] failWhenExistingHistoryLevelIsNotRegistered(org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest)  Time elapsed: 1.952 s  <<< ERROR!
java.lang.NullPointerException
        at org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest.after(DetermineHistoryLevelCmdTest.java:113)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
        at org.junit.internal.runners.statements.RunAfters.invokeMethod(RunAfters.java:46)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
        at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
        at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
        at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
        at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
        at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
        at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
        at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
        at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
        at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)

[INFO]
[INFO] Results:
[INFO]
[ERROR] Failures:
[ERROR]   DetermineHistoryLevelCmdTest.useDefaultLevelAudit:73 expected:<HistoryLevel[Audit(name=audit, id=2])> but was:<HistoryLevel[Full(name=full, id=3])>
[ERROR] Errors:
[ERROR] org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest.failWhenExistingHistoryLevelIsNotRegistered(org.camunda.bpm.engine.test.standalone.history.DetermineHistoryLevelCmdTest)
[ERROR]   Run 1: DetermineHistoryLevelCmdTest.failWhenExistingHistoryLevelIsNotRegistered:102 ▒ ProcessEngine
[ERROR]   Run 2: DetermineHistoryLevelCmdTest.after:113 NullPointer
[INFO]
[INFO]
[ERROR] Tests run: 6, Failures: 1, Errors: 1, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  01:35 min
[INFO] Finished at: 2021-08-23T17:24:00+02:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.22.2:test (default-test) on project camunda-engine: There are test failures.
[ERROR]
[ERROR] Please refer to C:\camunda\repos\camunda-bpm-platform\engine\target\surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException

This is the controller panel for Smart Panels app

Thorben Lindhauer added a comment - 23/Aug/21 5:41 PM - edited

Findings:

The two tests share the same in memory database URL. This was a copy-paste mistake when DatabaseHistoryPropertyAutoTest was created
H2 closes an in-memory database when the last connection to it is closed: http://www.h2database.com/html/features.html#in_memory_databases
DatabaseHistoryPropertyAutoTest closes all the engines it creates in @After: https://github.com/camunda/camunda-bpm-platform/blob/7.16.0-alpha4/engine/src/test/java/org/camunda/bpm/engine/test/api/cfg/DatabaseHistoryPropertyAutoTest.java#L99-L104
One test method builds an engine that fails (due to history level mismatch). I suspect this has certain side effects that are not rolled back. For example, the engine is then not added to the list of engines to be closed after the test. Furthermore, when I comment out these lines (https://github.com/camunda/camunda-bpm-platform/blob/7.16.0-alpha4/engine/src/test/java/org/camunda/bpm/engine/test/api/cfg/DatabaseHistoryPropertyAutoTest.java#L63-L65), then both tests succeed
Triggering a garbage collection System.gc(); after building the failing engine makes the issue disappear. I assume that the datasource isn't garbage-collected before the second test class runs and a new connection to the same in-memory database is established
A proper fix would be to ensure that the process engine closes all its resources (including the datasource) when an exception occurs during building the engine. However, as this is a larger undertaking:
- Needs proper try-catch wrapping in ProcessEngineConfigurationImpl#buildProcessEngine
- Needs to clean up/close all resources that matter (at least the data source)
- Should only clean up those resources that we also created during initialization (i.e. a datasource that was handed in from external should not be closed)
I will instead just use different H2 URLs for the tests; we could go for a proper solution in the future if we have more motivation for doing this

Thorben Lindhauer added a comment - 23/Aug/21 5:41 PM - edited Findings: The two tests share the same in memory database URL. This was a copy-paste mistake when DatabaseHistoryPropertyAutoTest was created H2 closes an in-memory database when the last connection to it is closed: http://www.h2database.com/html/features.html#in_memory_databases DatabaseHistoryPropertyAutoTest closes all the engines it creates in @After : https://github.com/camunda/camunda-bpm-platform/blob/7.16.0-alpha4/engine/src/test/java/org/camunda/bpm/engine/test/api/cfg/DatabaseHistoryPropertyAutoTest.java#L99-L104 One test method builds an engine that fails (due to history level mismatch). I suspect this has certain side effects that are not rolled back. For example, the engine is then not added to the list of engines to be closed after the test. Furthermore, when I comment out these lines ( https://github.com/camunda/camunda-bpm-platform/blob/7.16.0-alpha4/engine/src/test/java/org/camunda/bpm/engine/test/api/cfg/DatabaseHistoryPropertyAutoTest.java#L63-L65 ), then both tests succeed Triggering a garbage collection System.gc(); after building the failing engine makes the issue disappear. I assume that the datasource isn't garbage-collected before the second test class runs and a new connection to the same in-memory database is established A proper fix would be to ensure that the process engine closes all its resources (including the datasource) when an exception occurs during building the engine. However, as this is a larger undertaking: Needs proper try-catch wrapping in ProcessEngineConfigurationImpl#buildProcessEngine Needs to clean up/close all resources that matter (at least the data source) Should only clean up those resources that we also created during initialization (i.e. a datasource that was handed in from external should not be closed) I will instead just use different H2 URLs for the tests; we could go for a proper solution in the future if we have more motivation for doing this

camunda BPM

Details

Description

Acceptance Criteria (Required on creation):

Hints (Optional):

mgm-controller-panel

This is the controller panel for Smart Panels app

Attachments

Activity

Collapse comment: Thorben Lindhauer added a comment - 23/Aug/21 5:41 PM, Edited by Thorben Lindhauer - 23/Aug/21 6:10 PM

Expand comment: Thorben Lindhauer added a comment - 23/Aug/21 5:41 PM, Edited by Thorben Lindhauer - 23/Aug/21 6:10 PM

People

Dates

Salesforce