Skip to content

Commit

Permalink
[FIXED JENKINS-26521] Add activity flag to timeout step
Browse files Browse the repository at this point in the history
Many thanks to @ikedam for the original version of this. I've just
resurrected it and tweaked a couple things.
  • Loading branch information
abayer committed Mar 7, 2018
1 parent 7d42af6 commit 1307d5a
Show file tree
Hide file tree
Showing 5 changed files with 214 additions and 11 deletions.
Expand Up @@ -22,6 +22,8 @@ public class TimeoutStep extends Step implements Serializable {

private TimeUnit unit = TimeUnit.MINUTES;

private boolean activity = false;

@DataBoundConstructor
public TimeoutStep(int time) {
this.time = time;
Expand All @@ -40,6 +42,15 @@ public TimeUnit getUnit() {
return unit;
}

@DataBoundSetter
public void setActivity(boolean activity) {
this.activity = activity;
}

public boolean isActivity() {
return activity;
}

@Override
public DescriptorImpl getDescriptor() {
return (DescriptorImpl)super.getDescriptor();
Expand Down
Expand Up @@ -5,9 +5,14 @@
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 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;
Expand All @@ -31,30 +36,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 ResetCallback())
)
);
}

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);
}

private TaskListener listener() {
Expand All @@ -70,12 +90,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
Expand All @@ -89,6 +127,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()) {
Expand Down Expand Up @@ -134,7 +178,7 @@ private void cancel() {
forcible = true;
long now = System.currentTimeMillis();
end = now + GRACE_PERIOD;
setupTimer(now);
resetTimer();
}
}

Expand Down Expand Up @@ -185,5 +229,47 @@ public String getShortDescription() {
}
}

private class ResetCallback implements Serializable {
private static final long serialVersionUID = 1L;

private void logWritten() {
resetTimer();
}
}

private static class ConsoleLogFilterImpl extends ConsoleLogFilter implements Serializable {
private static final long serialVersionUID = 1L;

private final ResetCallback callback;

public ConsoleLogFilterImpl(ResetCallback callback) {
this.callback = 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;
}
Expand Up @@ -31,4 +31,7 @@ THE SOFTWARE.
<f:entry field="unit" title="${%Unit}">
<f:select/>
</f:entry>
<f:entry field="activity" title="${%Timeout after inactivity}">
<f:checkbox/>
</f:entry>
</j:jelly>
@@ -0,0 +1,3 @@
<div>
Timeout after no activity in logs for this block instead of absolute duration.
</div>
Expand Up @@ -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"
+ " 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 {
Expand Down

0 comments on commit 1307d5a

Please sign in to comment.