-
-
Notifications
You must be signed in to change notification settings - Fork 126
[FIXED JENKINS-26521] Add activity flag to timeout step #62
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -5,9 +5,15 @@ | |
| import edu.umd.cs.findbugs.annotations.SuppressFBWarnings; | ||
| import hudson.Main; | ||
| import hudson.Util; | ||
| import hudson.console.ConsoleLogFilter; | ||
| import hudson.console.LineTransformationOutputStream; | ||
| import hudson.model.Result; | ||
| import hudson.model.Run; | ||
| import hudson.model.TaskListener; | ||
| import hudson.remoting.Channel; | ||
| import java.io.IOException; | ||
| import java.io.OutputStream; | ||
| import java.io.Serializable; | ||
| import java.util.List; | ||
| import java.util.concurrent.ExecutionException; | ||
| import java.util.concurrent.ScheduledFuture; | ||
|
|
@@ -31,30 +37,45 @@ public class TimeoutStepExecution extends AbstractStepExecutionImpl { | |
| private BodyExecution body; | ||
| private transient ScheduledFuture<?> killer; | ||
|
|
||
| private long timeout = 0; | ||
| private long end = 0; | ||
|
|
||
| /** Used to track whether this is timing out on inactivity without needing to reference {@link #step}. */ | ||
| private boolean activity = false; | ||
|
|
||
| /** whether we are forcing the body to end */ | ||
| private boolean forcible; | ||
|
|
||
| TimeoutStepExecution(TimeoutStep step, StepContext context) { | ||
| super(context); | ||
| this.step = step; | ||
| this.activity = step.isActivity(); | ||
| } | ||
|
|
||
| @Override | ||
| public boolean start() throws Exception { | ||
| StepContext context = getContext(); | ||
| body = context.newBodyInvoker() | ||
| .withCallback(new Callback()) | ||
| .start(); | ||
| long now = System.currentTimeMillis(); | ||
| end = now + step.getUnit().toMillis(step.getTime()); | ||
| setupTimer(now); | ||
| BodyInvoker bodyInvoker = context.newBodyInvoker() | ||
| .withCallback(new Callback()); | ||
|
|
||
| if (step.isActivity()) { | ||
| bodyInvoker = bodyInvoker.withContext( | ||
| BodyInvoker.mergeConsoleLogFilters( | ||
| context.get(ConsoleLogFilter.class), | ||
| new ConsoleLogFilterImpl(new ResetCallbackImpl()) | ||
| ) | ||
| ); | ||
| } | ||
|
|
||
| body = bodyInvoker.start(); | ||
| timeout = step.getUnit().toMillis(step.getTime()); | ||
| resetTimer(); | ||
| return false; // execution is asynchronous | ||
| } | ||
|
|
||
| @Override | ||
| public void onResume() { | ||
| setupTimer(System.currentTimeMillis()); | ||
| setupTimer(System.currentTimeMillis(), false); | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. @abayer I wonder a bit about what the implications are for not resetting activity-based timers at resume... if we're looking at logs, won't the timer trip if Jenkins has been down for a while, and it takes a little bit to get the new log data? Then again we also trip normal timers at restart too I guess.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Yeah, I'm not sure what the ideal approach here would be, so I'd say let's go with this to start and change it in the future if needed. =) There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I have found issue with timeout activity, described in: How additional logs could be taken from Jenkins, to investigate that issue? |
||
| } | ||
|
|
||
| private TaskListener listener() { | ||
|
|
@@ -70,12 +91,30 @@ private TaskListener listener() { | |
| * Sets the timer to manage the timeout. | ||
| * | ||
| * @param now Current time in milliseconds. | ||
| * @param forceReset reset timer if already set | ||
| */ | ||
| private void setupTimer(final long now) { | ||
| private void setupTimer(final long now, boolean forceReset) { | ||
| // Used to track whether we should be logging the timeout setup/reset - for activity resets, we don't actually | ||
| // want to log the "Timeout set to expire..." line every single time. | ||
| boolean resettingKiller = false; | ||
|
|
||
| if (killer != null) { | ||
| if (!forceReset) { | ||
| // already set | ||
| return; | ||
| } | ||
| resettingKiller = true; | ||
| killer.cancel(true); | ||
| killer = null; | ||
| } | ||
| long delay = end - now; | ||
| if (delay > 0) { | ||
| if (!forcible) { | ||
| listener().getLogger().println("Timeout set to expire in " + Util.getTimeSpanString(delay)); | ||
| if (!forcible && !resettingKiller) { | ||
| if (activity) { | ||
| listener().getLogger().println("Timeout set to expire after " + Util.getTimeSpanString(delay) + " without activity"); | ||
| } else { | ||
| listener().getLogger().println("Timeout set to expire in " + Util.getTimeSpanString(delay)); | ||
| } | ||
| } | ||
| killer = Timer.get().schedule(new Runnable() { | ||
| @Override | ||
|
|
@@ -89,6 +128,12 @@ public void run() { | |
| } | ||
| } | ||
|
|
||
| private void resetTimer() { | ||
| long now = System.currentTimeMillis(); | ||
| end = now + timeout; | ||
| setupTimer(now, true); | ||
| } | ||
|
|
||
| private void cancel() { | ||
| if (forcible) { | ||
| if (!killer.isCancelled()) { | ||
|
|
@@ -134,7 +179,7 @@ private void cancel() { | |
| forcible = true; | ||
| long now = System.currentTimeMillis(); | ||
| end = now + GRACE_PERIOD; | ||
| setupTimer(now); | ||
| resetTimer(); | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Something strange. |
||
| } | ||
| } | ||
|
|
||
|
|
@@ -185,5 +230,55 @@ public String getShortDescription() { | |
| } | ||
| } | ||
|
|
||
| public interface ResetCallback extends Serializable { | ||
| void logWritten(); | ||
| } | ||
|
|
||
| private class ResetCallbackImpl implements ResetCallback { | ||
| private static final long serialVersionUID = 1L; | ||
| @Override public void logWritten() { | ||
| resetTimer(); | ||
| } | ||
| } | ||
|
|
||
| private static class ConsoleLogFilterImpl extends ConsoleLogFilter implements /* TODO Remotable */ Serializable { | ||
| private static final long serialVersionUID = 1L; | ||
|
|
||
| private final ResetCallback callback; | ||
|
|
||
| ConsoleLogFilterImpl(ResetCallback callback) { | ||
| this.callback = callback; | ||
| } | ||
|
|
||
| private Object writeReplace() { | ||
| Channel ch = Channel.current(); | ||
| return ch == null ? this : new ConsoleLogFilterImpl(ch.export(ResetCallback.class, callback)); | ||
| } | ||
|
|
||
| @Override | ||
| public OutputStream decorateLogger(@SuppressWarnings("rawtypes") Run build, final OutputStream logger) | ||
| throws IOException, InterruptedException { | ||
| return new LineTransformationOutputStream() { | ||
| @Override | ||
| protected void eol(byte[] b, int len) throws IOException { | ||
| logger.write(b, 0, len); | ||
| callback.logWritten(); | ||
| } | ||
|
|
||
| @Override | ||
| public void flush() throws IOException { | ||
| super.flush(); | ||
| logger.flush(); | ||
| } | ||
|
|
||
| @Override | ||
| public void close() throws IOException { | ||
| super.close(); | ||
| logger.close(); | ||
| } | ||
| }; | ||
| } | ||
| } | ||
|
|
||
| private static final long serialVersionUID = 1L; | ||
| } | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,3 @@ | ||
| <div> | ||
| Timeout after no activity in logs for this block instead of absolute duration. | ||
| </div> |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -139,6 +139,106 @@ public void evaluate() throws Throwable { | |
| }); | ||
| } | ||
|
|
||
| @Issue("JENKINS-26521") | ||
| @Test | ||
| public void activity() throws Exception { | ||
| story.addStep(new Statement() { | ||
| @Override | ||
| public void evaluate() throws Throwable { | ||
| WorkflowJob p = story.j.jenkins.createProject(WorkflowJob.class, "p"); | ||
| p.setDefinition(new CpsFlowDefinition("" | ||
| + "node {\n" | ||
| + " timeout(time:5, unit:'SECONDS', activity: true) {\n" | ||
| + " echo 'NotHere';\n" | ||
| + " sleep 3;\n" | ||
| + " echo 'NotHereYet';\n" | ||
| + " sleep 3;\n" | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Test could be flaky on loaded CI systems if you have only a 1s buffer. |
||
| + " echo 'JustHere!';\n" | ||
| + " sleep 10;\n" | ||
| + " echo 'ShouldNot!';\n" | ||
| + " }\n" | ||
| + "}\n", true)); | ||
| WorkflowRun b = story.j.assertBuildStatus(Result.ABORTED, p.scheduleBuild2(0).get()); | ||
| story.j.assertLogContains("JustHere!", b); | ||
| story.j.assertLogNotContains("ShouldNot!", b); | ||
| } | ||
| }); | ||
| } | ||
|
|
||
| @Issue("JENKINS-26521") | ||
| @Test | ||
| public void activityInParallel() throws Exception { | ||
| story.addStep(new Statement() { | ||
| @Override | ||
| public void evaluate() throws Throwable { | ||
| WorkflowJob p = story.j.jenkins.createProject(WorkflowJob.class, "p"); | ||
| p.setDefinition(new CpsFlowDefinition("" | ||
| + "node {\n" | ||
| + " parallel(\n" | ||
| + " a: {\n" | ||
| + " timeout(time:5, unit:'SECONDS', activity: true) {\n" | ||
| + " echo 'NotHere';\n" | ||
| + " sleep 3;\n" | ||
| + " echo 'NotHereYet';\n" | ||
| + " sleep 3;\n" | ||
| + " echo 'JustHere!';\n" | ||
| + " sleep 10;\n" | ||
| + " echo 'ShouldNot!';\n" | ||
| + " }\n" | ||
| + " },\n" | ||
| + " b: {\n" | ||
| + " for (int i = 0; i < 5; i++) {\n" | ||
| + " echo 'Other Thread'\n" | ||
| + " sleep 3\n" | ||
| + " }\n" | ||
| + " })\n" | ||
| + "}\n", true)); | ||
| WorkflowRun b = story.j.assertBuildStatus(Result.ABORTED, p.scheduleBuild2(0).get()); | ||
| story.j.assertLogContains("JustHere!", b); | ||
| story.j.assertLogNotContains("ShouldNot!", b); | ||
| } | ||
| }); | ||
| } | ||
|
|
||
| @Issue("JENKINS-26521") | ||
| @Test | ||
| public void activityRestart() throws Exception { | ||
| story.addStep(new Statement() { | ||
| @Override | ||
| public void evaluate() throws Throwable { | ||
| WorkflowJob p = story.j.jenkins.createProject(WorkflowJob.class, "restarted"); | ||
| p.setDefinition(new CpsFlowDefinition("" | ||
| + "node {\n" | ||
| + " timeout(time:15, unit:'SECONDS', activity: true) {\n" | ||
| + " echo 'NotHere';\n" | ||
| + " semaphore 'restarted'\n" | ||
| + " echo 'NotHereYet';\n" | ||
| + " sleep 10;\n" | ||
| + " echo 'NotHereYet';\n" | ||
| + " sleep 10;\n" | ||
| + " echo 'JustHere!';\n" | ||
| + " sleep 30;\n" | ||
| + " echo 'ShouldNot!';\n" | ||
| + " }\n" | ||
| + "}\n", true)); | ||
| WorkflowRun b = p.scheduleBuild2(0).getStartCondition().get(); | ||
| SemaphoreStep.waitForStart("restarted/1", b); | ||
| } | ||
| }); | ||
| story.addStep(new Statement() { | ||
| @Override | ||
| public void evaluate() throws Throwable { | ||
| WorkflowJob p = story.j.jenkins.getItemByFullName("restarted", WorkflowJob.class); | ||
| WorkflowRun b = p.getBuildByNumber(1); | ||
| assertTrue("took more than 15s to restart?", b.isBuilding()); | ||
| SemaphoreStep.success("restarted/1", null); | ||
| story.j.assertBuildStatus(Result.ABORTED, story.j.waitForCompletion(b)); | ||
| story.j.assertLogContains("JustHere!", b); | ||
| story.j.assertLogNotContains("ShouldNot!", b); | ||
| } | ||
| }); | ||
| } | ||
|
|
||
| @Issue("JENKINS-26163") | ||
| @Test | ||
| public void restarted() throws Exception { | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why not just delete the
stepfield altogether at this point?