search

dotCMS / core

Headless/Hybrid Content Management System for Enterprises
http://dotcms.com
Other
846 stars 465 forks source link

Flakey Integration test WorkflowAPITest.testPushIndexUpdate causing left over reindex entries and timeout #28643

Open spbolton opened 4 months ago

spbolton commented 4 months ago

WorkflowAPITest.testPushIndexUpdate

https://github.com/dotCMS/core/actions/runs/9203251769

This test has added reindex entries that are stuck in the indexer queue. We have a cleanup action to detect this but each subsequent test is waiting 30s for the queue to clear and it never is causing the whole run to timeout. 

2024-05-23T06:50:55.9309694Z 06:50:55.867 f1 main INFO  junit.RuleWatcher - >>> testPushIndexUpdate(com.dotmarketing.portlets.workflows.business.WorkflowAPITest) - starting...
2024-05-23T06:50:55.9311603Z 06:50:55.867 f1 main INFO  junit.RuleWatcher - >>>>>>>>>>>>>>>>>>>>>>>>>>
2024-05-23T06:50:56.0307242Z 06:50:55.958 f1 main INFO  junit.RuleWatcher - >>>>>>>>>cleanup>>>>>>>>>>
2024-05-23T06:50:56.0308596Z 06:50:55.958 f1 main WARN  junit.RuleWatcher - Checking for modified Config overrides...
2024-05-23T06:50:56.0309603Z 06:50:55.958 f1 main INFO  junit.MainBaseSuite - Checking indexer status...
2024-05-23T06:50:56.0310577Z 06:50:55.958 f1 main INFO  junit.MainBaseSuite - Indexer is not empty, waiting for it to finish
2024-05-23T06:50:57.0354229Z 06:50:56.938 f1 dot-ReindexThreadSubmitter-0 WARN  util.KeyValueFieldUtil - Error parsing json: messed-up-json. Trying to parse with the JS replacement due to container or key/value data...
2024-05-23T06:50:57.0358918Z 06:50:56.938 f1 dot-ReindexThreadSubmitter-0 ERROR util.KeyValueFieldUtil - Unable to parse JSON: messed-up-json. Please review the content and check for potential JS replacements. Returning exception
2024-05-23T06:50:57.0362293Z com.dotmarketing.exception.DotRuntimeException: Unrecognized token 'messed': was expecting (JSON String, Number, Array, Object or token 'null', 'true' or 'false')
2024-05-23T06:50:57.0364582Z  at [Source: REDACTED (`StreamReadFeature.INCLUDE_SOURCE_IN_LOCATION` disabled); line: 1, column: 7]
2024-05-23T06:50:57.0366496Z    at io.vavr.control.Try.getOrElseThrow(Try.java:748) ~[vavr-0.10.3.jar:?]
2024-05-23T06:50:57.0368746Z    at com.dotcms.util.marshal.JacksonMarshalUtilsImpl.unmarshal(JacksonMarshalUtilsImpl.java:65) ~[dotcms-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
2024-05-23T06:50:57.0371672Z    at com.dotcms.contenttype.util.KeyValueFieldUtil.JSONValueToHashMap(KeyValueFieldUtil.java:31) ~[dotcms-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
2024-05-23T06:50:57.0374635Z    at com.dotmarketing.portlets.structure.model.KeyValueFieldUtil.JSONValueToHashMap(KeyValueFieldUtil.java:14) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0377832Z    at com.dotmarketing.portlets.contentlet.transform.ContentletTransformer.getObjectValue(ContentletTransformer.java:353) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0381481Z    at com.dotmarketing.portlets.contentlet.transform.ContentletTransformer.populateFields(ContentletTransformer.java:313) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0384775Z    at com.dotmarketing.portlets.contentlet.transform.ContentletTransformer.transform(ContentletTransformer.java:116) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0387593Z    at com.dotmarketing.portlets.contentlet.transform.ContentletTransformer.<init>(ContentletTransformer.java:63) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0390516Z    at com.dotcms.util.transform.TransformerLocator.createContentletTransformer(TransformerLocator.java:137) ~[dotcms-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
2024-05-23T06:50:57.0393329Z    at com.dotcms.content.elasticsearch.business.ESContentFactoryImpl.findInDb(ESContentFactoryImpl.java:853) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0396060Z    at com.dotcms.content.elasticsearch.business.ESContentletAPIImpl.findInDb(ESContentletAPIImpl.java:574) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0398897Z    at com.dotmarketing.portlets.contentlet.business.ContentletAPIInterceptor.findInDb(ContentletAPIInterceptor.java:3018) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0401879Z    at com.dotcms.content.elasticsearch.business.ContentletIndexAPIImpl.appendBulkRequest(ContentletIndexAPIImpl.java:726) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0405017Z    at com.dotcms.content.elasticsearch.business.ContentletIndexAPIImpl.appendToBulkProcessor(ContentletIndexAPIImpl.java:762) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0407949Z    at com.dotcms.content.elasticsearch.business.ContentletIndexAPIImpl.appendToBulkProcessor(ContentletIndexAPIImpl.java:688) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0410186Z    at com.dotmarketing.common.reindex.ReindexThread.runReindexLoop(ReindexThread.java:227) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0411404Z    at com.dotmarketing.common.reindex.ReindexThread.lambda$new$1(ReindexThread.java:159) ~[dotcms-core-1.0.0-SNAPSHOT.jar:?]
2024-05-23T06:50:57.0412156Z    at java.lang.Thread.run(Thread.java:829) ~[?:?]
2024-05-23T06:50:57.0412727Z    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
2024-05-23T06:50:57.0413379Z    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
2024-05-23T06:50:57.0414088Z    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
2024-05-23T06:50:57.0414892Z    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
2024-05-23T06:50:57.0415490Z    at java.lang.Thread.run(Thread.java:829) [?:?]
2024-05-23T06:50:57.0416545Z Caused by: com.fasterxml.jackson.core.JsonParseException: Unrecognized token 'messed': was expecting (JSON String, Number, Array, Object or token 'null', 'true' or 'false')
2024-05-23T06:50:57.0417683Z  at [Source: REDACTED (`StreamReadFeature.INCLUDE_SOURCE_IN_LOCATION` disabled); line: 1, column: 7]
2024-05-23T06:50:57.0418674Z    at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:2481) ~[jackson-core-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0419902Z    at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:762) ~[jackson-core-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0421920Z    at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._reportInvalidToken(ReaderBasedJsonParser.java:3042) ~[jackson-core-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0424516Z    at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._handleOddValue(ReaderBasedJsonParser.java:2085) ~[jackson-core-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0427080Z    at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextToken(ReaderBasedJsonParser.java:812) ~[jackson-core-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0429472Z    at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:4986) ~[jackson-databind-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0431679Z    at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4892) ~[jackson-databind-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0433913Z    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3846) ~[jackson-databind-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0436239Z    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3829) ~[jackson-databind-2.16.1.jar:2.16.1]
2024-05-23T06:50:57.0439427Z    at com.dotcms.util.marshal.JacksonMarshalUtilsImpl.lambda$unmarshal$a21c04d4$1(JacksonMarshalUtilsImpl.java:65) ~[dotcms-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
2024-05-23T06:50:57.0441301Z    at io.vavr.control.Try.of(Try.java:75) ~[vavr-0.10.3.jar:?]
2024-05-23T06:50:57.0442012Z    ... 22 more
2024-05-23T06:50:57.0443861Z 06:50:56.938 f1 dot-ReindexThreadSubmitter-0 WARN  transform.ContentletTransformer - Failed to convert keyValue field `keyValueField` to an actual json. An Empty will be returned instead. 
2024-05-23T06:51:26.0652310Z 06:51:25.992 f1 main WARN  datagen.TestWorkflowUtils - Reindex Queue is not empty after 30s
2024-05-23T06:51:26.0653658Z java.lang.Throwable: null
2024-05-23T06:51:26.0654980Z    at com.dotcms.datagen.TestDataUtils.waitForEmptyQueue(TestDataUtils.java:2600) ~[test-classes/:?]
2024-05-23T06:51:26.0656989Z    at com.dotcms.datagen.TestDataUtils.waitForEmptyQueue(TestDataUtils.java:2606) ~[test-classes/:?]
2024-05-23T06:51:26.0659810Z    at com.dotcms.junit.RuleWatcher.indexerTrackerAfter(RuleWatcher.java:137) ~[test-classes/:?]
2024-05-23T06:51:26.0662223Z    at com.dotcms.junit.RuleWatcher.finished(RuleWatcher.java:74) ~[test-classes/:?]
2024-05-23T06:51:26.0663733Z    at org.junit.rules.TestWatcher.finishedQuietly(TestWatcher.java:122) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0665429Z    at org.junit.rules.TestWatcher.access$400(TestWatcher.java:52) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0666550Z    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:70) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0667351Z    at org.junit.rules.RunRules.evaluate(RunRules.java:20) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0668370Z    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0669361Z    at com.dotcms.junit.CustomDataProviderRunner.runChild(CustomDataProviderRunner.java:31) ~[test-classes/:?]
2024-05-23T06:51:26.0670462Z    at com.dotcms.junit.CustomDataProviderRunner.runChild(CustomDataProviderRunner.java:17) ~[test-classes/:?]
2024-05-23T06:51:26.0671536Z    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0672399Z    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0673300Z    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0674199Z    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0676400Z    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0678122Z    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0679607Z    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0680573Z    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0681407Z    at org.junit.runners.ParentRunner.run(ParentRunner.java:413) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0682239Z    at com.dotcms.junit.MainBaseSuite$DotRunner.run(MainBaseSuite.java:71) ~[test-classes/:?]
2024-05-23T06:51:26.0683026Z    at org.junit.runners.Suite.runChild(Suite.java:128) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0683752Z    at org.junit.runners.Suite.runChild(Suite.java:27) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0684525Z    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0685353Z    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0686239Z    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0687210Z    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0688311Z    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0689166Z    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0689990Z    at org.junit.runners.ParentRunner.run(ParentRunner.java:413) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0690773Z    at org.junit.runner.JUnitCore.run(JUnitCore.java:137) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0691501Z    at org.junit.runner.JUnitCore.run(JUnitCore.java:115) ~[junit-4.13.2.jar:4.13.2]
2024-05-23T06:51:26.0692487Z    at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42) ~[junit-vintage-engine-5.10.2.jar:5.10.2]
2024-05-23T06:51:26.0693758Z    at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80) ~[junit-vintage-engine-5.10.2.jar:5.10.2]
2024-05-23T06:51:26.0694990Z    at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72) ~[junit-vintage-engine-5.10.2.jar:5.10.2]
2024-05-23T06:51:26.0696354Z    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0697876Z    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0699515Z    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0701275Z    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0702947Z    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0704551Z    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0705923Z    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0707177Z    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0708470Z    at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47) ~[junit-platform-launcher-1.10.2.jar:1.10.2]
2024-05-23T06:51:26.0709761Z    at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:56) ~[surefire-junit-platform-3.2.5.jar:3.2.5]
2024-05-23T06:51:26.0711214Z    at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:184) ~[surefire-junit-platform-3.2.5.jar:3.2.5]
2024-05-23T06:51:26.0712744Z    at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:148) ~[surefire-junit-platform-3.2.5.jar:3.2.5]
2024-05-23T06:51:26.0714246Z    at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:122) ~[surefire-junit-platform-3.2.5.jar:3.2.5]
2024-05-23T06:51:26.0715600Z    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:385) ~[surefire-booter-3.2.5.jar:3.2.5]
2024-05-23T06:51:26.0716767Z    at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162) ~[surefire-booter-3.2.5.jar:3.2.5]
2024-05-23T06:51:26.0717847Z    at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:507) ~[surefire-booter-3.2.5.jar:3.2.5]
2024-05-23T06:51:26.0718901Z    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:495) ~[surefire-booter-3.2.5.jar:3.2.5]
2024-05-23T06:51:49.6915356Z DB:2024-05-23 06:51:49.690 UTC [65] LOG:  checkpoint complete: wrote 1049 buffers (3.2%); 0 WAL file(s) added, 0 removed, 1 recycled; write=103.080 s, sync=0.003 s, total=103.084 s; sync files=273, longest=0.001 s, average=0.001 s; distance=14345 kB, estimate=14345 kB
2024-05-23T06:51:56.0234850Z 06:51:56.021 f1 main WARN  datagen.TestWorkflowUtils - Reindex Queue is not empty after 30s

9Merge Group Test JVM IT Tests - JDK 11 MainSuite 2a.txt

spbolton commented 4 months ago

It looks like the test gets identifiers and then adds them to reindex. I think we are hitting a case where we have an entry in the reindex queue that can never be processed and never gets cleaned up. Looks like like the Json deserialization here JSONValueToHashMap is causing the ContentletIndexAPIImpl.appendToBulkProcessor to fail and the db entry for the reindex is left in the queue

spbolton commented 4 months ago

The failure is triggered by the existance of a bad contentlet that has been purposely created with ContentletAPITest.Test_Key_Value_As_Map_Test. so we may be able to recreate the issue as long as this test is run first.

github-actions[bot] commented 1 month ago

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 30 days.