From ce9adda134431b8e1e4e3710236555c963ad416a Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Thu, 27 Jul 2023 19:20:55 -0400 Subject: [PATCH 1/2] Use async calls where possible, and add some richer logging --- .../plugins/durabletask/FileMonitoringTask.java | 10 ++++++---- .../org/jenkinsci/plugins/durabletask/Handler.java | 6 ++++-- 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java b/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java index 9e78653a..4f9ef885 100644 --- a/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java +++ b/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java @@ -541,8 +541,8 @@ public FilePath getOutputFile(FilePath workspace) throws IOException, Interrupte } @Override public void watch(FilePath workspace, Handler handler, TaskListener listener) throws IOException, InterruptedException, ClassCastException { - workspace.act(new StartWatching(this, handler, listener)); - LOGGER.log(Level.FINE, "started asynchronous watch in {0}", controlDir); + workspace.actAsync(new StartWatching(this, handler, listener)); + LOGGER.log(Level.FINE, "started asynchronous watch in " + controlDir, new Throwable()); } /** @@ -585,6 +585,7 @@ private static class Watcher implements Runnable { private final @CheckForNull Charset cs; Watcher(FileMonitoringController controller, FilePath workspace, Handler handler, TaskListener listener) { + LOGGER.log(Level.FINE, "starting " + this, new Throwable()); this.controller = controller; this.workspace = workspace; this.handler = handler; @@ -611,7 +612,8 @@ private static class Watcher implements Runnable { handler.output(utf8EncodedStream); long newLocation = ch.position(); lastLocationFile.write(Long.toString(newLocation), null); - LOGGER.log(Level.FINER, "copied {0} bytes from {1}", new Object[] {newLocation - lastLocation, logFile}); + long delta = newLocation - lastLocation; + LOGGER.finer(() -> this + " copied " + delta + " bytes from " + logFile); } } if (exitStatus != null) { @@ -621,7 +623,7 @@ private static class Watcher implements Runnable { } else { output = null; } - LOGGER.log(Level.FINE, "exiting with code {0}", exitStatus); + LOGGER.fine(() -> this + " exiting with code " + exitStatus); handler.exited(exitStatus, output); controller.cleanup(workspace); } else { diff --git a/src/main/java/org/jenkinsci/plugins/durabletask/Handler.java b/src/main/java/org/jenkinsci/plugins/durabletask/Handler.java index abd1edba..b7bdd046 100644 --- a/src/main/java/org/jenkinsci/plugins/durabletask/Handler.java +++ b/src/main/java/org/jenkinsci/plugins/durabletask/Handler.java @@ -31,13 +31,15 @@ import java.io.Serializable; import edu.umd.cs.findbugs.annotations.NonNull; import edu.umd.cs.findbugs.annotations.Nullable; +import hudson.remoting.Asynchronous; +import org.jenkinsci.remoting.SerializableOnlyOverRemoting; /** * A remote handler which may be sent to an agent and handle process output and results. * If it needs to communicate with the master, you may use {@link VirtualChannel#export}. * @see Controller#watch */ -public abstract class Handler implements Serializable { // TODO 2.107+ SerializableOnlyOverRemoting +public abstract class Handler implements SerializableOnlyOverRemoting { /** * Notification that new process output is available. @@ -60,8 +62,8 @@ public abstract class Handler implements Serializable { // TODO 2.107+ Serializa * you still need to occasionally poll for an exit status from the master. * @param code the exit code, if known (0 conventionally represents success); may be negative for anomalous conditions such as a missing process * @param output standard output captured, if {@link DurableTask#captureOutput} was called; else null - * @throws Exception if anything goes wrong, this watch is deactivated */ + @Asynchronous public abstract void exited(int code, @Nullable byte[] output) throws Exception; } From bfaf04b091786979aeb28d08b4b88dc7d90089d5 Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Thu, 27 Jul 2023 19:21:17 -0400 Subject: [PATCH 2/2] Tone down logging --- .../durabletask/FileMonitoringTask.java | 25 ++++++++++++++++++- 1 file changed, 24 insertions(+), 1 deletion(-) diff --git a/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java b/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java index 4f9ef885..218842fe 100644 --- a/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java +++ b/src/main/java/org/jenkinsci/plugins/durabletask/FileMonitoringTask.java @@ -71,6 +71,10 @@ import java.util.logging.Logger; import edu.umd.cs.findbugs.annotations.CheckForNull; import edu.umd.cs.findbugs.annotations.NonNull; +import hudson.remoting.ChannelClosedException; +import java.io.EOFException; +import java.nio.channels.ClosedChannelException; +import java.util.stream.Stream; import jenkins.MasterToSlaveFileCallable; import jenkins.model.Jenkins; import jenkins.security.MasterToSlaveCallable; @@ -576,6 +580,21 @@ private static class StartWatching extends MasterToSlaveFileCallable { } + // TODO https://github.com/jenkinsci/remoting/pull/657 + private static boolean isClosedChannelException(Throwable t) { + if (t instanceof ClosedChannelException) { + return true; + } else if (t instanceof ChannelClosedException) { + return true; + } else if (t instanceof EOFException) { + return true; + } else if (t == null) { + return false; + } else { + return isClosedChannelException(t.getCause()) || Stream.of(t.getSuppressed()).anyMatch(FileMonitoringTask::isClosedChannelException); + } + } + private static class Watcher implements Runnable { private final FileMonitoringController controller; @@ -638,7 +657,11 @@ private static class Watcher implements Runnable { } } catch (Exception x) { // note that LOGGER here is going to the agent log, not master log - LOGGER.log(Level.WARNING, "giving up on watching " + controller.controlDir, x); + if (isClosedChannelException(x)) { + LOGGER.warning(() -> this + " giving up on watching " + controller.controlDir); + } else { + LOGGER.log(Level.WARNING, this + " giving up on watching " + controller.controlDir, x); + } // Typically this will have been inside Handler.output, e.g.: // hudson.remoting.ChannelClosedException: channel is already closed // at hudson.remoting.Channel.send(Channel.java:667)