[JENKINS-34637] Failure to kill bodies from timeout #76

jglick · 2016-10-18T22:44:17Z

Downstream of jenkinsci/workflow-support-plugin#20.

@reviewbybees esp. @kohsuke

…ure from its own body. Happens when stop() is implemented to call getContext().onFailure(cause), and something incorrectly calls stop on a non-innermost execution. Also providing much better diagnostics in other cases where a step seems to be completing twice.

…ameter, since in most cases we want to test sandboxed behavior.

…conditions.

…t the innermost execution, and block-scoped StepExecution.stop does not generally kill its body (JENKINS-26148). getCurrentExecutions was also in direct violation of its Javadoc, though it does not appear to have ever been called, much less tested.

jglick · 2016-10-18T22:45:07Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecution.java

@@ -172,29 +179,63 @@ private Continuable createContinuable(CpsThread currentThread, CpsCallableInvoca
    }

    @Override
-    public synchronized Collection<StepExecution> getCurrentExecutions() {
+    public Collection<StepExecution> getCurrentExecutions() {


This method was not involved in the original bug, but it was wrong too, in the same way.

jglick · 2016-10-18T22:45:24Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecution.java

+                        for (FlowNode node : scanner) {
+                            if (node.getId().equals(startNodeId)) {
+                                t.stop(stopped);
+                                break;


This is the main fix.

jglick · 2016-10-18T22:45:37Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsFlowDefinition.java

+    /**
+     * @deprecated use {@link #CpsFlowDefinition(String, boolean)} instead
+     */
+    @Deprecated


Not related, just on my to-do list for ages…

jglick · 2016-10-18T22:46:05Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsStepContext.java

+                for (CauseOfInterruption cause : ((FlowInterruptedException) failure).getCauses()) {
+                    if (cause instanceof BodyFailed) {
+                        LOGGER.log(Level.FINE, "already completed " + this + " and now received body failure", failure);
+                        // Predictable that the error would be thrown up here; quietly ignore it.


Otherwise we get an ugly stack trace when timing out.

jglick · 2016-10-18T22:46:52Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsThread.java

@@ -231,7 +231,7 @@ void fireCompletionHandlers(Outcome o) {
    /**
     * Finds the next younger {@link CpsThread} that shares the same {@link FlowHead}.
     *
-     * Can be {@code this.}
+     * Cannot be {@code this}.


Did not wind up using this function; another comment, at its sole call site, notes that it is probably wrong to use it there, too (but leaving that for another day).

jglick · 2016-10-18T22:47:12Z

src/main/java/org/jenkinsci/plugins/workflow/cps/steps/ParallelStep.java

@@ -126,7 +126,10 @@ public void onFailure(StepContext context, Throwable t) {
                if (handler.originalFailure == null) {
                    handler.originalFailure = new SimpleEntry<String, Throwable>(name, t);
                } else {
-                    handler.originalFailure.getValue().addSuppressed(t);
+                    Throwable originalT = handler.originalFailure.getValue();
+                    if (t != originalT) { // could be the same abort being delivered across branches


Otherwise blows up when using parallel inside timeout.

This comment helped a lot for understanding here. ++

ghost · 2016-10-18T22:47:26Z

This pull request originates from a CloudBees employee. At CloudBees, we require that all pull requests be reviewed by other CloudBees employees before we seek to have the change accepted. If you want to learn more about our process please see this explanation.

jglick · 2016-10-18T22:47:48Z

src/test/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecutionTest.java

+        Collection<StepExecution> currentExecutions2 = execs[2].body.getCurrentExecutions();
+        assertThat(currentExecutions2, Matchers.<StepExecution>iterableWithSize(1));
+        assertEquals(semaphores, Sets.union(Sets.newLinkedHashSet(currentExecutions1), Sets.newLinkedHashSet(currentExecutions2)));
+        assertEquals(semaphores, Sets.newLinkedHashSet(execs[0].body.getCurrentExecutions())); // the top-level one


Failed before fix: returned a singleton set of ParallelStepExecution.

jglick · 2016-10-18T22:48:26Z

src/test/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecutionTest.java

+        assertEquals(semaphores, Sets.newLinkedHashSet(execs[0].body.getCurrentExecutions())); // the top-level one
+        execs[0].body.cancel();
+        SemaphoreStep.success("c/1", null);
+        jenkins.assertBuildStatus(Result.ABORTED, jenkins.waitForCompletion(b));


Failed before fix: called ParallelStepExecution.stop, which delegated to RetainsBodyStep.Execution.stop, rather than going straight to SemaphoreStep.Execution.stop.

rsandell · 2016-10-19T15:20:07Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecution.java

+        // cf. trick in CpsFlowExecution.getCurrentExecutions(true)
+        Map<FlowHead, CpsThread> m = new LinkedHashMap<>();
+        // TODO access to CpsThreadGroup.threads should be restricted to the CPS VM thread, but the API signature does not allow us to return a promise or throw InterruptedException
+        for (CpsThread t : thread.group.threads.values()) {


don't you need to guard against concurrent modifications?

Well, yes—see the TODO comment right above. Unfortunately when @kohsuke defined this API method, besides implementing it incorrectly here, he did not allow it to throw any exceptions—and to implement it correctly (to run in the CPS VM thread) we would need to either throw exceptions, or return a ListenableFuture.

At any rate it appears this method was never actually called, so I am not sure it matters. Perhaps the API method should be deprecated and a better replacement introduced if and when there is a need.

rsandell · 2016-10-19T15:22:44Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecution.java

-                    t.stop(stopped);
+                    // Similar to getCurrentExecutions but we want the raw CpsThread, not a StepExecution; cf. CpsFlowExecution.interrupt
+                    Map<FlowHead, CpsThread> m = new LinkedHashMap<>();
+                    for (CpsThread t : thread.group.threads.values()) {


do you need to guard against concurrent modifications?

Not here, because we are in the single CPS VM thread.

rsandell · 2016-10-19T15:29:56Z

🐝

…dell

…dell rightly pointed out that it ought to be made thread-safe.

svanoort · 2016-10-19T20:33:30Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecution.java

+                    }
+                    for (CpsThread t : m.values()) {
+                        // TODO seems cumbersome to have to go through the flow graph to find out whether a head is a descendant of ours, yet FlowHead does not seem to retain a parent field
+                        LinearBlockHoppingScanner scanner = new LinearBlockHoppingScanner();


You can simply this with FlowScanningUtils.fetchEnclosingBlocks -- it will just take the t.head.get() and return an iterator over enclosing BlockStartNodes.

I saw that utility method, but it does not simplify much, I think:

for (FlowNode node : FlowScanningUtils.fetchEnclosingBlocks(t.head.get())) { if (node.getId().equals(startNodeId)) { // …as before } }

It's a little more terse and does a prefilter to only return block start nodes by instanceof check (maybe slightly faster). Not a big deal though, there's a half dozen ways to do this, I just want to put it on your radar since this is exactly what it's for.

svanoort · 2016-10-19T20:39:37Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecution.java

+                        m.put(t.head, t);
+                    }
+                    for (CpsThread t : m.values()) {
+                        // TODO seems cumbersome to have to go through the flow graph to find out whether a head is a descendant of ours, yet FlowHead does not seem to retain a parent field


Consideration: would it be worth adding an enclosingBlockStartNodeId field to FlowNode, and setting it with our block-generating steps?

More data to persist and read, but simplifies many things.

adding an enclosingBlockStartNodeId field to FlowNode

Well it could be transient since it recomputable based on existing information. Anyway that would not help here I think, because we are starting with thread information, which does not completely align with flow graph information.

(For getCurrentExecutions—which no one besides my new test ever calls—it would probably suffice: you could filter FlowExecution.currentHeads to those enclosed by this body. But for cancel we need the actual CpsThreads, since these have special behavior for stop even when not inside a Step.)

So what I would really want here is a way to get from a FlowHead to an Iterable<CpsThread> representing the parts of the call stack that interact with step executions, or conversely to go from a CpsThread to any descendants (getNextInner does not suffice). For example in

timeout(…) {/* #1 */ parallel a: { sleep 9999 /* #2 */ }, b: { while (true) {/* #3 */} } }

we would have a straightforward way of going from the CpsBodyExecution marked at point 1 to the CpsThreads representing points 2 and 3.

It simplifies the LinearBlockHoppingScanner use anyway (and might make it mostly redundant), but the catch is you have to have provided it at execution time or do a full scan of the flow to generate the data (persisting as you go).

Meh, there are bigger optimizations. Flow scanning will get faster and faster over time anyway.

svanoort · 2016-10-19T20:42:04Z

src/main/java/org/jenkinsci/plugins/workflow/cps/CpsBodyExecution.java

+                        m.put(t.head, t);
+                    }
+                    for (CpsThread t : Iterators.reverse(ImmutableList.copyOf(m.values()))) {
+                        LinearBlockHoppingScanner scanner = new LinearBlockHoppingScanner();


Same simplification as before applies (FlowScanner.getEnclosingBlocks)

Actually, scratch that: reuse the scanner though. You can create an instance and do setup on it repeatedly since it is stateful.

I could. This code is not performance-critical however.

Yeah, it's a micro-optimization here. Stuff that's on the hot path should do that though wherever possible.

jglick · 2016-10-19T20:44:55Z

CpsThreadDump test failures are trivial, will fix. Need to look at the ParallelStepTest.suspend failure closely.

svanoort · 2016-10-19T20:51:59Z

🐝 AIUI with a suggested small improvement. Smells potentially risky though due to complexity. Would suggest deploying on an instance with a few jobs using different structures to test (I've got one I can toss it on if you don't)

svanoort

re-approving with a 🐝

jglick · 2016-10-19T21:46:09Z

potentially risky

Well, the changes should only affect calls to BodyExecution.cancel…which we already know was badly broken. So I am comfortable with the functional test coverage here. Was hoping for some guidance from @kohsuke on his original intention w.r.t. StepExecution.stop, but my understanding of his more recent code in CpsFlowExecution.interrupt is that it is expected that we deliver interrupts directly to the innermost running code—which may then propagate throwables up the call stack, log them and continue, process finally blocks, etc.

jglick added 5 commits October 18, 2016 16:10

Safest to deprecate the constructor which does not take a sandbox par…

86d26f4

…ameter, since in most cases we want to test sandboxed behavior.

Found an error in the getNextInner Javadoc.

5c91c7c

JENKINS-25894 fix could throw an IllegalArgumentException under some …

72bba7f

…conditions.

jglick commented Oct 18, 2016

View reviewed changes

jglick mentioned this pull request Oct 18, 2016

[JENKINS-34637] Test for timeout bug jenkinsci/workflow-basic-steps-plugin#24

Merged

rsandell reviewed Oct 19, 2016

View reviewed changes

jglick added 2 commits October 19, 2016 16:11

Merge branch 'master' into timeout-block-JENKINS-34637

a2d98da

Though no one seems to have ever called getCurrentExecutions(), @rsan…

e15225c

…dell rightly pointed out that it ought to be made thread-safe.

svanoort reviewed Oct 19, 2016

View reviewed changes

jglick added 2 commits October 19, 2016 17:01

Adapted to jenkinsci/workflow-support-plugin#20.

904145f

Pick up JENKINS-38457 fix.

43db33d

svanoort approved these changes Oct 19, 2016

View reviewed changes

workflow-support 2.9

da75238

jglick merged commit bee2879 into jenkinsci:master Oct 20, 2016

jglick deleted the timeout-block-JENKINS-34637 branch October 20, 2016 15:12

jglick mentioned this pull request Dec 1, 2021

Avoid printing warnings from CpsStepContext.completed #490

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[JENKINS-34637] Failure to kill bodies from timeout #76

[JENKINS-34637] Failure to kill bodies from timeout #76

jglick commented Oct 18, 2016

jglick Oct 18, 2016

jglick Oct 18, 2016

jglick Oct 18, 2016

jglick Oct 18, 2016

jglick Oct 18, 2016

jglick Oct 18, 2016

svanoort Oct 19, 2016

ghost commented Oct 18, 2016

jglick Oct 18, 2016

jglick Oct 18, 2016

rsandell Oct 19, 2016

jglick Oct 19, 2016

rsandell Oct 19, 2016

jglick Oct 19, 2016

rsandell commented Oct 19, 2016

svanoort Oct 19, 2016

jglick Oct 19, 2016

svanoort Oct 19, 2016

svanoort Oct 19, 2016

jglick Oct 19, 2016

jglick Oct 19, 2016

svanoort Oct 19, 2016

svanoort Oct 19, 2016

svanoort Oct 19, 2016

jglick Oct 19, 2016

svanoort Oct 19, 2016

jglick commented Oct 19, 2016

svanoort commented Oct 19, 2016 •

edited

Loading

svanoort left a comment

jglick commented Oct 19, 2016

[JENKINS-34637] Failure to kill bodies from timeout #76

[JENKINS-34637] Failure to kill bodies from timeout #76

Conversation

jglick commented Oct 18, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ghost commented Oct 18, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rsandell commented Oct 19, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jglick commented Oct 19, 2016

svanoort commented Oct 19, 2016 • edited Loading

svanoort left a comment

Choose a reason for hiding this comment

jglick commented Oct 19, 2016

svanoort commented Oct 19, 2016 •

edited

Loading