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

Investigate TestSQLRepositoryFulltextWork randomly failing in postgresql mode

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Cannot Reproduce
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: CI/CD

      Description

      After NXP-28579 was merged we notice this random test on Jenkins X: TestSQLRepositoryFulltextWork.testFulltextWithConcurrentDelete

      Let's see if it happens again and try to understand...

      [INFO] Running org.nuxeo.ecm.core.TestSQLRepositoryFulltextWork
      [2020-03-02T15:16:06.892Z] RuntimeStreamFeature: Deploying Nuxeo Stream using Chronicle
      [2020-03-02T15:16:06.893Z] WorkManagerFeature: Deploying WorkManager using default implementation
      [2020-03-02T15:16:06.893Z] StorageConfiguration: Deploying JDBC using DatabasePostgreSQL
      [2020-03-02T15:16:06.893Z] StorageConfiguration: Deploying a VCS repository
      [2020-03-02T15:16:07.829Z] 2020-03-02 15:16:07,511 [main] WARN  [TransientStorageComponent] Missing configuration for default transient store, using in-memory
      [2020-03-02T15:16:07.830Z] 2020-03-02 15:16:07,530 [main] ERROR [OSGiRuntimeService] Nuxeo Platform Started
      [2020-03-02T15:16:07.830Z] ======================================================================
      [2020-03-02T15:16:07.830Z] = Component Loading Warnings:
      [2020-03-02T15:16:07.830Z]   * Missing configuration for default transient store, using in-memory
      [2020-03-02T15:16:07.830Z] ======================================================================
      [2020-03-02T15:16:07.830Z] = Component Loading Status: Pending: 0 / Missing: 1 / Unstarted: 0 / Total: 112
      [2020-03-02T15:16:07.830Z]   * service:org.nuxeo.runtime.stream.service.managment.contrib references missing [target=org.nuxeo.ecm.core.management.CoreManagementComponent;point=probes, target=org.nuxeo.ecm.core.management.CoreManagementComponent;point=healthCheck]
      [2020-03-02T15:16:07.830Z] ======================================================================
      [2020-03-02T15:16:07.830Z] [ERROR] Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 3.73 s <<< FAILURE! - in org.nuxeo.ecm.core.TestSQLRepositoryFulltextWork
      [2020-03-02T15:16:07.830Z] [ERROR] testFulltextWithConcurrentDelete(org.nuxeo.ecm.core.TestSQLRepositoryFulltextWork)  Time elapsed: 1.251 s  <<< ERROR!
      [2020-03-02T15:16:07.830Z] org.nuxeo.ecm.core.api.ConcurrentUpdateException: Failed to remove document e199f95d-18fe-477a-8396-b03a446c38c1, Concurrent update
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCConnection.checkConcurrentUpdate(JDBCConnection.java:183)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCRowMapper.deleteRowsDirect(JDBCRowMapper.java:829)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCRowMapper.remove(JDBCRowMapper.java:1262)
      [2020-03-02T15:16:07.830Z] 	at jdk.internal.reflect.GeneratedMethodAccessor28.invoke(Unknown Source)
      [2020-03-02T15:16:07.830Z] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      [2020-03-02T15:16:07.830Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapperConnector.doInvoke(JDBCMapperConnector.java:111)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapperConnector.lambda$doConnectAndInvoke$0(JDBCMapperConnector.java:98)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.transaction.TransactionHelper.runInTransaction(TransactionHelper.java:607)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapperConnector.doConnectAndInvoke(JDBCMapperConnector.java:95)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCMapperConnector.invoke(JDBCMapperConnector.java:84)
      [2020-03-02T15:16:07.830Z] 	at com.sun.proxy.$Proxy179.remove(Unknown Source)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.SoftRefCachingRowMapper.remove(SoftRefCachingRowMapper.java:449)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.PersistenceContext.removeNode(PersistenceContext.java:992)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.SessionImpl.removeNode(SessionImpl.java:1018)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.ra.ConnectionImpl.removeNode(ConnectionImpl.java:256)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.coremodel.SQLSession.remove(SQLSession.java:624)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.coremodel.SQLDocumentLive.remove(SQLDocumentLive.java:165)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.storage.sql.coremodel.SQLDocumentLive.remove(SQLDocumentLive.java:171)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.api.AbstractSession.removeNotifyOneDoc(AbstractSession.java:1431)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.api.AbstractSession.removeDocument(AbstractSession.java:1403)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.api.AbstractSession.removeDocument(AbstractSession.java:1393)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.TestSQLRepositoryFulltextWork.createAndDeleteFile(TestSQLRepositoryFulltextWork.java:84)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.ecm.core.TestSQLRepositoryFulltextWork.testFulltextWithConcurrentDelete(TestSQLRepositoryFulltextWork.java:94)
      [2020-03-02T15:16:07.830Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      [2020-03-02T15:16:07.830Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      [2020-03-02T15:16:07.830Z] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      [2020-03-02T15:16:07.830Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
      [2020-03-02T15:16:07.830Z] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
      [2020-03-02T15:16:07.830Z] 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeMethodRunStatement.evaluate(FeaturesRunner.java:308)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeSetupStatement.evaluate(FeaturesRunner.java:322)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterMethodRunStatement.evaluate(FeaturesRunner.java:345)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterTeardownStatement.evaluate(FeaturesRunner.java:362)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:435)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.RuntimeDeployment$DeploymentStatement.evaluate(RuntimeDeployment.java:326)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$AfterClassStatement.evaluate(FeaturesRunner.java:251)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$RulesFactory$1.evaluate(FeaturesRunner.java:435)
      [2020-03-02T15:16:07.830Z] 	at org.nuxeo.runtime.test.runner.FeaturesRunner$BeforeClassStatement.evaluate(FeaturesRunner.java:234)
      [2020-03-02T15:16:07.830Z] 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.Suite.runChild(Suite.java:128)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.Suite.runChild(Suite.java:27)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
      [2020-03-02T15:16:07.830Z] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:158)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
      [2020-03-02T15:16:07.830Z] 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)
      [2020-03-02T15:16:07.830Z] Caused by: org.postgresql.util.PSQLException: ERROR: deadlock detected
      [2020-03-02T15:16:07.830Z]   Detail: Process 4573 waits for ShareLock on transaction 35373; blocked by process 4572.
      [2020-03-02T15:16:07.830Z] Process 4572 waits for ShareLock on transaction 35372; blocked by process 4573.
      [2020-03-02T15:16:07.830Z]   Hint: See server log for query details.
      [2020-03-02T15:16:07.830Z]   Where: while deleting tuple (0,13) in relation "fulltext"
      [2020-03-02T15:16:07.831Z] SQL statement "DELETE FROM ONLY "public"."fulltext" WHERE $1::pg_catalog.text OPERATOR(pg_catalog.=) "id"::pg_catalog.text"
      [2020-03-02T15:16:07.831Z] 	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2505)
      [2020-03-02T15:16:07.831Z] 	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2241)
      [2020-03-02T15:16:07.831Z] 	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:310)
      [2020-03-02T15:16:07.831Z] 	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:447)
      [2020-03-02T15:16:07.831Z] 	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:368)
      [2020-03-02T15:16:07.831Z] 	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:158)
      [2020-03-02T15:16:07.831Z] 	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:124)
      [2020-03-02T15:16:07.831Z] 	at org.tranql.connector.jdbc.PreparedStatementHandle.executeUpdate(PreparedStatementHandle.java:186)
      [2020-03-02T15:16:07.831Z] 	at org.nuxeo.ecm.core.storage.sql.jdbc.JDBCRowMapper.deleteRowsDirect(JDBCRowMapper.java:825)
      [2020-03-02T15:16:07.831Z] 	... 71 more
      

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved: