Skip to content
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

Better fix of timeout activity tick after restart #234

Merged
merged 2 commits into from
Aug 30, 2022
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
}
Expand All @@ -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;
}
}
Expand Down Expand Up @@ -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);
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand All @@ -71,6 +73,8 @@ public class TimeoutStepTest {

@Rule public GitSampleRepoRule git = new GitSampleRepoRule();

@Rule public LoggerRule logging = new LoggerRule().record(TimeoutStepExecution.class, Level.FINE);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just to help debug.


@Test public void configRoundTrip() throws Throwable {
sessions.then(j -> {
TimeoutStep s1 = new TimeoutStep(3);
Expand Down Expand Up @@ -212,13 +216,14 @@ public void activityRestart() throws Throwable {
+ " echo 'NotHereYet';\n"
+ " sleep 10;\n"
+ " echo 'JustHere!';\n"
+ " sleep 30;\n"
+ " sleep 20;\n"
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A pre-commit version the main patch contained a mistake—the build did not time out until 1½× the stated period; in this case sleep would run for ~23s before being terminated. I was trying to strengthen the test here to verify that the 15s activity timeout really applies.

+ " 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
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Making the test reliably reproduce the originally reported problem.

sessions.then(j -> {
WorkflowJob p = j.jenkins.getItemByFullName("restarted", WorkflowJob.class);
WorkflowRun b = p.getBuildByNumber(1);
Expand Down