From 85b6c33ca6e05fe30dcb3e8da1bfd04c01a48e21 Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Mon, 29 Aug 2022 12:56:58 -0400 Subject: [PATCH 1/2] Better fix of `timeout` activity tick after restart --- .../workflow/steps/TimeoutStepExecution.java | 14 ++++---------- .../plugins/workflow/steps/TimeoutStepTest.java | 7 ++++++- 2 files changed, 10 insertions(+), 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 index ba6a97a4..3b28feb0 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepExecution.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepExecution.java @@ -142,6 +142,7 @@ private void setupTimer(final long now, boolean forceReset) { } private void resetTimer() { + LOGGER.fine(() -> "resetting timer on " + id); long now = System.currentTimeMillis(); end = now + timeout; setupTimer(now, true); @@ -340,9 +341,6 @@ public OutputStream decorateLogger(@SuppressWarnings("rawtypes") Run build, fina OutputStream decorated = new LineTransformationOutputStream() { @Override protected void eol(byte[] b, int len) throws IOException { - if (channel == null) { - new ResetTimer(id).call(); - } logger.write(b, 0, len); active.set(true); } @@ -359,9 +357,7 @@ public void close() throws IOException { logger.close(); } }; - if (channel != null) { - new Tick(active, new WeakReference<>(decorated), timeout, channel, id).schedule(); - } + new Tick(active, new WeakReference<>(decorated), timeout, channel, id).schedule(0); return decorated; } } @@ -397,16 +393,14 @@ public void run() { } else { resetTimer.call(); } - schedule(); + schedule(timeout / 2); // less than the full timeout, to give some grace period, but in the same ballpark to avoid overhead } else { // Idle at the moment, but check well before the timeout expires in case new output appears. schedule(timeout / 10); } } - void schedule() { - schedule(timeout / 2); // less than the full timeout, to give some grace period, but in the same ballpark to avoid overhead - } private void schedule(long delay) { + LOGGER.fine(() -> "scheduling tick for " + Util.getTimeSpanString(delay)); Timer.get().schedule(this, delay, TimeUnit.MILLISECONDS); } } diff --git a/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java b/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java index f18f476a..272bddb8 100644 --- a/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java +++ b/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java @@ -33,6 +33,7 @@ import java.util.List; import java.util.Set; import java.util.concurrent.TimeUnit; +import java.util.logging.Level; import jenkins.model.CauseOfInterruption; import jenkins.model.InterruptedBuildAction; import jenkins.plugins.git.GitSampleRepoRule; @@ -59,6 +60,7 @@ import org.jvnet.hudson.test.BuildWatcher; import org.jvnet.hudson.test.Issue; import org.jvnet.hudson.test.JenkinsSessionRule; +import org.jvnet.hudson.test.LoggerRule; import org.jvnet.hudson.test.TestExtension; import org.jvnet.hudson.test.recipes.LocalData; import org.kohsuke.stapler.DataBoundConstructor; @@ -71,6 +73,8 @@ public class TimeoutStepTest { @Rule public GitSampleRepoRule git = new GitSampleRepoRule(); + @Rule public LoggerRule logging = new LoggerRule().record(TimeoutStepExecution.class, Level.FINE); + @Test public void configRoundTrip() throws Throwable { sessions.then(j -> { TimeoutStep s1 = new TimeoutStep(3); @@ -212,13 +216,14 @@ public void activityRestart() throws Throwable { + " echo 'NotHereYet';\n" + " sleep 10;\n" + " echo 'JustHere!';\n" - + " sleep 30;\n" + + " sleep 20;\n" + " echo 'ShouldNot!';\n" + " }\n" + "}\n", true)); WorkflowRun b = p.scheduleBuild2(0).getStartCondition().get(); SemaphoreStep.waitForStart("restarted/1", b); }); + Thread.sleep(10_000); // restarting should count as activity sessions.then(j -> { WorkflowJob p = j.jenkins.getItemByFullName("restarted", WorkflowJob.class); WorkflowRun b = p.getBuildByNumber(1); From 512d9205566e1ab9072f1465f377522e06e891c1 Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Tue, 30 Aug 2022 08:36:00 -0400 Subject: [PATCH 2/2] Reverting test changes since they seem to flake ~1%: https://github.com/jenkinsci/workflow-basic-steps-plugin/pull/234#issuecomment-1231596576 --- .../jenkinsci/plugins/workflow/steps/TimeoutStepTest.java | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java b/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java index 272bddb8..f18f476a 100644 --- a/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java +++ b/src/test/java/org/jenkinsci/plugins/workflow/steps/TimeoutStepTest.java @@ -33,7 +33,6 @@ import java.util.List; import java.util.Set; import java.util.concurrent.TimeUnit; -import java.util.logging.Level; import jenkins.model.CauseOfInterruption; import jenkins.model.InterruptedBuildAction; import jenkins.plugins.git.GitSampleRepoRule; @@ -60,7 +59,6 @@ import org.jvnet.hudson.test.BuildWatcher; import org.jvnet.hudson.test.Issue; import org.jvnet.hudson.test.JenkinsSessionRule; -import org.jvnet.hudson.test.LoggerRule; import org.jvnet.hudson.test.TestExtension; import org.jvnet.hudson.test.recipes.LocalData; import org.kohsuke.stapler.DataBoundConstructor; @@ -73,8 +71,6 @@ public class TimeoutStepTest { @Rule public GitSampleRepoRule git = new GitSampleRepoRule(); - @Rule public LoggerRule logging = new LoggerRule().record(TimeoutStepExecution.class, Level.FINE); - @Test public void configRoundTrip() throws Throwable { sessions.then(j -> { TimeoutStep s1 = new TimeoutStep(3); @@ -216,14 +212,13 @@ public void activityRestart() throws Throwable { + " echo 'NotHereYet';\n" + " sleep 10;\n" + " echo 'JustHere!';\n" - + " sleep 20;\n" + + " sleep 30;\n" + " echo 'ShouldNot!';\n" + " }\n" + "}\n", true)); WorkflowRun b = p.scheduleBuild2(0).getStartCondition().get(); SemaphoreStep.waitForStart("restarted/1", b); }); - Thread.sleep(10_000); // restarting should count as activity sessions.then(j -> { WorkflowJob p = j.jenkins.getItemByFullName("restarted", WorkflowJob.class); WorkflowRun b = p.getBuildByNumber(1);