Stop agents before exiting test cases, and reliably close `all_*.log` when agents exit #624

jglick · 2025-02-14T20:13:43Z

As noted in #617 (comment) there are mostly consistent test failures on Windows. Not sure why these are just appearing now (and I cannot reproduce locally on Windows 10), but at any rate SupportLogHandler opens a file handle on e.g. agent-work-dirs\agent0\support\all_2025-02-14_13.33.29.log which will not be closed unless the agent process exits.

(CloudBees internal issue)

src/test/java/com/cloudbees/jenkins/support/CheckFilterTest.java

jglick · 2025-02-17T12:26:53Z

Apparently did not suffice. Maybe this file is not actually closed when the agent terminates? Or the current attempt to terminate the agent is not effective because it just closes the connection and does not exit the JVM?

jglick · 2025-02-18T20:21:02Z

support-core-plugin/src/main/java/com/cloudbees/jenkins/support/SupportPlugin.java

Line 879 in 7fcc00b

ROOT_LOGGER.addHandler(LogHolder.AGENT_LOG_HANDLER);

initializes a log handler which opens this file handle in

support-core-plugin/src/main/java/com/cloudbees/jenkins/support/SupportLogHandler.java

Line 242 in 7fcc00b

fos = new FileOutputStream(file);

and AFAICT an agent would not normally close this handle until the JVM exits. https://github.com/jenkinsci/jenkins-test-harness/blob/052a595c77a54099ceeac0002c0d4f816838092e/src/main/java/org/jvnet/hudson/test/SimpleCommandLauncher.java#L82-L91 ought to be terminating that JVM, but I guess this just initiates termination of the JVM, it does not wait for it.

jglick · 2025-02-18T20:27:57Z

Incorrect. SimpleCommandLauncher seems to be waiting for the process to exit, but its listener is not being called synchronously by this thread:

java.lang.Throwable
	at org.jvnet.hudson.test.SimpleCommandLauncher$1.onClosed(SimpleCommandLauncher.java:85)
	at hudson.remoting.Channel.terminate(Channel.java:1219)
	at hudson.remoting.Channel$CloseCommand.execute(Channel.java:1438)
	at hudson.remoting.Channel$1.handle(Channel.java:664)
	at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:86)

jglick · 2025-02-18T22:29:15Z

Almost, but not quite. Weird because the log does show the agent process having been killed before the test cleanup begins.

This reverts commit 06190e8. It seemed to mostly work, but not in one case.

MarkEWaite

Thanks very much for the investigation!

jglick · 2025-02-19T00:39:05Z

So this failure is puzzling me.

11.263 [id=227]	INFO	c.c.j.support.SupportTestUtils#stopAgents: successfully deleted C:\Jenkins\agent\workspace\57ae19e04dee06d2eba8c5f1128e603e\target\tmp\j h17291846234312879372\agent-work-dirs
…
11.374 [id=227]	INFO	o.j.h.t.TemporaryDirectoryAllocator#dispose: deleting C:\Jenkins\agent\workspace\57ae19e04dee06d2eba8c5f1128e603e\target\tmp\j h17291846234312879372
…
java.nio.file.FileSystemException: C:\Jenkins\agent\workspace\57ae19e04dee06d2eba8c5f1128e603e\target\tmp\j h17291846234312879372\agent-work-dirs\slave0\support\all_2025-02-18_23.39.21.log: The process cannot access the file because it is being used by another process

would seem to indicate that something recreated this file after its containing directory had been deleted.

jglick · 2025-02-19T01:14:06Z

Two tracks now: jenkinsci/jenkins-test-harness#922; and trying to see if I can get SupportLogHandler.close to be called when the connection is closed.

jglick · 2025-02-19T01:28:03Z

No luck so far on the latter approach:

diff --git src/main/java/com/cloudbees/jenkins/support/SupportPlugin.java src/main/java/com/cloudbees/jenkins/support/SupportPlugin.java
index 3e57d01..c09f9d6 100644
--- src/main/java/com/cloudbees/jenkins/support/SupportPlugin.java
+++ src/main/java/com/cloudbees/jenkins/support/SupportPlugin.java
@@ -57,6 +57,7 @@ import hudson.model.Descriptor;
 import hudson.model.Node;
 import hudson.model.PeriodicWork;
 import hudson.model.TaskListener;
+import hudson.remoting.Channel;
 import hudson.remoting.ChannelClosedException;
 import hudson.remoting.Future;
 import hudson.remoting.VirtualChannel;
@@ -877,6 +878,12 @@ public class SupportPlugin extends Plugin {
             LogHolder.AGENT_LOG_HANDLER.setLevel(level);
             LogHolder.AGENT_LOG_HANDLER.setDirectory(new File(rootPath.getRemote(), SUPPORT_DIRECTORY_NAME), "all");
             ROOT_LOGGER.addHandler(LogHolder.AGENT_LOG_HANDLER);
+            Channel.currentOrFail().addListener(new Channel.Listener() {
+                @Override
+                public void onClosed(Channel channel, IOException cause) {
+                    LogHolder.AGENT_LOG_HANDLER.close();
+                }
+            });
             return null;
         }
     }

So far as I can tell, onClosed does not get called.

jglick · 2025-02-19T02:16:05Z

Still failing so I am running out of hypotheses.

jglick · 2025-02-19T03:09:20Z

With better logs we can see that the agent process is terminated (exit code zero), and yet 59ms later the attempt to delete its working directory fails. This remark

If a process terminates with a portion of a file locked or closes a file that has outstanding locks, the locks are unlocked by the operating system. However, the time it takes for the operating system to unlock these locks depends upon available system resources. Therefore, it is recommended that your process explicitly unlock all files it has locked when it terminates. If this is not done, access to these files may be denied if the operating system has not yet unlocked them.

suggests that jenkinsci/jenkins-test-harness#922 (while probably a step in the right direction) cannot suffice. Either I figure out how to make the agent release its locks before it exits, or the deletion code needs to just retry for a while.

…lying on channel events

very stale

jglick · 2025-02-19T19:27:01Z

pom.xml

@@ -70,6 +70,8 @@
    <!-- https://www.jenkins.io/doc/developer/plugin-development/choosing-jenkins-baseline/ -->
    <jenkins.baseline>2.479</jenkins.baseline>
    <jenkins.version>${jenkins.baseline}.1</jenkins.version>
+    <!-- TODO until in parent -->
+    <jenkins-test-harness.version>2403.v256947ecb_c8a_</jenkins-test-harness.version>


jenkinsci/jenkins-test-harness#922

Previously, the agent JVM launched by SimpleCommandLauncher (JenkinsRule.createSlave / .createOnlineSlave) would be terminated when the Computer was disconnected as part of Jenkins.cleanUp, but asynchronously and possible slightly later, when TemporaryDirectoryAllocator was already trying to clean up.

jglick · 2025-02-19T19:29:32Z

src/main/java/com/cloudbees/jenkins/support/SupportLogHandler.java

@@ -234,6 +234,7 @@ private void setFile(File file) throws FileNotFoundException {
                parentFile.mkdirs();
            }

+            StreamUtils.closeQuietly(null); // ensure class is loaded so close() can succeed


Does nothing but loads this class. Otherwise there can occasionally be a NoClassDefFoundError from close during agent shutdown, at which time it is too late to load new classes from RemoteClassLoader because the connection has already been closed.

jglick · 2025-02-19T19:30:43Z

src/main/java/com/cloudbees/jenkins/support/SupportPlugin.java

@@ -862,6 +862,15 @@ public Void call() {
            // avoid double installation of the handler. JNLP agents can reconnect to the controller multiple times
            // and each connection gets a different RemoteClassLoader, so we need to evict them by class name,
            // not by their identity.
+            closeAll();
+            Runtime.getRuntime().addShutdownHook(new Thread(LogInitializer::closeAll, "close log handlers"));


Ensures that the file handle is closed before the JVM exits. Likely irrelevant on Linux, but seems to matter on Windows, where the OS will release mandatory file locks “sometime” after the process exits but not necessarily quickly enough for a test.

MarkEWaite

Thanks very, very much!

jglick · 2025-02-19T20:08:02Z

Yet another flake 👀

…diate disconnection

Stop agents before exiting test cases

8ecc1f3

jglick added the chore label Feb 14, 2025

jglick requested a review from a team as a code owner February 14, 2025 20:13

jglick requested a review from Dohbedoh February 14, 2025 20:13

jglick commented Feb 14, 2025

View reviewed changes

src/test/java/com/cloudbees/jenkins/support/CheckFilterTest.java Outdated Show resolved Hide resolved

jglick marked this pull request as draft February 17, 2025 12:24

jglick mentioned this pull request Feb 18, 2025

WIP , possible fix for the breaking tests for windows #626

Closed

Trying harder to delete agent-work-dirs

7fcc00b

jglick mentioned this pull request Feb 18, 2025

Let SimpleCommandLauncher kill the agent JVM more promptly when disconnected jenkinsci/jenkins-test-harness#921

Closed

jenkinsci/jenkins-test-harness#921 should suffice

06190e8

jglick mentioned this pull request Feb 18, 2025

WorkflowTest.env failure jenkinsci/workflow-cps-plugin#986

Merged

Revert "jenkinsci/jenkins-test-harness#921 should suffice"

201f598

This reverts commit 06190e8. It seemed to mostly work, but not in one case.

jglick marked this pull request as ready for review February 18, 2025 23:12

jglick enabled auto-merge February 18, 2025 23:12

jglick added this pull request to the merge queue Feb 18, 2025

github-merge-queue bot removed this pull request from the merge queue due to failed status checks Feb 18, 2025

MarkEWaite previously approved these changes Feb 19, 2025

View reviewed changes

jglick marked this pull request as draft February 19, 2025 01:12

Maybe jenkinsci/jenkins-test-harness#922 is all I needed?

7449467

Bump

6aafeb3

Another attempt at closing log handlers before exit, this time not re…

173a6c4

…lying on channel events

jglick changed the title ~~Stop agents before exiting test cases~~ Stop agents before exiting test cases, and reliably close all_*.log when agents exit Feb 19, 2025

jglick mentioned this pull request Feb 19, 2025

Implement afterDisconnect in SimpleCommandLauncher jenkinsci/jenkins-test-harness#922

Merged

jglick added bug and removed chore labels Feb 19, 2025

jenkinsci/jenkins-test-harness#922 released

f9aa9e6

jglick marked this pull request as ready for review February 19, 2025 19:25

jglick requested review from MarkEWaite, dwnusbaum and jtnord February 19, 2025 19:25

jglick commented Feb 19, 2025

View reviewed changes

dwnusbaum approved these changes Feb 19, 2025

View reviewed changes

jglick enabled auto-merge February 19, 2025 19:33

MarkEWaite approved these changes Feb 19, 2025

View reviewed changes

jglick added this pull request to the merge queue Feb 19, 2025

github-merge-queue bot removed this pull request from the merge queue due to failed status checks Feb 19, 2025

jtnord approved these changes Feb 19, 2025

View reviewed changes

SmartLogCleanerTest flake; Jenkins.removeNode does not force imme…

d576db6

…diate disconnection

jglick enabled auto-merge February 19, 2025 20:13

jtnord approved these changes Feb 19, 2025

View reviewed changes

dwnusbaum approved these changes Feb 19, 2025

View reviewed changes

jglick added this pull request to the merge queue Feb 19, 2025

Merged via the queue into jenkinsci:master with commit 49b01a4 Feb 19, 2025
17 checks passed

jglick deleted the SupportLogHandler branch February 19, 2025 20:47

This was referenced Feb 20, 2025

Close all files in CustomLogsTest #629

Merged

Bump deps to address test flakes on Windows jenkinsci/pipeline-model-definition-plugin#764

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stop agents before exiting test cases, and reliably close `all_*.log` when agents exit #624

Stop agents before exiting test cases, and reliably close `all_*.log` when agents exit #624

jglick commented Feb 14, 2025 •

edited

Loading

jglick commented Feb 17, 2025

jglick commented Feb 18, 2025

jglick commented Feb 18, 2025

jglick commented Feb 18, 2025 •

edited

Loading

MarkEWaite left a comment

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick Feb 19, 2025 •

edited

Loading

jglick Feb 19, 2025 •

edited

Loading

jglick Feb 19, 2025

MarkEWaite left a comment

jglick commented Feb 19, 2025

Stop agents before exiting test cases, and reliably close all_*.log when agents exit #624

Stop agents before exiting test cases, and reliably close all_*.log when agents exit #624

Conversation

jglick commented Feb 14, 2025 • edited Loading

jglick commented Feb 17, 2025

jglick commented Feb 18, 2025

jglick commented Feb 18, 2025

jglick commented Feb 18, 2025 • edited Loading

MarkEWaite left a comment

Choose a reason for hiding this comment

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick commented Feb 19, 2025

jglick Feb 19, 2025 • edited Loading

Choose a reason for hiding this comment

jglick Feb 19, 2025 • edited Loading

Choose a reason for hiding this comment

jglick Feb 19, 2025

Choose a reason for hiding this comment

MarkEWaite left a comment

Choose a reason for hiding this comment

jglick commented Feb 19, 2025

Stop agents before exiting test cases, and reliably close `all_*.log` when agents exit #624

Stop agents before exiting test cases, and reliably close `all_*.log` when agents exit #624

jglick commented Feb 14, 2025 •

edited

Loading

jglick commented Feb 18, 2025 •

edited

Loading

jglick Feb 19, 2025 •

edited

Loading

jglick Feb 19, 2025 •

edited

Loading