Recover gracefully when a `PlaceholderTask` is in the queue but the associated build is complete #185

dwnusbaum · 2021-12-01T21:01:20Z

While testing Jenkins in various backup and restore scenarios, we ran into a case where the Jenkins queue contained a ExecutorStepExecution.PlaceholderTask whose associated build was already complete, causing the task to sit in the queue forever. We are not sure how this happened or how to reproduce it, but this PR adds a test that reproduces the same symptoms that may be useful for future investigation.

I did some experimentation to see if the issue could be fixed, and something like this does fix it but does not seem like the best approach:

diff --git a/src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java b/src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java
index c81bf0c..64ca128 100644
--- a/src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java
+++ b/src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java
@@ -360,6 +360,10 @@ public class ExecutorStepExecution extends AbstractStepExecutionImpl {
         }
 
         private Object readResolve() {
+            Run<?, ?> run = runForDisplay();
+            if (run != null && !run.isLogUpdated()) {
+                return null;
+            }
             if (cookie != null) {
                 synchronized (runningTasks) {
                     runningTasks.put(cookie, new RunningTask());

A patch like this would cause Pipeline builds to be loaded and resumed from inside of Queue.load while the queue lock is held during Jenkins startup, which seems concerning. Accessing any context variables via StepContext.get would have the same problem because CpsStepContext.doGet transitively calls getThreadGroupSynchronously which has to load the WorkflowRun and resume the Pipeline. Perhaps we could expose CpsStepContext.isComplete as a new method on StepContext and check that instead, but I'm not sure. Queue.load does explicitly handle the case where a task is null, although maybe there is a better way to remove the task from the queue.

Given @jglick is working on stuff related to resumption of the node step in #180, it seems best not to try to make a speculative fix right now.

Make sure you are opening from a topic/feature/bugfix branch (right side) and not your main branch!
Ensure that the pull request title represents the desired changelog entry
Please describe what you did
Link to relevant issues in GitHub or Jira
Link to relevant pull requests, esp. upstream and downstream changes
Ensure you have provided tests - that demonstrates feature works or fixes the issue

…ciated build is complete

jglick · 2021-12-01T21:17:22Z

I need to think about the interaction with #180.

src/test/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepTest.java

Co-authored-by: Jesse Glick <jglick@cloudbees.com>

src/test/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepTest.java

dwnusbaum · 2021-12-02T20:39:59Z

Moving back to draft to wait for a release of jenkinsci/jenkins-test-harness#353 and to investigate jenkinsci/workflow-cps-plugin#490 (comment).

jglick

A QueueDecisionHandler might fix the real bug, but not the problem path tested here. You could add a QueueTaskDispatcher whose canRun cancels the item if it matches this condition, which avoids the problems with readResolve but on the other hand adds overhead to a critical code path for what I guess is a rare case. Maybe you could implement a fix in PlaceholderTask.getAssignedLabel or getAffinityKey or some similar method Queue.maintain is guaranteed to call, cancelling itself (perhaps asynchronously via Timer to avoid weird reëntrancy issues)?

pom.xml

dwnusbaum · 2021-12-03T18:37:03Z

FWIW I looked into exposing CpsStepContext.isCompleted as an API on StepContext to be able to check if the step completed without having to load the build in PlaceholderTask.readResolve, but then I realized that kind of fix would be useless for my test case since the serialized CpsStepContext would be outdated and so isCompleted would return false.

Maybe you could implement a fix in PlaceholderTask.getAssignedLabel or getAffinityKey or some similar method Queue.maintain is guaranteed to call, cancelling itself (perhaps asynchronously via Timer to avoid weird reëntrancy issues)?

Yeah I was thinking about something like this. I will spend a bit of time looking into it.

src/test/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepTest.java

…if so, block execution and cancel task

dwnusbaum · 2021-12-03T20:55:17Z

src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java

@@ -422,6 +422,22 @@ public String getCookie() {
        }

        @Override public CauseOfBlockage getCauseOfBlockage() {
+            Run<?, ?> run = runForDisplay();


I think this is safe. If we get here for a step that is just starting or resuming, then the run is already loaded and so this should complete quickly. The only time this should be slow is if this is after a Jenkins restart and the build has already completed so we end up here without the build having been loaded via some other route and we trigger the cancellation path.

dwnusbaum · 2021-12-03T20:56:40Z

src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java

+                return new CauseOfBlockage() {
+                    @Override
+                    public String getShortDescription() {
+                        return "Stopping " + getDisplayName();
+                    }
+                };


Not sure if an anonymous class or hard-coded text is ok here. My thought was that this cause should not usually be around long enough for anyone to see it, but I guess we should set up localization just in case.

An anonymous class should be fine here. As you say, it ought not appear in the GUI for more than a moment if at all.

dwnusbaum · 2021-12-03T20:58:59Z

@jglick let me know what you think of 9d8eeca. If you think there are some problems with that approach then I'll just revert that commit and leave the test ignored for now.

jglick

Looks reasonable to me.

src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java

jglick · 2021-12-03T21:27:17Z

src/main/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepExecution.java

+                return new CauseOfBlockage() {
+                    @Override
+                    public String getShortDescription() {
+                        return "Stopping " + getDisplayName();
+                    }
+                };


An anonymous class should be fine here. As you say, it ought not appear in the GUI for more than a moment if at all.

Co-authored-by: Jesse Glick <jglick@cloudbees.com>

dduportal · 2021-12-06T08:01:33Z

The issue described (and fixed) by this PR happens quite often on restarts of ci.jenkins.io (but not on other instances owned by the infra team).
Would you want us to try this change on ci.jenkins in advance? I'm asking because I'm not sure to really get all the impacts that it could have, but since ci.jenkins.io is basically a giant infinite retry loop for its jobs, that should not cause harm while allowing the "rare" bug to be caught and tried. Let us know?

jglick · 2021-12-06T14:13:51Z

@dduportal sure, if you want to install an incremental build (assuming all dependencies are met) and be prepared to roll back at the first sign of trouble, that would be great.

Somehow https://repo.jenkins-ci.org/incrementals/org/jenkins-ci/plugins/workflow/workflow-durable-task-step/1107.ve0b5abf0ca7f/ is dead. Not sure why; https://ci.jenkins.io/job/Plugins/job/workflow-durable-task-step-plugin/job/PR-185/5/console claims to have deployed as the status check confirms. @daniel-beck any clue?

jglick · 2021-12-06T14:14:45Z

CD is also set up here, so if @car-roll merges, then you should have an official release version within the hour.

car-roll · 2021-12-06T15:28:50Z

I can go ahead and merge. Was just waiting for @dduportal 's comments.

jglick · 2021-12-06T15:52:57Z

And there we go @dduportal: https://github.com/jenkinsci/workflow-durable-task-step-plugin/releases/tag/1102.v9c8d2f466adb (should be on UC shortly)

jglick · 2021-12-06T20:19:42Z

src/test/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepTest.java

+            assertThat(logging.getMessages(), hasItem(startsWith("Refusing to build ExecutorStepExecution.PlaceholderTask{runId=p#")));
+        });
+    }
+


BTW the reason there was no newline here before is that this step was a @TestExtension of the test formerly above it, now with the new test intervening.

dduportal · 2021-12-22T15:47:16Z

And there we go @dduportal: https://github.com/jenkinsci/workflow-durable-task-step-plugin/releases/tag/1102.v9c8d2f466adb (should be on UC shortly)

Installed, tested and approved: last restart did not triggered "ghosh" builds in the queue. Many thanks for this \o/

dwnusbaum · 2021-12-22T15:55:15Z

@dduportal do you see messages of the form "Refusing to build <...> and cancelling it because associated build is complete" in the Jenkins system logs? What about "Resuming <...>, which is missing from FlowExecutionList (<...>), so registering it now"?

dduportal · 2021-12-22T16:22:54Z

@dduportal do you see messages of the form "Refusing to build <...> and cancelling it because associated build is complete" in the Jenkins system logs? What about "Resuming <...>, which is missing from FlowExecutionList (<...>), so registering it now"?

Yes, just retried a restart and got the following message:

Dec 22, 2021 4:21:02 PM WARNING org.jenkinsci.plugins.workflow.support.steps.ExecutorStepExecution$PlaceholderTask getCauseOfBlockage

Refusing to build ExecutorStepExecution.PlaceholderTask{runId=Plugins/declarative-pipeline-migration-assistant-plugin/PR-117#1,label=maven-windows,context=CpsStepContext[13:null]:Owner[Plugins/declarative-pipeline-migration-assistant-plugin/PR-117/1:Plugins/declarative-pipeline-migration-assistant-plugin/PR-117 #1],cookie=null,auth=null} and cancelling it because associated build is complete

dwnusbaum · 2021-12-22T16:29:07Z

Hmm, it's somewhat concerning to me that you are seeing those messages just on a regular restart. Thanks for confirming though!

…ut the associated build is complete (jenkinsci#185)" This reverts commit 9c8d2f4.

Add ignored test where a PlaceholderTask is in the queue but the asso…

8db0ae1

…ciated build is complete

dwnusbaum requested a review from jglick December 1, 2021 21:01

jglick requested a review from dduportal December 1, 2021 21:18

jglick approved these changes Dec 1, 2021

View reviewed changes

src/test/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepTest.java Outdated Show resolved Hide resolved

Update annotation to explain why test is ignored

d0632af

Co-authored-by: Jesse Glick <jglick@cloudbees.com>

jglick requested a review from car-roll December 1, 2021 21:23

jglick added the tests label Dec 1, 2021

jglick changed the title ~~Add ignored test where a PlaceholderTask is in the queue but the associated build is complete~~ Add ignored test where a PlaceholderTask is in the queue but the associated build is complete Dec 1, 2021

dwnusbaum commented Dec 1, 2021

View reviewed changes

src/test/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepTest.java Outdated Show resolved Hide resolved

This was referenced Dec 2, 2021

Add new JenkinsSessionRule.getHome method jenkinsci/jenkins-test-harness#353

Merged

Avoid printing warnings from CpsStepContext.completed jenkinsci/workflow-cps-plugin#490

Merged

Simplify test using JenkinsSessionRule.getHome and TemporaryFolder

3abef26

dwnusbaum marked this pull request as draft December 2, 2021 20:39

jglick approved these changes Dec 2, 2021

View reviewed changes

pom.xml Outdated Show resolved Hide resolved

dwnusbaum commented Dec 3, 2021

View reviewed changes

src/test/java/org/jenkinsci/plugins/workflow/support/steps/ExecutorStepTest.java Outdated Show resolved Hide resolved

dwnusbaum added 2 commits December 3, 2021 15:50

De-flake test and update to released version of jenkins-test-harness

00cdd69

Check if build is complete in PlaceholderTask.getCauseOfBlockage and …

9d8eeca

…if so, block execution and cancel task

dwnusbaum commented Dec 3, 2021

View reviewed changes

dwnusbaum requested a review from jglick December 3, 2021 20:58

dwnusbaum marked this pull request as ready for review December 3, 2021 20:58

jglick approved these changes Dec 3, 2021

View reviewed changes

jglick added bug and removed tests labels Dec 3, 2021

jglick changed the title ~~Add ignored test where a PlaceholderTask is in the queue but the associated build is complete~~ Recover gracefully when a PlaceholderTask is in the queue but the associated build is complete Dec 3, 2021

Simplify lambda in PlaceholderTask.getCauseOfBlockage

e0b5abf

Co-authored-by: Jesse Glick <jglick@cloudbees.com>

car-roll approved these changes Dec 6, 2021

View reviewed changes

car-roll merged commit 9c8d2f4 into jenkinsci:master Dec 6, 2021

jglick reviewed Dec 6, 2021

View reviewed changes

This was referenced Dec 15, 2021

[JENKINS-67351] Avoid deadlock when resuming Pipelines in some cases jenkinsci/workflow-api-plugin#188

Merged

[JENKINS-67351] Do not load Pipelines during PlaceholderTask.getCauseOfBlockage in normal scenarios #188

Merged

dwnusbaum deleted the stale-placeholdertask branch December 22, 2021 15:53

dwnusbaum added a commit to dwnusbaum/workflow-durable-task-step-plugin that referenced this pull request Jan 14, 2022

Revert "Recover gracefully when a PlaceholderTask is in the queue b…

6de78ce

…ut the associated build is complete (jenkinsci#185)" This reverts commit 9c8d2f4.

dwnusbaum added a commit to dwnusbaum/workflow-durable-task-step-plugin that referenced this pull request Jan 14, 2022

Revert "Recover gracefully when a PlaceholderTask is in the queue b…

185989a

…ut the associated build is complete (jenkinsci#185)" This reverts commit 9c8d2f4.

This was referenced Jan 14, 2022

Revert fixes related to JENKINS-67351 and JENKINS-67164 #197

Merged

Revert fixes related to JENKINS-67351 and JENKINS-67164 jenkinsci/workflow-api-plugin#198

Merged

jglick mentioned this pull request May 11, 2022

Recover gracefully when a PlaceholderTask is in the queue but the associated build is complete (II) #226

Merged

dwnusbaum mentioned this pull request Aug 8, 2022

Try to remove items from completed builds even if supposedly already cancelled #259

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Recover gracefully when a `PlaceholderTask` is in the queue but the associated build is complete #185

Recover gracefully when a `PlaceholderTask` is in the queue but the associated build is complete #185

dwnusbaum commented Dec 1, 2021

jglick commented Dec 1, 2021

dwnusbaum commented Dec 2, 2021

jglick left a comment

dwnusbaum commented Dec 3, 2021

dwnusbaum Dec 3, 2021

dwnusbaum Dec 3, 2021

jglick Dec 3, 2021

dwnusbaum commented Dec 3, 2021

jglick left a comment

jglick Dec 3, 2021

dduportal commented Dec 6, 2021

jglick commented Dec 6, 2021

jglick commented Dec 6, 2021

car-roll commented Dec 6, 2021

jglick commented Dec 6, 2021

jglick Dec 6, 2021

dduportal commented Dec 22, 2021

dwnusbaum commented Dec 22, 2021

dduportal commented Dec 22, 2021

dwnusbaum commented Dec 22, 2021

Recover gracefully when a PlaceholderTask is in the queue but the associated build is complete #185

Recover gracefully when a PlaceholderTask is in the queue but the associated build is complete #185

Conversation

dwnusbaum commented Dec 1, 2021

jglick commented Dec 1, 2021

dwnusbaum commented Dec 2, 2021

jglick left a comment

Choose a reason for hiding this comment

dwnusbaum commented Dec 3, 2021

dwnusbaum Dec 3, 2021

Choose a reason for hiding this comment

dwnusbaum Dec 3, 2021

Choose a reason for hiding this comment

jglick Dec 3, 2021

Choose a reason for hiding this comment

dwnusbaum commented Dec 3, 2021

jglick left a comment

Choose a reason for hiding this comment

jglick Dec 3, 2021

Choose a reason for hiding this comment

dduportal commented Dec 6, 2021

jglick commented Dec 6, 2021

jglick commented Dec 6, 2021

car-roll commented Dec 6, 2021

jglick commented Dec 6, 2021

jglick Dec 6, 2021

Choose a reason for hiding this comment

dduportal commented Dec 22, 2021

dwnusbaum commented Dec 22, 2021

dduportal commented Dec 22, 2021

dwnusbaum commented Dec 22, 2021

Recover gracefully when a `PlaceholderTask` is in the queue but the associated build is complete #185

Recover gracefully when a `PlaceholderTask` is in the queue but the associated build is complete #185