Make Timeout repeatedly interrupt a stuck thread, and note that this is happening

pom.xml

@@ -28,15 +28,15 @@
     <parent>
         <groupId>org.jenkins-ci.plugins</groupId>
         <artifactId>plugin</artifactId>
-        <version>2.33</version>
+        <version>3.2</version>
         <relativePath />
     </parent>
     <groupId>org.jenkins-ci.plugins.workflow</groupId>
     <artifactId>workflow-support</artifactId>
     <version>2.17-SNAPSHOT</version>
     <packaging>hpi</packaging>
     <name>Pipeline: Supporting APIs</name>
-    <url>https://wiki.jenkins-ci.org/display/JENKINS/Pipeline+Supporting+APIs+Plugin</url>
+    <url>https://wiki.jenkins.io/display/JENKINS/Pipeline+Supporting+APIs+Plugin</url>
     <licenses>
         <license>
             <name>MIT License</name>
@@ -63,6 +63,7 @@
     </pluginRepositories>
     <properties>
         <jenkins.version>2.60.2</jenkins.version>
+        <java.level>8</java.level>
         <no-test-jar>false</no-test-jar>
         <git-plugin.version>3.0.5</git-plugin.version>
         <workflow-scm-step-plugin.version>2.4</workflow-scm-step-plugin.version>

src/main/java/org/jenkinsci/plugins/workflow/support/concurrent/Timeout.java

@@ -25,12 +25,15 @@
 package org.jenkinsci.plugins.workflow.support.concurrent;
 
 import hudson.FilePath;
+import hudson.Util;
 import hudson.remoting.VirtualChannel;
-import java.util.concurrent.ScheduledFuture;
+import hudson.util.DaemonThreadFactory;
+import hudson.util.NamingThreadFactory;
+import java.util.concurrent.Executors;
+import java.util.concurrent.ScheduledExecutorService;
 import java.util.concurrent.TimeUnit;
 import java.util.logging.Level;
 import java.util.logging.Logger;
-import jenkins.util.Timer;
 
 /**
  * Allows operations to be limited in execution time.
@@ -41,28 +44,62 @@ public class Timeout implements AutoCloseable {
 
     private static final Logger LOGGER = Logger.getLogger(Timeout.class.getName());
 
-    private final ScheduledFuture<?> task;
+    private static final ScheduledExecutorService interruptions = Executors.newSingleThreadScheduledExecutor(new NamingThreadFactory(new DaemonThreadFactory(), "Timeout.interruptions"));
 
-    private Timeout(ScheduledFuture<?> task) {
-        this.task = task;
+    private final Thread thread;
+    private volatile boolean completed;
+    private long endTime;
+    /*
+    private final String originalName;
+    */
+
+    private Timeout(long time, TimeUnit unit) {
+        thread = Thread.currentThread();
+        LOGGER.log(Level.FINER, "Might interrupt {0} after {1} {2}", new Object[] {thread.getName(), time, unit});
+        /* see below:
+        originalName = thread.getName();
+        thread.setName(String.format("%s (Timeout@%h: %s)", originalName, this, Util.getTimeSpanString(unit.toMillis(time))));
+        */
+        ping(time, unit);
     }
 
     @Override public void close() {
-        task.cancel(false);
+        completed = true;
+        /*
+        thread.setName(originalName);
+        */
+        LOGGER.log(Level.FINER, "completed {0}", thread.getName());
     }
 
-    public static Timeout limit(final long time, final TimeUnit unit) {
-        final Thread thread = Thread.currentThread();
-        return new Timeout(Timer.get().schedule(new Runnable() {
-            @Override public void run() {
-                if (LOGGER.isLoggable(Level.FINE)) {
-                    Throwable t = new Throwable();
-                    t.setStackTrace(thread.getStackTrace());
-                    LOGGER.log(Level.FINE, "Interrupting " + thread + " after " + time + " " + unit, t);
-                }
-                thread.interrupt();
+    private void ping(final long time, final TimeUnit unit) {
+        interruptions.schedule(() -> {
+            if (completed) {
+                LOGGER.log(Level.FINER, "{0} already finished, no need to interrupt", thread.getName());
+                return;
+            }
+            if (LOGGER.isLoggable(Level.FINE)) {
+                Throwable t = new Throwable();
+                t.setStackTrace(thread.getStackTrace());
+                LOGGER.log(Level.FINE, "Interrupting " + thread.getName() + " after " + time + " " + unit, t);
+            }
+            thread.interrupt();
+            if (endTime == 0) {
+                // First interruption.
+                endTime = System.nanoTime();
+            } else {
+                // Not dead yet?
+                String unresponsiveness = Util.getTimeSpanString((System.nanoTime() - endTime) / 1_000_000);
+                LOGGER.log(Level.INFO, "{0} unresponsive for {1}", new Object[] {thread.getName(), unresponsiveness});
+                /* TODO does not work; thread.getName() does not seem to return the current value when called from another thread, even w/ synchronized access, and running with -Xint
+                thread.setName(thread.getName().replaceFirst(String.format("(Timeout@%h: )[^)]+", this), "$1unresponsive for " + unresponsiveness));
+                */
             }
-        }, time, unit));
+            ping(5, TimeUnit.SECONDS);
+        }, time, unit);
+    }
+
+    public static Timeout limit(final long time, final TimeUnit unit) {
+        return new Timeout(time, unit);
     }
 
     // TODO JENKINS-32986 offer a variant that will escalate to Thread.stop

src/test/java/org/jenkinsci/plugins/workflow/support/concurrent/TimeoutTest.java

@@ -24,11 +24,21 @@
 
 package org.jenkinsci.plugins.workflow.support.concurrent;
 
+import java.util.Map;
+import java.util.TreeMap;
+import java.util.concurrent.Future;
 import java.util.concurrent.TimeUnit;
+import java.util.logging.Level;
+import java.util.stream.IntStream;
+import jenkins.util.Timer;
 import org.junit.Test;
 import static org.junit.Assert.*;
+import org.junit.Rule;
+import org.jvnet.hudson.test.LoggerRule;
 
 public class TimeoutTest {
+
+    @Rule public LoggerRule logging = new LoggerRule().record(Timeout.class, Level.FINER);
 
     @Test public void passed() throws Exception {
         try (Timeout timeout = Timeout.limit(5, TimeUnit.SECONDS)) {
@@ -47,4 +57,53 @@ public class TimeoutTest {
         Thread.sleep(1_000);
     }
 
+    @Test public void hung() throws Exception {
+        /* see disabled code in Timeout:
+        final AtomicBoolean stop = new AtomicBoolean();
+        Thread t = Thread.currentThread();
+        Timer.get().submit(() -> {
+            while (!stop.get()) {
+                System.err.println(t.getName());
+                try {
+                    Thread.sleep(1_000);
+                } catch (InterruptedException x) {
+                    x.printStackTrace();
+                }
+            }
+        });
+        */
+        try (Timeout timeout = Timeout.limit(1, TimeUnit.SECONDS)) {
+            for (int i = 0; i < 5; i++) {
+                try /* (WithThreadName naming = new WithThreadName(" cycle #" + i)) */ {
+                    Thread.sleep(10_000);
+                    fail("should have timed out");
+                } catch (InterruptedException x) {
+                    // OK
+                }
+            }
+        }
+        Thread.sleep(6_000);
+        /*
+        stop.set(true);
+        */
+    }
+
+    @Test public void starvation() throws Exception {
+        Map<Integer, Future<?>> hangers = new TreeMap<>();
+        IntStream.range(0, 15).forEachOrdered(i -> hangers.put(i, Timer.get().submit(() -> {
+            try (Timeout timeout = Timeout.limit(5, TimeUnit.SECONDS)) {
+                System.err.println("starting #" + i);
+                Thread.sleep(Long.MAX_VALUE);
+                fail("should have timed out");
+            } catch (InterruptedException x) {
+                System.err.println("interrupted #" + i);
+            }
+        })));
+        for (Map.Entry<Integer, Future<?>> hanger : hangers.entrySet()) {
+            System.err.println("joining #" + hanger.getKey());
+            hanger.getValue().get(30, TimeUnit.SECONDS);
+            System.err.println("joined #" + hanger.getKey());
+        }
+    }
+
 }