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

Fix FT Kafka ERROR In log taggedVersionListener documentRestored

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 11.1-SNAPSHOT
    • Fix Version/s: 11.1, 2021.0
    • Component/s: Tagging
    • Team:
      PLATFORM
    • Sprint:
      nxplatform 11.1.22, nxplatform 11.1.23, nxplatform 11.1.24
    • Story Points:
      3

      Description

      On FT build with Kafka there are systematic errors in logs (tests are ok).

      https://qa.nuxeo.org/jenkins/job/master/job/FT-nuxeo-master-server-tomcat-kafka

      2019-09-13T19:46:39,758 ERROR [defaultPool-01,in:77,inCheckpoint:77,out:0,lastRead:1568403999737,lastTimer:0,wm:205573849043304449,loop:199,checkpoint:22567986446780080.1928188938] [org.nuxeo.ecm.core.work.AbstractWork] Exception during work: ListenerWork(Listener taggedVersionListener [documentRestored/5eb446d0-1ab6-4699-b23e-a1d1f83f60e6], Progress(?%, ?/0), null)
      org.nuxeo.ecm.core.api.DocumentNotFoundException: 5eb446d0-1ab6-4699-b23e-a1d1f83f60e6
      	at org.nuxeo.ecm.core.storage.sql.coremodel.SQLSession.getDocumentByUUID(SQLSession.java:188) ~[nuxeo-core-storage-sql-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.api.AbstractSession.resolveReference(AbstractSession.java:315) ~[nuxeo-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.api.AbstractSession.getDocument(AbstractSession.java:917) ~[nuxeo-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.platform.tag.FacetedTagService.doCopyTags(FacetedTagService.java:171) ~[nuxeo-platform-tag-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.platform.tag.AbstractTagService.lambda$copyTags$5(AbstractTagService.java:177) ~[nuxeo-platform-tag-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.api.CoreInstance$4.run(CoreInstance.java:236) ~[nuxeo-core-api-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.api.UnrestrictedSessionRunner.runUnrestricted(UnrestrictedSessionRunner.java:112) ~[nuxeo-core-api-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.api.CoreInstance.doPrivileged(CoreInstance.java:238) ~[nuxeo-core-api-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.platform.tag.AbstractTagService.copyTags(AbstractTagService.java:176) ~[nuxeo-platform-tag-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.platform.tag.AbstractTagService.replaceTags(AbstractTagService.java:183) ~[nuxeo-platform-tag-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.platform.tag.TaggedVersionListener.handleEvent(TaggedVersionListener.java:85) ~[nuxeo-platform-tag-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.platform.tag.TaggedVersionListener.handleEvent(TaggedVersionListener.java:53) ~[nuxeo-platform-tag-core-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.event.impl.AsyncEventExecutor$ListenerWork.work(AsyncEventExecutor.java:221) [nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.work.AbstractWork.runWorkWithTransaction(AbstractWork.java:484) [nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.work.AbstractWork.run(AbstractWork.java:374) [nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.work.WorkHolder.run(WorkHolder.java:57) [nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.work.WorkComputation.processRecord(WorkComputation.java:102) [nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.lib.stream.computation.log.ComputationRunner.lambda$processRecordWithRetry$10(ComputationRunner.java:366) [nuxeo-stream-11.1-SNAPSHOT.jar:?]
      	at net.jodah.failsafe.Functions$10.call(Functions.java:252) [failsafe-1.1.0.jar:1.1.0]
      	at net.jodah.failsafe.SyncFailsafe.call(SyncFailsafe.java:145) [failsafe-1.1.0.jar:1.1.0]
      	at net.jodah.failsafe.SyncFailsafe.run(SyncFailsafe.java:81) [failsafe-1.1.0.jar:1.1.0]
      	at org.nuxeo.lib.stream.computation.log.ComputationRunner.processRecordWithRetry(ComputationRunner.java:366) [nuxeo-stream-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.lib.stream.computation.log.ComputationRunner.processRecord(ComputationRunner.java:349) [nuxeo-stream-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.lib.stream.computation.log.ComputationRunner.processLoop(ComputationRunner.java:239) [nuxeo-stream-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.lib.stream.computation.log.ComputationRunner.run(ComputationRunner.java:184) [nuxeo-stream-11.1-SNAPSHOT.jar:?]
      	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
      	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
      	at java.lang.Thread.run(Thread.java:834) [?:?]
      

      Also after 2 retries the work fails:

      2019-09-13T19:46:39,885 ERROR [defaultPool-01,in:77,inCheckpoint:77,out:0,lastRead:1568403999737,lastTimer:0,wm:205573849043304449,loop:199,checkpoint] [org.nuxeo.ecm.core.work.WorkComputation] Skip Work in failure: id: 22567986446780080.1928188938, title: Listener taggedVersionListener [documentRestored/5eb446d0-1ab6-4699-b23e-a1d1f83f60e6], offset: default-05:+35, record: Record{watermark=205573849031507968, wmDate=2019-09-13 19:46:39.569, flags=[DEFAULT], key='5eb446d0-1ab6-4699-b23e-a1d1f83f60e6', data.length=3760, data="....sr.=org.nuxeo.ecm.core.event.impl.AsyncEventExecutor$ListenerWork...........I..retryCountL..bundlet.1Lorg/nuxeo/ecm/core/ev"}, thread: defaultPool-01,in:77,inCheckpoint:77,out:0,lastRead:1568403999737,lastTimer:0,wm:205573849043304449,loop:199,checkpoint
      2019-09-13T19:46:39,886 ERROR [defaultPool-01,in:77,inCheckpoint:77,out:0,lastRead:1568403999737,lastTimer:0,wm:205573849043304449,loop:199,checkpoint] [org.nuxeo.ecm.core.work.AbstractWork] Exception during work: ListenerWork(Listener taggedVersionListener [documentRestored/5eb446d0-1ab6-4699-b23e-a1d1f83f60e6], Progress(?%, ?/0), null)
      org.nuxeo.ecm.core.api.NuxeoException: Work failed after 2 retries, class=class org.nuxeo.ecm.core.event.impl.AsyncEventExecutor$ListenerWork id=22567986446780080.1928188938 category=taggedVersionListener title=Listener taggedVersionListener [documentRestored/5eb446d0-1ab6-4699-b23e-a1d1f83f60e6]
      	at org.nuxeo.ecm.core.work.AbstractWork.workFailed(AbstractWork.java:430) ~[nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.work.AbstractWork.run(AbstractWork.java:386) ~[nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.work.WorkHolder.run(WorkHolder.java:57) ~[nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      	at org.nuxeo.ecm.core.work.WorkComputation.processRecord(WorkComputation.java:102) [nuxeo-core-event-11.1-SNAPSHOT.jar:?]
      

      Something is different with the latency/visibility when using Kafka. See NXP-25808 which has already fix some document not found in listeners.

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 3 hours
                  3h