[JENKINS-39072] In case a timeout fails to kill its block normally, t…

…ry forcibly killing the innermost step, akin to doTerm. Does not suffice to kill the body in all cases.
jenkinsci · Oct 24, 2016 · 040ed79 · 040ed79
1 parent 5c13f4f
commit 040ed79
Show file tree

Hide file tree

Showing 2 changed files with 116 additions and 11 deletions.
diff --git a/src/main/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepExecution.java b/src/main/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepExecution.java
@@ -1,27 +1,41 @@
 package org.jenkinsci.plugins.workflow.steps;
 
+import com.google.common.util.concurrent.ListenableFuture;
+import com.google.common.util.concurrent.MoreExecutors;
 import com.google.inject.Inject;
 import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
+import hudson.Main;
 import hudson.Util;
+import hudson.model.Result;
 import hudson.model.TaskListener;
+import java.io.IOException;
+import java.util.List;
+import java.util.concurrent.ExecutionException;
 import java.util.concurrent.ScheduledFuture;
 import java.util.concurrent.TimeUnit;
-
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import jenkins.model.CauseOfInterruption;
 import jenkins.util.Timer;
+import org.jenkinsci.plugins.workflow.flow.FlowExecution;
+import org.jenkinsci.plugins.workflow.graph.FlowNode;
+import org.jenkinsci.plugins.workflow.graphanalysis.LinearBlockHoppingScanner;
 
-/**
- * @author Kohsuke Kawaguchi
- */
 @SuppressFBWarnings("SE_INNER_CLASS")
 public class TimeoutStepExecution extends AbstractStepExecutionImpl {
+
+    private static final Logger LOGGER = Logger.getLogger(TimeoutStepExecution.class.getName());
+    private static final long GRACE_PERIOD = Main.isUnitTest ? /* 5s */5_000 : /* 1m */60_000;
+
     @Inject(optional=true)
     private transient TimeoutStep step;
     @StepContextParameter private transient TaskListener listener;
     private BodyExecution body;
     private transient ScheduledFuture<?> killer;
 
     private long end = 0;
+    /** whether we are forcing the body to end */
+    private boolean forcible;
 
     @Override
     public boolean start() throws Exception {
@@ -49,7 +63,9 @@ public void onResume() {
     private void setupTimer(final long now) {
         if (end > now) {
             long delay = end - now;
-            listener.getLogger().println("Timeout set to expire in " + Util.getTimeSpanString(delay));
+            if (!forcible) {
+                listener.getLogger().println("Timeout set to expire in " + Util.getTimeSpanString(delay));
+            }
             killer = Timer.get().schedule(new Runnable() {
                 @Override
                 public void run() {
@@ -62,8 +78,52 @@ public void run() {
     }
 
     private void cancel() {
-        listener.getLogger().println("Cancelling nested steps due to timeout");
-        body.cancel(new ExceededTimeout());
+        if (forcible) {
+            if (!killer.isCancelled()) {
+                listener.getLogger().println("Body did not finish within grace period; terminating with extreme prejudice");
+                FlowExecution exec;
+                try {
+                    exec = getContext().get(FlowExecution.class);
+                } catch (IOException | InterruptedException x) {
+                    LOGGER.log(Level.WARNING, null, x);
+                    return;
+                }
+                final Throwable death = new FlowInterruptedException(Result.ABORTED, new ExceededTimeout());
+                /* Due to JENKINS-25504, this does not accomplish anything beyond what the original body.cancel would have:
+                getContext().onFailure(death);
+                */
+                final ListenableFuture<List<StepExecution>> currentExecutions = exec.getCurrentExecutions(true);
+                // TODO would use Futures.addCallback but this is still @Beta in Guava 19 and the Pipeline copy is in workflow-support on which we have no dep
+                currentExecutions.addListener(new Runnable() {
+                    @Override public void run() {
+                        assert currentExecutions.isDone();
+                        try {
+                            FlowNode outer = getContext().get(FlowNode.class); // timeout
+                            for (StepExecution exec : currentExecutions.get()) {
+                                FlowNode inner = exec.getContext().get(FlowNode.class); // some deadbeat step, perhaps
+                                LinearBlockHoppingScanner scanner = new LinearBlockHoppingScanner();
+                                scanner.setup(inner);
+                                for (FlowNode enclosing : scanner) {
+                                    if (enclosing.equals(outer)) {
+                                        exec.getContext().onFailure(death);
+                                        break;
+                                    }
+                                }
+                            }
+                        } catch (IOException | InterruptedException | ExecutionException x) {
+                            LOGGER.log(Level.WARNING, null, x);
+                        }
+                    }
+                }, MoreExecutors.sameThreadExecutor());
+            }
+        } else {
+            listener.getLogger().println("Cancelling nested steps due to timeout");
+            body.cancel(new ExceededTimeout());
+            forcible = true;
+            long now = System.currentTimeMillis();
+            end = now + GRACE_PERIOD;
+            setupTimer(now);
+        }
     }
 
     @Override

diff --git a/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java b/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java
@@ -25,6 +25,9 @@
 package org.jenkinsci.plugins.workflow.steps;
 
 import hudson.model.Result;
+import hudson.model.TaskListener;
+import java.util.List;
+import java.util.concurrent.TimeUnit;
 import jenkins.model.CauseOfInterruption;
 import jenkins.model.InterruptedBuildAction;
 import org.jenkinsci.plugins.workflow.actions.ErrorAction;
@@ -36,14 +39,13 @@
 import org.jenkinsci.plugins.workflow.support.visualization.table.FlowGraphTable.Row;
 import org.jenkinsci.plugins.workflow.test.steps.SemaphoreStep;
 import org.junit.*;
+import static org.junit.Assert.assertEquals;
 import org.junit.runners.model.Statement;
 import org.jvnet.hudson.test.BuildWatcher;
 import org.jvnet.hudson.test.Issue;
 import org.jvnet.hudson.test.RestartableJenkinsRule;
-
-import java.util.List;
-import java.util.concurrent.TimeUnit;
-import static org.junit.Assert.assertEquals;
+import org.jvnet.hudson.test.TestExtension;
+import org.kohsuke.stapler.DataBoundConstructor;
 
 public class TimeoutStepTest extends Assert {
 
@@ -198,6 +200,49 @@ public void evaluate() throws Throwable {
         });
     }
 
+    @Issue("JENKINS-39072")
+    @Test public void unresponsiveBody() {
+        story.addStep(new Statement() {
+            @Override public void evaluate() throws Throwable {
+                WorkflowJob p = story.j.jenkins.createProject(WorkflowJob.class, "p");
+                p.setDefinition(new CpsFlowDefinition("timeout(time: 2, unit: 'SECONDS') {unkillable()}", true));
+                story.j.assertBuildStatus(Result.ABORTED, p.scheduleBuild2(0).get());
+            }
+        });
+    }
+    public static class UnkillableStep extends AbstractStepImpl {
+        @DataBoundConstructor public UnkillableStep() {}
+        public static class Execution extends AbstractStepExecutionImpl {
+            @StepContextParameter transient TaskListener listener;
+            @Override public boolean start() throws Exception {
+                return false;
+            }
+            @Override public void stop(Throwable cause) throws Exception {
+                listener.getLogger().println("ignoring " + cause);
+            }
+        }
+        @TestExtension("unresponsiveBody") public static class DescriptorImpl extends AbstractStepDescriptorImpl {
+            public DescriptorImpl() {
+                super(Execution.class);
+            }
+            @Override public String getFunctionName() {
+                return "unkillable";
+            }
+        }
+    }
+
+    @Ignore("TODO cannot find any way to solve this case")
+    @Issue("JENKINS-39072")
+    @Test public void veryUnresponsiveBody() {
+        story.addStep(new Statement() {
+            @Override public void evaluate() throws Throwable {
+                WorkflowJob p = story.j.jenkins.createProject(WorkflowJob.class, "p");
+                p.setDefinition(new CpsFlowDefinition("timeout(time: 2, unit: 'SECONDS') {while (true) {try {sleep 10} catch (e) {echo(/ignoring ${e}/)}}}", true));
+                story.j.assertBuildStatus(Result.ABORTED, p.scheduleBuild2(0).get());
+            }
+        });
+    }
+
     // TODO: timeout inside parallel
 
 }