Uploaded image for project: 'Nuxeo Platform'
  1. Nuxeo Platform
  2. NXP-22168

Drive elasticsearch random bug beforeSetup: [audit] IndexAlreadyExistsException[already exists]

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Duplicate
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Nuxeo Drive

      Description

      See https://qa.nuxeo.org/jenkins/view/Drive/job/master/job/addons_nuxeo-drive-server-master/287/

      15:58:45 -------------------------------------------------------
      15:58:45  T E S T S
      15:58:45 -------------------------------------------------------
      15:58:46 Running org.nuxeo.drive.fixtures.AuditChangeFinderTestSuite
      15:58:46 Tests run: 1, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 0 sec - in org.nuxeo.drive.fixtures.AuditChangeFinderTestSuite
      15:58:46 Running org.nuxeo.drive.fixtures.AuditChangeFinderClusteringEnabledTestSuite
      15:58:49 StorageConfiguration: Deploying JDBC using DatabaseH2
      15:58:49 StorageConfiguration: Deploying a VCS repository
      15:58:49 main 15:58:49,819 ERROR [SchemaManagerImpl] XSD Schema not found: schemas/expired_search.xsd{{fState,beforeRun}{tx,1000000047544d4944}}
      15:58:54 main 15:58:54,591 ERROR [OSGiRuntimeService] Nuxeo Platform Started
      15:58:54 ======================================================================
      15:58:54 = Component Loading Status: Pending: 1 / Missing: 4 / Unstarted: 0 / Total: 207
      15:58:54   * service:org.nuxeo.ecm.platform.audit.PageProviderservice.es.contrib requires [service:org.nuxeo.admin.pageproviders]
      15:58:54   * service:org.nuxeo.ecm.platform.audit.service.persistence references missing [target=org.nuxeo.ecm.core.persistence.PersistenceComponent;point=hibernate]
      15:58:54   * service:org.nuxeo.collections.operations references missing [target=org.nuxeo.ecm.core.operation.OperationServiceComponent;point=operations]
      15:58:54   * service:org.nuxeo.ecm.platform.uidgen.contribs references missing [target=org.nuxeo.ecm.core.persistence.PersistenceComponent;point=hibernate]
      15:58:54   * service:org.nuxeo.drive.elasticsearch.operations references missing [target=org.nuxeo.ecm.core.operation.OperationServiceComponent;point=operations]
      15:58:54 ======================================================================{{fState,beforeRun}{tx,1000000047544d4944}}
      15:58:55 Tests run: 1, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 8.404 sec - in org.nuxeo.drive.fixtures.AuditChangeFinderClusteringEnabledTestSuite
      15:58:55 Running org.nuxeo.drive.fixtures.GroupChangesTestSuite
      15:59:10 main 15:59:10,768 WARN  [CacheServiceImpl] Unregistery leaked contribution driveCollectionSyncRootMember{{fState,afterRun}{fSuite,class org.nuxeo.drive.fixtures.GroupChangesTestSuite}}
      15:59:10 main 15:59:10,769 WARN  [CacheServiceImpl] Unregistery leaked contribution driveDescendantsScroll{{fState,afterRun}{fSuite,class org.nuxeo.drive.fixtures.GroupChangesTestSuite}}
      15:59:10 main 15:59:10,769 WARN  [CacheServiceImpl] Unregistery leaked contribution driveSyncRoot{{fState,afterRun}{fSuite,class org.nuxeo.drive.fixtures.GroupChangesTestSuite}}
      15:59:10 main 15:59:10,778 WARN  [DefaultMonitorComponent] Total commits during server life: 293{{fState,afterRun}{fSuite,class org.nuxeo.drive.fixtures.GroupChangesTestSuite}}
      15:59:11 StorageConfiguration: Deploying JDBC using DatabaseH2
      15:59:11 StorageConfiguration: Deploying a VCS repository
      15:59:12 main 15:59:12,792 ERROR [OSGiRuntimeService] Nuxeo Platform Started
      15:59:12 ======================================================================
      15:59:12 = Component Loading Status: Pending: 0 / Missing: 1 / Unstarted: 0 / Total: 128
      15:59:12   * service:org.nuxeo.drive.listeners references missing [target=org.nuxeo.ecm.platform.audit.service.NXAuditEventsService;point=event]
      15:59:12 ======================================================================{{fState,beforeRun}}
      15:59:12 Tests run: 6, Failures: 1, Errors: 1, Skipped: 0, Time elapsed: 17.564 sec <<< FAILURE! - in org.nuxeo.drive.fixtures.GroupChangesTestSuite
      15:59:12 testGroupChangesOnSyncRoot(org.nuxeo.drive.fixtures.GroupChangesTestSuite)  Time elapsed: 2.099 sec  <<< FAILURE!
      15:59:12 java.lang.AssertionError: invoke on features error [Holder [type=class org.nuxeo.runtime.test.runner.MDCFeature], Holder [type=class org.nuxeo.runtime.test.runner.ConditionalIgnoreRule$Feature], Holder [type=class org.nuxeo.runtime.test.runner.RandomBug$Feature], Holder [type=class org.nuxeo.runtime.test.runner.RuntimeFeature], Holder [type=class org.nuxeo.runtime.management.ManagementFeature], Holder [type=class org.nuxeo.ecm.core.management.jtajca.JtajcaManagementFeature], Holder [type=class org.nuxeo.runtime.test.runner.ContainerFeature], Holder [type=class org.nuxeo.ecm.core.test.TransactionalFeature], Holder [type=class org.nuxeo.ecm.core.test.CoreFeature], Holder [type=class org.nuxeo.ecm.platform.login.test.ClientLoginFeature], Holder [type=class org.nuxeo.ecm.directory.sql.SQLDirectoryFeature], Holder [type=class org.nuxeo.ecm.platform.test.PlatformFeature], Holder [type=class org.nuxeo.drive.test.NuxeoDriveFeature], Holder [type=class org.nuxeo.elasticsearch.test.RepositoryElasticSearchFeature], Holder [type=class org.nuxeo.drive.test.ESAuditFeature]]
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesLoader.apply(FeaturesLoader.java:123)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesLoader.apply(FeaturesLoader.java:113)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner.beforeSetup(FeaturesRunner.java:214)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeSetupStatement.evaluate(FeaturesRunner.java:361)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterMethodRunStatement.evaluate(FeaturesRunner.java:393)
      15:59:12 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterTeardownStatement.evaluate(FeaturesRunner.java:412)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:525)
      15:59:12 	at org.nuxeo.runtime.test.runner.RuntimeDeployment$DeploymentStatement.evaluate(RuntimeDeployment.java:300)
      15:59:12 	at org.nuxeo.runtime.test.runner.RuntimeFeature$2$1.evaluate(RuntimeFeature.java:124)
      15:59:12 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
      15:59:12 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
      15:59:12 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
      15:59:12 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
      15:59:12 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
      15:59:12 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
      15:59:12 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
      15:59:12 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
      15:59:12 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterClassStatement.evaluate(FeaturesRunner.java:285)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:525)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeClassStatement.evaluate(FeaturesRunner.java:268)
      15:59:12 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
      15:59:12 	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:127)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:26)
      15:59:12 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
      15:59:12 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
      15:59:12 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
      15:59:12 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
      15:59:12 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
      15:59:12 	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:127)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:26)
      15:59:12 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
      15:59:12 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
      15:59:12 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
      15:59:12 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
      15:59:12 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
      15:59:12 	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
      15:59:12 	at org.junit.runner.JUnitCore.run(JUnitCore.java:160)
      15:59:12 	at org.junit.runner.JUnitCore.run(JUnitCore.java:138)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:113)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:85)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:54)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:134)
      15:59:12 	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
      15:59:12 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
      15:59:12 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
      15:59:12 	Suppressed: [audit] IndexAlreadyExistsException[already exists]
      15:59:12 		at org.elasticsearch.cluster.metadata.MetaDataCreateIndexService.validateIndexName(MetaDataCreateIndexService.java:138)
      15:59:12 		at org.elasticsearch.cluster.metadata.MetaDataCreateIndexService.validate(MetaDataCreateIndexService.java:473)
      15:59:12 		at org.elasticsearch.cluster.metadata.MetaDataCreateIndexService.access$100(MetaDataCreateIndexService.java:97)
      15:59:12 		at org.elasticsearch.cluster.metadata.MetaDataCreateIndexService$1.execute(MetaDataCreateIndexService.java:192)
      15:59:12 		at org.elasticsearch.cluster.ClusterStateUpdateTask.execute(ClusterStateUpdateTask.java:45)
      15:59:12 		at org.elasticsearch.cluster.service.InternalClusterService.runTasksForExecutor(InternalClusterService.java:468)
      15:59:12 		at org.elasticsearch.cluster.service.InternalClusterService$UpdateTask.run(InternalClusterService.java:772)
      15:59:12 		at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:231)
      15:59:12 		at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:194)
      15:59:12 		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      15:59:12 		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      15:59:12 		at java.lang.Thread.run(Thread.java:745)
      15:59:12 
      15:59:12 testGroupChangesOnSyncRoot(org.nuxeo.drive.fixtures.GroupChangesTestSuite)  Time elapsed: 2.099 sec  <<< ERROR!
      15:59:12 java.lang.NullPointerException
      15:59:12 	at org.nuxeo.drive.fixtures.GroupChangesTestSuite.deleteGroup(GroupChangesTestSuite.java:116)
      15:59:12 	at org.nuxeo.drive.fixtures.GroupChangesTestSuite.tearDown(GroupChangesTestSuite.java:93)
      15:59:12 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      15:59:12 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      15:59:12 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      15:59:12 	at java.lang.reflect.Method.invoke(Method.java:498)
      15:59:12 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
      15:59:12 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
      15:59:12 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
      15:59:12 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterTeardownStatement.evaluate(FeaturesRunner.java:412)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:525)
      15:59:12 	at org.nuxeo.runtime.test.runner.RuntimeDeployment$DeploymentStatement.evaluate(RuntimeDeployment.java:300)
      15:59:12 	at org.nuxeo.runtime.test.runner.RuntimeFeature$2$1.evaluate(RuntimeFeature.java:124)
      15:59:12 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
      15:59:12 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
      15:59:12 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
      15:59:12 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
      15:59:12 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
      15:59:12 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
      15:59:12 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
      15:59:12 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
      15:59:12 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterClassStatement.evaluate(FeaturesRunner.java:285)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:525)
      15:59:12 	at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeClassStatement.evaluate(FeaturesRunner.java:268)
      15:59:12 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
      15:59:12 	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:127)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:26)
      15:59:12 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
      15:59:12 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
      15:59:12 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
      15:59:12 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
      15:59:12 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
      15:59:12 	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:127)
      15:59:12 	at org.junit.runners.Suite.runChild(Suite.java:26)
      15:59:12 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
      15:59:12 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
      15:59:12 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
      15:59:12 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
      15:59:12 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
      15:59:12 	at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
      15:59:12 	at org.junit.runner.JUnitCore.run(JUnitCore.java:160)
      15:59:12 	at org.junit.runner.JUnitCore.run(JUnitCore.java:138)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:113)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:85)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:54)
      15:59:12 	at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:134)
      15:59:12 	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200)
      15:59:12 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153)
      15:59:12 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
      15:59:12 
      15:59:12 Running org.nuxeo.drive.elasticsearch.TestESSyncRootFolderItem
      15:59:16 Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 3.342 sec - in org.nuxeo.drive.elasticsearch.TestESSyncRootFolderItem
      15:59:16 
      15:59:16 Results :
      15:59:16 
      15:59:16 Failed tests: 
      15:59:16   GroupChangesTestSuite.testGroupChangesOnSyncRoot invoke on features error [Holder [type=class org.nuxeo.runtime.test.runner.MDCFeature], Holder [type=class org.nuxeo.runtime.test.runner.ConditionalIgnoreRule$Feature], Holder [type=class org.nuxeo.runtime.test.runner.RandomBug$Feature], Holder [type=class org.nuxeo.runtime.test.runner.RuntimeFeature], Holder [type=class org.nuxeo.runtime.management.ManagementFeature], Holder [type=class org.nuxeo.ecm.core.management.jtajca.JtajcaManagementFeature], Holder [type=class org.nuxeo.runtime.test.runner.ContainerFeature], Holder [type=class org.nuxeo.ecm.core.test.TransactionalFeature], Holder [type=class org.nuxeo.ecm.core.test.CoreFeature], Holder [type=class org.nuxeo.ecm.platform.login.test.ClientLoginFeature], Holder [type=class org.nuxeo.ecm.directory.sql.SQLDirectoryFeature], Holder [type=class org.nuxeo.ecm.platform.test.PlatformFeature], Holder [type=class org.nuxeo.drive.test.NuxeoDriveFeature], Holder [type=class org.nuxeo.elasticsearch.test.RepositoryElasticSearchFeature], Holder [type=class org.nuxeo.drive.test.ESAuditFeature]]
      15:59:16 
      15:59:16 Tests in error: 
      15:59:16   GroupChangesTestSuite.tearDown:93->deleteGroup:116 NullPointer
      15:59:16 
      15:59:16 Tests run: 9, Failures: 1, Errors: 1, Skipped: 2
      15:59:16 
      15:59:16 [ERROR] There are test failures.
      

      This might be a consequence of https://github.com/nuxeo/nuxeo-drive-server/commit/3cff3c0e0cf5f976499a54bbb2f3790b2a42bc91#diff-6510deea78318bbf75a91055808b1ccdL88.
      This was done because when dropping the audit index after the teardown in the ESAuditFeature, the CoreFeature teardown would run afterwards and perform the repository cleanup, inserting new deleted events in the audit logs, so the audit index was not clean before the next test.

      Yest, I don't understand how:

      • The injected userManager can be null at tearDown.
      • Surefire displays "Tests run: 6, Failures: 1, Errors: 1" whereas there are only 5 tests in the suite.

        Attachments

        1. trace.log
          731 kB
          Antoine Taillefer

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: