-
Type: Bug
-
Status: Resolved
-
Priority: Minor
-
Resolution: Fixed
-
Affects Version/s: 11.1-SNAPSHOT
-
Component/s: Tagging
-
Tags:
-
Team:PLATFORM
-
Sprint:nxplatform 11.1.22, nxplatform 11.1.23, nxplatform 11.1.24
-
Story Points:3
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.