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

[JENKINS-73824][JENKINS-73835] Remove redundant log rotation after changes in core and add regression tests related to deleting Pipeline jobs and builds #470

Merged
merged 11 commits into from
Oct 15, 2024
Merged
7 changes: 4 additions & 3 deletions pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -63,7 +63,8 @@
</pluginRepositories>
<properties>
<changelist>999999-SNAPSHOT</changelist>
<jenkins.version>2.479</jenkins.version>
<!-- TODO: Waiting for JENKINS-73824 and JENKINS-73835 to make it into an LTS line -->
<jenkins.version>2.481</jenkins.version>
Copy link
Member Author

@dwnusbaum dwnusbaum Oct 15, 2024

Choose a reason for hiding this comment

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

Up to reviewers what we want to do here. The removal of the call to logRotate in WorkflowRun.finish eliminates a redundancy, but things should be fine for 2.481+ users even with the redundant log rotation. We can either merge this as-is or wait for the fixes to make it into an LTS line.

<no-test-jar>false</no-test-jar>
<useBeta>true</useBeta>
<hpi.compatibleSinceVersion>2.26</hpi.compatibleSinceVersion>
Expand All @@ -73,8 +74,8 @@
<dependencies>
<dependency>
<groupId>io.jenkins.tools.bom</groupId>
<artifactId>bom-2.462.x</artifactId>
<version>3221.ve8f7b_fdd149d</version>
<artifactId>bom-2.479.x</artifactId>
<version>3482.vc10d4f6da_28a_</version>
<scope>import</scope>
<type>pom</type>
</dependency>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -660,13 +660,6 @@ private void finish(@NonNull Result r, @CheckForNull Throwable t) {
listener = null;
}
saveWithoutFailing(true);
Timer.get().submit(() -> {
try {
getParent().logRotate();
} catch (Exception x) {
LOGGER.log(Level.WARNING, "failed to perform log rotation after " + this, x);
}
});
Comment on lines -663 to -669
Copy link
Member Author

@dwnusbaum dwnusbaum Oct 1, 2024

Choose a reason for hiding this comment

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

Originally made asynchronous in 63fdbe8. Note though that since jenkinsci/jenkins#4368, Jenkins core was also calling Job.logRotate synchronously from Run.onEndBuilding -> RunListener.onFinalized (at least with the default global build discarder configuration), so one of the calls was redundant.

With this PR only Jenkins core calls Job.logRotate, and it does so synchronously. We could make that call asynchronous if there are any concerns, but given that default configurations have been calling it synchronously for years now, it didn't seem necessary to preserve the asynchronicity.

Copy link
Member

Choose a reason for hiding this comment

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

(#70)

onEndBuilding();
} finally { // Ensure this is ALWAYS removed from FlowExecutionList
FlowExecutionList.get().unregister(new Owner(this));
Expand Down
Original file line number Diff line number Diff line change
@@ -1,6 +1,8 @@
package org.jenkinsci.plugins.workflow.job;

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.empty;
import static org.hamcrest.Matchers.nullValue;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertFalse;
import static org.junit.Assert.assertNotNull;
Expand All @@ -12,20 +14,30 @@
import org.htmlunit.html.HtmlCheckBoxInput;
import org.htmlunit.html.HtmlForm;
import hudson.cli.CLICommandInvoker;
import hudson.model.Executor;
import hudson.model.Result;
import hudson.plugins.git.GitSCM;
import hudson.security.WhoAmI;
import hudson.triggers.SCMTrigger;
import java.util.Objects;
import java.util.logging.Logger;
import java.util.stream.Collectors;
import java.util.stream.Stream;
import jenkins.plugins.git.GitSampleRepoRule;
import org.jenkinsci.plugins.workflow.cps.CpsFlowDefinition;
import org.jenkinsci.plugins.workflow.cps.CpsScmFlowDefinition;
import org.junit.ClassRule;
import org.junit.Rule;
import org.junit.Test;
import org.jvnet.hudson.test.BuildWatcher;
import org.jvnet.hudson.test.Issue;
import org.jvnet.hudson.test.JenkinsRule;
import org.jvnet.hudson.test.RunLoadCounter;

public class WorkflowJobTest {
private static final Logger LOGGER = Logger.getLogger(WorkflowJobTest.class.getName());

@ClassRule public static BuildWatcher watcher = new BuildWatcher();

@Rule public JenkinsRule j = new JenkinsRule();
@Rule public GitSampleRepoRule sampleRepo = new GitSampleRepoRule();
Expand Down Expand Up @@ -157,4 +169,35 @@ public void newBuildsShouldNotLoadOld() throws Throwable {
});
}

@Issue("JENKINS-73824")
@Test
public void deletionShouldWaitForBuildsToComplete() throws Throwable {
var p = j.createProject(WorkflowJob.class);
p.setDefinition(new CpsFlowDefinition(
"""
try {
echo 'about to sleep'
sleep 999
} catch(e) {
echo 'aborting soon'
sleep 3
}
""", true));
var b = p.scheduleBuild2(0).waitForStart();
j.waitForMessage("about to sleep", b);
// The build isn't done and catches the interruption, so ItemDeletion.cancelBuildsInProgress should have to wait at least 3 seconds for it to complete.
LOGGER.info(() -> "Deleting " + p);
p.delete();
LOGGER.info(() -> "Deleted " + p);
// Make sure that the job really has been deleted.
assertThat(j.jenkins.getItemByFullName(p.getFullName()), nullValue());
// ItemDeletion.cancelBuildsInProgress should guarantee that the queue is empty at this point.
var executables = Stream.of(j.jenkins.getComputers())
.flatMap(c -> c.getAllExecutors().stream())
.map(Executor::getCurrentExecutable)
.filter(Objects::nonNull)
.collect(Collectors.toList());
assertThat(executables, empty());
}

}
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@
import static org.hamcrest.collection.IsEmptyCollection.empty;
import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.containsString;
import static org.hamcrest.Matchers.emptyArray;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.notNullValue;
import static org.hamcrest.Matchers.nullValue;
Expand Down Expand Up @@ -58,6 +59,7 @@
import hudson.slaves.EnvironmentVariablesNodeProperty;
import hudson.slaves.NodeProperty;
import hudson.slaves.NodePropertyDescriptor;
import hudson.tasks.LogRotator;
import hudson.util.DescribableList;
import hudson.util.StreamTaskListener;
import java.io.File;
Expand All @@ -73,6 +75,7 @@
import java.util.TreeSet;
import java.util.concurrent.TimeUnit;
import java.util.logging.Level;
import java.util.logging.Logger;
import jenkins.model.CauseOfInterruption;
import jenkins.model.InterruptedBuildAction;
import jenkins.model.Jenkins;
Expand Down Expand Up @@ -109,6 +112,7 @@
import org.xml.sax.SAXException;

public class WorkflowRunTest {
private static final Logger LOGGER = Logger.getLogger(WorkflowRunTest.class.getName());

@ClassRule public static BuildWatcher buildWatcher = new BuildWatcher();
@Rule public JenkinsRule r = new JenkinsRule();
Expand Down Expand Up @@ -520,7 +524,7 @@ private void assertCulprits(WorkflowRun b, String... expectedIds) throws IOExcep
assertThat(await().until(() -> ExtensionList.lookupSingleton(CheckCompletedFlag.class).buildXml.get(b.getExternalizableId()), notNullValue()),
containsString("<completed>true</completed>"));
}
@TestExtension public static final class CheckCompletedFlag extends RunListener<WorkflowRun> {
@TestExtension("completedFlag") public static final class CheckCompletedFlag extends RunListener<WorkflowRun> {
Copy link
Member Author

Choose a reason for hiding this comment

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

Only need by this specific test and causes annoying log spam in the new test since it tries to look at build directories for deleted builds.

final Map<String, String> buildXml = new HashMap<>();
@Override public void onFinalized(WorkflowRun r) {
try {
Expand Down Expand Up @@ -600,6 +604,20 @@ private void assertCulprits(WorkflowRun b, String... expectedIds) throws IOExcep
assertPollingBaselines(b3.checkouts(listener), nullValue(), nullValue());
}

@SafeVarargs
private static void assertPollingBaselines(List<WorkflowRun.SCMCheckout> checkouts, Matcher<Object>... indexedMatchers) {
assertThat("Number of checkouts should match number of matchers", checkouts.size(), equalTo(indexedMatchers.length));
for (int i = 0; i < checkouts.size(); i++) {
assertThat("Unexpected baseline for checkout at index " + i, checkouts.get(i).pollingBaseline, indexedMatchers[i]);
}
}

private static String checkoutString(GitSampleRepoRule repo, boolean changelog, boolean polling) {
return " checkout(changelog:" + changelog +", poll:" + polling +
", scm: [$class: 'GitSCM', branches: [[name: '*/master']], " +
", userRemoteConfigs: [[url: $/" + repo.fileUrl() + "/$]]])\n";
}

Comment on lines +607 to +620
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 moving these next to the relevant test for clarity.

// This test is to ensure that the shortDescription on the CancelCause is escaped properly on summary.jelly
@Issue("SECURITY-3042")
@Test public void escapedDisplayNameAfterAbort() throws Exception {
Expand Down Expand Up @@ -667,19 +685,42 @@ public void onInitialize(Run run) {

}


@SafeVarargs
private static void assertPollingBaselines(List<WorkflowRun.SCMCheckout> checkouts, Matcher<Object>... indexedMatchers) {
assertThat("Number of checkouts should match number of matchers", checkouts.size(), equalTo(indexedMatchers.length));
for (int i = 0; i < checkouts.size(); i++) {
assertThat("Unexpected baseline for checkout at index " + i, checkouts.get(i).pollingBaseline, indexedMatchers[i]);
@Issue("JENKINS-73835")
@Test public void logRotationOnlyProcessesCompletedBuilds() throws Throwable {
logging.record(LogRotator.class, Level.FINER);
var p = r.createProject(WorkflowJob.class);
p.setDefinition(new CpsFlowDefinition(
"echo params.FOO; semaphore 'wait'", true));
p.addProperty(new ParametersDefinitionProperty(List.of(new StringParameterDefinition("FOO"))));
// Keep 0 builds, i.e. delete all builds immediately.
Copy link
Member Author

Choose a reason for hiding this comment

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

I am keeping 0 builds rather than 1 build to simplify test assertions. Mainly I am trying to avoid complicated issues involving the exact timing of calls to RunList.size and RunList.sublist in LogRotator.perform compared to other builds completing, which can cause builds other than the one with the largest build number to be preserved by LogRotator.

LogRotator logRotator = new LogRotator(-1, 0, -1, -1);
logRotator.setRemoveLastBuild(true);
p.setBuildDiscarder(logRotator);
int buildsToRun = 10; // Increase this number to reproduce the issue more easily prior to the fix.
Run[] builds = new Run[buildsToRun];
File[] buildDirs = new File[buildsToRun];
// Run a large number of builds that should finish around the same time to check race conditions with log rotation and build completion.
for (int i = 0; i < buildsToRun; i++) {
var b = p.scheduleBuild2(0, new ParametersAction(List.of(new StringParameterValue("FOO", "b" + i)))).waitForStart();
builds[i] = b;
buildDirs[i] = b.getRootDir();
SemaphoreStep.waitForStart("wait/" + (i+1), b);
}
for (int i = 0; i < buildsToRun; i++) {
SemaphoreStep.success("wait/" + (i+1), null);
}
LOGGER.info("Waiting for all builds to complete");
for (int i = 0; i < buildsToRun; i++) {
r.waitForCompletion(builds[i]);
}
LOGGER.info("Checking that all build directories are empty");
for (int i = 0; i < buildsToRun; i++) {
String[] filesInBuildDir = buildDirs[i].list();
if (filesInBuildDir == null) {
filesInBuildDir = new String[0];
}
assertThat("Expected " + buildDirs[i] + " to be empty but saw: " + Arrays.toString(filesInBuildDir), filesInBuildDir, emptyArray());
Copy link
Member Author

Choose a reason for hiding this comment

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

Prior to the fix, this fails intermittently because some directory contains build.xml.

}
}

private static String checkoutString(GitSampleRepoRule repo, boolean changelog, boolean polling) {
return " checkout(changelog:" + changelog +", poll:" + polling +
", scm: [$class: 'GitSCM', branches: [[name: '*/master']], " +
", userRemoteConfigs: [[url: $/" + repo.fileUrl() + "/$]]])\n";
}

}
Loading