Background CE tasks get cancelled randomly

Hello,

We have Jenkins jobs that trigger Sonar Analysis and then pull (every 5 seconds) to check if the background CE task is done in order to retrieve the Quality Gate status.

Since we have update Sonar to 7.6, we noticed that these background CE tasks get CANCELLED sometimes, there’s no absolute behavior, sometimes it goes well, sometimes it get cancelled. There is no external action performed by anyone to cancel the tasks (I’ve check the Sonar access.log).
I’ve noticed that the following exception is raised for the task that get cancelled.

Any idea ?
Thanks.

Sonar Version: 7.6 Developer Edition
Error observed:

2019.12.09 17:47:08 INFO ce[AW7rxLjExnGfOz0hTuG1][o.s.c.t.CeWorkerImpl] Executed task | project=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx | type=REPORT | branch=release/1.2 | branchType=LONG | id=AW7rxLjExnGfOz0hTuG1 | submitter=jenkins | status=SUCCESS | time=58568ms
2019.12.09 17:49:34 INFO ce[o.s.c.t.CeWorkerImpl] Execute task | project=xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx | type=REPORT | branch=develop | branchType=LONG | id=AW7rx9k0xnGfOz0hTuG7 | submitter=jenkins
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Extract report | status=SUCCESS | time=467ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist scanner context | status=SUCCESS | time=13ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Propagate analysis warnings from scanner report | status=SUCCESS | time=0ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Execute DB migrations for current project | status=SUCCESS | time=22ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Generate analysis UUID | status=SUCCESS | time=0ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Load analysis metadata | status=SUCCESS | time=35ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Initialize | status=SUCCESS | time=12ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Verify billing | status=SUCCESS | time=0ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Build tree of components | components=980 | status=SUCCESS | time=52ms
2019.12.09 17:49:34 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Validate project | status=SUCCESS | time=10ms
2019.12.09 17:49:35 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Load quality profiles | status=SUCCESS | time=215ms
2019.12.09 17:49:35 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Load Quality gate | status=SUCCESS | time=12ms
2019.12.09 17:49:35 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Load new code period | status=SUCCESS | time=14ms
2019.12.09 17:49:35 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Detect file moves | reportFiles=727 | dbFiles=727 | addedFiles=0 | status=SUCCESS | time=17ms
2019.12.09 17:49:35 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Load duplications | duplications=516 | status=SUCCESS | time=23ms
2019.12.09 17:49:35 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute cross project duplications | status=SUCCESS | time=0ms
2019.12.09 17:49:35 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute size measures | status=SUCCESS | time=56ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute new coverage | status=SUCCESS | time=4608ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute coverage measures | status=SUCCESS | time=3ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute comment measures | status=SUCCESS | time=3ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Copy custom measures | status=SUCCESS | time=6ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute duplication measures | status=SUCCESS | time=3ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute duplication data measures | status=SUCCESS | time=16ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute size measures on new code | status=SUCCESS | time=6ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute language distribution | status=SUCCESS | time=2ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute test measures | status=SUCCESS | time=1ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute complexity measures | status=SUCCESS | time=4ms
2019.12.09 17:49:39 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Load measure computers | status=SUCCESS | time=0ms
2019.12.09 17:49:40 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute Quality Profile status | status=SUCCESS | time=14ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Execute component visitors | status=SUCCESS | time=10563ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Checks executed after computation of measures | status=SUCCESS | time=20ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute Quality Gate measures | status=SUCCESS | time=0ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Compute Quality profile measures | status=SUCCESS | time=1ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Generate Quality profile events | status=SUCCESS | time=12ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Generate Quality gate events | status=SUCCESS | time=10ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist components | status=SUCCESS | time=49ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist analysis | status=SUCCESS | time=9ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist analysis properties | status=SUCCESS | time=9ms
2019.12.09 17:49:50 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist measures | inserts=90 | status=SUCCESS | time=14ms
2019.12.09 17:50:53 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist live measures | insertsOrUpdates=41034 | status=SUCCESS | time=63166ms
2019.12.09 17:50:53 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist new ad hoc Rules | status=SUCCESS | time=0ms
2019.12.09 17:50:57 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist issues | inserts=0 | updates=172 | merged=0 | untouched=6457 | status=SUCCESS | time=3741ms
2019.12.09 17:50:57 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist project links | status=SUCCESS | time=7ms
2019.12.09 17:50:57 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist events | status=SUCCESS | time=8ms
2019.12.09 17:50:58 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist sources | status=SUCCESS | time=669ms
2019.12.09 17:50:58 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Persist cross project duplications | status=SUCCESS | time=0ms
2019.12.09 17:50:58 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Enable analysis | status=SUCCESS | time=27ms
2019.12.09 17:50:58 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Update last usage date of quality profiles | status=SUCCESS | time=46ms
2019.12.09 17:50:58 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Purge db | status=SUCCESS | time=220ms
2019.12.09 17:51:00 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Index analysis | status=SUCCESS | time=1783ms
2019.12.09 17:51:07 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Send issue notifications | newIssuesNotifs=0 | newIssuesDeliveries=0 | myNewIssuesNotifs=0 | myNewIssuesDeliveries=0 | changesNotifs=0 | changesDeliveries=0 | status=SUCCESS | time=7331ms
2019.12.09 17:51:07 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Publish task results | status=SUCCESS | time=0ms
2019.12.09 17:51:07 INFO ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.s.ComputationStepExecutor] Trigger refresh of Portfolios and Applications | status=SUCCESS | time=0ms
2019.12.09 17:51:08 ERROR ce[AW7rx9k0xnGfOz0hTuG7][o.s.c.t.CeWorkerImpl] Failed to finalize task with uuid ‘AW7rx9k0xnGfOz0hTuG7’ and persist its state to db
java.lang.IllegalStateException: Task does not exist anymore: CeTask{organizationUuid=AVqPSOrIKVORlXH-mOsO, type=REPORT, uuid=AW7rx9k0xnGfOz0hTuG7, component=Component{uuid=‘AWaBNoVTohFSohNhTLSs’, key=‘xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx’, name=‘xxxxxxxx’}, mainComponent=Component{uuid=‘AWaBNoVTohFSohNhTLSs’, key=‘xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx’, name=‘xxxxxxxx’}, submitter=User{uuid=‘jenkins’, login=‘jenkins’}}
at org.sonar.ce.queue.InternalCeQueueImpl.lambda$remove$0(InternalCeQueueImpl.java:118)
at java.util.Optional.orElseThrow(Optional.java:290)
at org.sonar.ce.queue.InternalCeQueueImpl.remove(InternalCeQueueImpl.java:118)
at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.finalizeTask(CeWorkerImpl.java:240)
at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.afterExecute(CeWorkerImpl.java:234)
at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.close(CeWorkerImpl.java:194)
at org.sonar.ce.taskprocessor.CeWorkerImpl.findAndProcessTask(CeWorkerImpl.java:157)
at org.sonar.ce.taskprocessor.CeWorkerImpl$TrackRunningState.get(CeWorkerImpl.java:131)
at org.sonar.ce.taskprocessor.CeWorkerImpl.call(CeWorkerImpl.java:83)
at org.sonar.ce.taskprocessor.CeWorkerImpl.call(CeWorkerImpl.java:51)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Hi,

Someone else recently tracked similar reports to running out of resources on the SonarQube server during the processing of very large analysis reports. Could that be happening in your case?

 
Ann