Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-50199

Failed pipeline jobs stuck running after incorrect resume

    XMLWordPrintable

    Details

    • Sprint:
      Pipeline - April 2018
    • Similar Issues:

      Description

      Setup

      Jenkins v2.89.4 LTS
      Pipeline API Plugin: 2.26
      Pipeline Nodes and Processes Plugin: 2.19
      Durable Task Plugin: 1.18
      Pipeline Job Plugin: 2.17
      Pipeline Shared Groovy Libraries Plugin: 2.9
      Pipeline Supporting APIs Plugin: 2.18
      Pipeline Groovy Plugin: 2.45
      Script Security Plugin: 1.41

      Pipeline Default Speed/Durability Level: Performance-Optimized
      "Do not allow the pipeline to resume if the master restarts": Enabled on all jobs

      Problem

      I logged into a Jenkins master and saw no builds running but there was a queue of about 10 jobs. When mousing over the queued jobs, I saw "pending - Already running 2 builds across all nodes". This is strange because no jobs were showing as running and no Jenkins agents or executors were showing any running builds.

      I then ran "http://xx.xxx.xxx.xxx:8080/computer/api/xml?tree=computer[executors[currentExecutable[url]],oneOffExecutors[currentExecutable[url]]]&xpath=//url&wrapper=builds" which did show 5 builds were running. I checked these builds and they were red (failure) and were not running.

      Research

      I checked the console log of a build that showed as running but isn't and saw the line below near the top of the log.

      Resume disabled by user, switching to high-performance, low-durability mode.

      At the end of the of the log I saw the following:

      Finished: FAILURE
      Resuming build at Tue Mar 13 23:04:52 UTC 2018 after Jenkins restart

      Why Resume Build?

      The build failed on Mar 12, 2018 6:02:37 PM.
      Why did the build try to resume almost a day later? The job and system durability are configured to not resume builds. Below are some details taken from the API for the build.

      _class "hudson.model.OneOffExecutor"
      id "41"
      keepLog false
      number 41
      queueId 7178
      result "FAILURE"
      timestamp 1520877757466

      I checked the Java process on the server and it was last restarted on March 02 2018.

      What triggered the "Jenkins restart" identified on Mar 13 23:04:52 UTC 2018 since the Java process was not restarted?

      Why does this get the build stuck in a "running" state when it's not running?

      Scope

      This issue can be seen across many of our Jenkins masters. In each case we see "Resuming build at xxxxx after Jenkins restart" occur a few days after the build failure or abort even though Java was not restarted. This issue didn't occur on Jenkins 2.60.3 running the older (pre-durability configurable) Pipeline plugins.

      Logs

      I checked the jenkins.log file and saw the following when the build was attempting to be resumed.

       

      Mar 13, 2018 9:29:56 PM org.jenkinsci.plugins.workflow.cps.CpsFlowExecution onLoad
       WARNING: Pipeline state not properly persisted, cannot resume job/JENKINS-JOB-NAME1/42/
      
       Mar 13, 2018 9:29:56 PM org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService reportProblem
       WARNING: Unexpected exception in CPS VM thread: CpsFlowExecution[OwnerJENKINS-JOB-NAME1/42:JENKINS-JOB-NAME1 #42]
       java.lang.NullPointerException
       at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:997)
       at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1368)
       at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:412)
       at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:35)
       at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
       at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
       at java.util.concurrent.FutureTask.run(FutureTask.java:266)
       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)
      
      Mar 13, 2018 9:29:56 PM org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService reportProblem
       WARNING: Unexpected exception in CPS VM thread: CpsFlowExecution[OwnerJENKINS-JOB-NAME1/42:JENKINS-JOB-NAME1 #42]
       java.lang.NullPointerException
       at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:997)
       at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1368)
       at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:412)
       at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:35)
       at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
       at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
       at java.util.concurrent.FutureTask.run(FutureTask.java:266)
       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)
      
      Mar 13, 2018 9:29:56 PM org.jenkinsci.plugins.workflow.cps.CpsFlowExecution onLoad
       WARNING: Pipeline state not properly persisted, cannot resume job/JENKINS-JOB-NAME1/40/
      
       Mar 13, 2018 9:29:56 PM org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService reportProblem
       WARNING: Unexpected exception in CPS VM thread: CpsFlowExecution[OwnerJENKINS-JOB-NAME1/40:JENKINS-JOB-NAME1 #40]
       java.lang.NullPointerException
       at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:997)
       at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1368)
       at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:412)
       at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:35)
       at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
       at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
       at java.util.concurrent.FutureTask.run(FutureTask.java:266)
       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)
      
      Mar 13, 2018 9:29:56 PM org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService reportProblem
       WARNING: Unexpected exception in CPS VM thread: CpsFlowExecution[OwnerJENKINS-JOB-NAME1/40:JENKINS-JOB-NAME1 #40]
       java.lang.NullPointerException
       at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:997)
       at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1368)
       at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:412)
       at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:35)
       at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
       at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
       at java.util.concurrent.FutureTask.run(FutureTask.java:266)
       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)
      
      Mar 13, 2018 11:04:52 PM org.jenkinsci.plugins.workflow.cps.CpsFlowExecution onLoad
       WARNING: Pipeline state not properly persisted, cannot resume job/JENKINS-JOB-NAME2/41/
      
       Mar 13, 2018 11:04:52 PM org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService reportProblem
       WARNING: Unexpected exception in CPS VM thread: CpsFlowExecution[OwnerJENKINS-JOB-NAME2/41:JENKINS-JOB-NAME2 #41]
       java.lang.NullPointerException
       at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:997)
       at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1368)
       at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:412)
       at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:35)
       at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
       at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
       at java.util.concurrent.FutureTask.run(FutureTask.java:266)
       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)
      
      Mar 13, 2018 11:04:52 PM org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService reportProblem
       WARNING: Unexpected exception in CPS VM thread: CpsFlowExecution[OwnerJENKINS-JOB-NAME2/41:JENKINS-JOB-NAME2 #41]
       java.lang.NullPointerException
       at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:997)
       at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1368)
       at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:412)
       at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:35)
       at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
       at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
       at java.util.concurrent.FutureTask.run(FutureTask.java:266)
       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)
      

       

      Thread Dump

      I only saw WorkflowRun.copyLogs with workflow in the name in a thread dump so I'm not sure if it is related. I didn't see anything BLOCKING. A lot of different items were WAITING on "java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject".

      "WorkflowRun.copyLogs [#3]" Id=8829 Group=main TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@477b1566
       at sun.misc.Unsafe.park(Native Method)
       - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@477b1566
       at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
       at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
       at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
       at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
       at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
       at java.lang.Thread.run(Thread.java:748)
      
      "WorkflowRun.copyLogs [#4]" Id=8830 Group=main WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@477b1566
       at sun.misc.Unsafe.park(Native Method)
       - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@477b1566
       at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
       at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
       at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
       at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
       at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
       at java.lang.Thread.run(Thread.java:748)
      

      Workaround

      Running the Jenkins script below will set the running build to aborted to work around the issue.

      Jenkins.instance.getItemByFullName("JOBNAME").getBuildByNumber(JOB#).finish(hudson.model.Result.ABORTED, new java.io.IOException("Aborting build"));

        Attachments

        1. build.log
          0.4 kB
        2. build.xml
          10 kB
        3. build.xml
          1 kB
        4. flownode-84.xml
          21 kB
        5. flowNodeStore.xml
          4 kB
        6. workflow-cps.hpi
          548 kB
        7. workflow-cps.hpi
          540 kB
        8. workflow-cps.hpi
          540 kB
        9. workflow-fallback-flowNodeStore.xml
          7 kB
        10. workflow-job.hpi
          112 kB
        11. workflow-job.hpi
          110 kB
        12. workflow-job.hpi
          110 kB
        13. workflows.xml
          5 kB

          Issue Links

            Activity

            Hide
            svanoort Sam Van Oort added a comment - - edited

            Mike Kozell Also I think we're clear for release of this now – but I'm aiming to delay until at least tonight EST if that'll permit enough time to land it on some real-world Jenkins masters as a sanity check.

            Show
            svanoort Sam Van Oort added a comment - - edited Mike Kozell Also I think we're clear for release of this now – but I'm aiming to delay until at least tonight EST if that'll permit enough time to land it on some real-world Jenkins masters as a sanity check.
            Hide
            svanoort Sam Van Oort added a comment -

            Mike Kozell Are you building on Windows, by any chance? I'd try to set the platform encoding to UTF-8 – that error is safe to ignore though. You can comment out the whole test by adding "@Ignore" to src/test/java/org/jenkinsci/plugins/workflow/job/CLITest.java on line 85.

            Show
            svanoort Sam Van Oort added a comment - Mike Kozell Are you building on Windows, by any chance? I'd try to set the platform encoding to UTF-8 – that error is safe to ignore though. You can comment out the whole test by adding "@Ignore" to src/test/java/org/jenkinsci/plugins/workflow/job/CLITest.java on line 85.
            Hide
            svanoort Sam Van Oort added a comment -

            Fixes released with workflow-cps 2.50 and workflow-job 2.21 – would really appreciate if you guys could install the latest and confirm the issue is resolved.

            CCMike Kozell Matt Gaspar

            Show
            svanoort Sam Van Oort added a comment - Fixes released with workflow-cps 2.50 and workflow-job 2.21 – would really appreciate if you guys could install the latest and confirm the issue is resolved. CC Mike Kozell Matt Gaspar
            Hide
            svanoort Sam Van Oort added a comment -

            Mike Kozell That is... the exact opposite of what I would expect. Not sure what's going on there, since the ci.jenkins.io builder does both Windows and Linux builds and they succeed. Weird.

            Show
            svanoort Sam Van Oort added a comment - Mike Kozell That is... the exact opposite of what I would expect. Not sure what's going on there, since the ci.jenkins.io builder does both Windows and Linux builds and they succeed. Weird.
            Hide
            vqrs Christian V added a comment -

            I'm also seeing this:

            org.jenkinsci.remoting.util.ExecutorServiceUtils$FatalRejectedExecutionException: Cannot execute the command java.util.concurrent.FutureTask@134626b. The executor service is shutting down
            
            at hudson.remoting.SingleLaneExecutorService.execute(SingleLaneExecutorService.java:108)
            
            at java.util.concurrent.AbstractExecutorService.submit(Unknown Source)
            
            at com.google.common.util.concurrent.ForwardingExecutorService.submit(ForwardingExecutorService.java:110)
            
            at jenkins.util.InterceptingExecutorService.submit(InterceptingExecutorService.java:49)
            
            at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution$4.onSuccess(CpsFlowExecution.java:903)
            
            at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution$4.onSuccess(CpsFlowExecution.java:899)
            
            at org.jenkinsci.plugins.workflow.support.concurrent.Futures$1.run(Futures.java:150)
            
            at com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:253)
            
            at com.google.common.util.concurrent.ExecutionList$RunnableExecutorPair.execute(ExecutionList.java:149)
            
            at com.google.common.util.concurrent.ExecutionList.add(ExecutionList.java:105)
            
            at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:155)
            
            at org.jenkinsci.plugins.workflow.support.concurrent.Futures.addCallback(Futures.java:160)
            
            at org.jenkinsci.plugins.workflow.support.concurrent.Futures.addCallback(Futures.java:90)
            
            at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.runInCpsVmThread(CpsFlowExecution.java:899)
            
            at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.getCurrentExecutions(CpsFlowExecution.java:977)
            
            at org.jenkinsci.plugins.workflow.flow.FlowExecutionList$ItemListenerImpl.onLoaded(FlowExecutionList.java:180)
            
            at jenkins.model.Jenkins.<init>(Jenkins.java:972)
            
            at hudson.model.Hudson.<init>(Hudson.java:85)
            
            at hudson.model.Hudson.<init>(Hudson.java:81)
            
            at hudson.WebAppMain$3.run(WebAppMain.java:233)

             

            I have updated to the latest Jenkins version and all my Pipeline plugins are up to date. This happened before the update, after the plugin updates, and after updating Jenkins. It's always the same exception.

            Show
            vqrs Christian V added a comment - I'm also seeing this: org.jenkinsci.remoting.util.ExecutorServiceUtils$FatalRejectedExecutionException: Cannot execute the command java.util.concurrent.FutureTask@134626b. The executor service is shutting down at hudson.remoting.SingleLaneExecutorService.execute(SingleLaneExecutorService.java:108) at java.util.concurrent.AbstractExecutorService.submit(Unknown Source) at com.google.common.util.concurrent.ForwardingExecutorService.submit(ForwardingExecutorService.java:110) at jenkins.util.InterceptingExecutorService.submit(InterceptingExecutorService.java:49) at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution$4.onSuccess(CpsFlowExecution.java:903) at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution$4.onSuccess(CpsFlowExecution.java:899) at org.jenkinsci.plugins.workflow.support.concurrent.Futures$1.run(Futures.java:150) at com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:253) at com.google.common.util.concurrent.ExecutionList$RunnableExecutorPair.execute(ExecutionList.java:149) at com.google.common.util.concurrent.ExecutionList.add(ExecutionList.java:105) at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:155) at org.jenkinsci.plugins.workflow.support.concurrent.Futures.addCallback(Futures.java:160) at org.jenkinsci.plugins.workflow.support.concurrent.Futures.addCallback(Futures.java:90) at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.runInCpsVmThread(CpsFlowExecution.java:899) at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.getCurrentExecutions(CpsFlowExecution.java:977) at org.jenkinsci.plugins.workflow.flow.FlowExecutionList$ItemListenerImpl.onLoaded(FlowExecutionList.java:180) at jenkins.model.Jenkins.<init>(Jenkins.java:972) at hudson.model.Hudson.<init>(Hudson.java:85) at hudson.model.Hudson.<init>(Hudson.java:81) at hudson.WebAppMain$3.run(WebAppMain.java:233)   I have updated to the latest Jenkins version and all my Pipeline plugins are up to date. This happened before the update, after the plugin updates, and after updating Jenkins. It's always the same exception.

              People

              • Assignee:
                svanoort Sam Van Oort
                Reporter:
                mkozell Mike Kozell
              • Votes:
                3 Vote for this issue
                Watchers:
                10 Start watching this issue

                Dates

                • Created:
                  Updated: