From c57af92ba2781a2f25cae6673070bc0428ce2b7a Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Thu, 13 Jul 2023 18:45:39 -0400 Subject: [PATCH 1/4] Define `OutputStreamTaskListener` & close `BufferedBuildListener` --- .../workflow/log/BufferedBuildListener.java | 72 ++++++++++++- .../log/OutputStreamTaskListener.java | 100 ++++++++++++++++++ .../workflow/log/TaskListenerDecorator.java | 26 +++-- 3 files changed, 185 insertions(+), 13 deletions(-) create mode 100644 src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java b/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java index 85316ff8..89e57694 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java @@ -28,27 +28,38 @@ import edu.umd.cs.findbugs.annotations.SuppressFBWarnings; import hudson.CloseProofOutputStream; import hudson.model.BuildListener; +import hudson.remoting.Channel; +import hudson.remoting.ChannelClosedException; import hudson.remoting.RemoteOutputStream; import hudson.util.StreamTaskListener; import java.io.Closeable; +import java.io.FilterOutputStream; import java.io.IOException; import java.io.OutputStream; import java.io.PrintStream; +import java.nio.charset.StandardCharsets; +import java.util.logging.Logger; import org.jenkinsci.remoting.SerializableOnlyOverRemoting; /** * Unlike {@link StreamTaskListener} this does not set {@code autoflush} on the reconstructed {@link PrintStream}. * It also wraps on the remote side in {@link DelayBufferedOutputStream}. */ -final class BufferedBuildListener implements BuildListener, Closeable, SerializableOnlyOverRemoting { +final class BufferedBuildListener implements BuildListener, Closeable, SerializableOnlyOverRemoting, OutputStreamTaskListener { + + private static final Logger LOGGER = Logger.getLogger(BufferedBuildListener.class.getName()); private final OutputStream out; @SuppressFBWarnings(value = "SE_BAD_FIELD", justification = "using Replacement anyway, fields here are irrelevant") private final PrintStream ps; - BufferedBuildListener(OutputStream out) throws IOException { + BufferedBuildListener(OutputStream out) { this.out = out; - ps = new PrintStream(out, false, "UTF-8"); + ps = new PrintStream(out, false, StandardCharsets.UTF_8); + } + + @Override public OutputStream getOutputStream() { + return out; } @NonNull @@ -75,8 +86,59 @@ private static final class Replacement implements SerializableOnlyOverRemoting { this.ros = new RemoteOutputStream(new CloseProofOutputStream(cbl.out)); } - private Object readResolve() throws IOException { - return new BufferedBuildListener(new GCFlushedOutputStream(new DelayBufferedOutputStream(ros, tuning))); + private Object readResolve() { + var cos = new CloseableOutputStream(new GCFlushedOutputStream(new DelayBufferedOutputStream(ros, tuning))); + Channel.currentOrFail().addListener(new Channel.Listener() { + @Override public void onClosed(Channel channel, IOException cause) { + LOGGER.fine(() -> "closing " + channel.getName()); + cos.close(channel, cause); + } + }); + return new BufferedBuildListener(cos); + } + + } + + /** + * Output stream which throws {@link ChannelClosedException} when appropriate. + * Otherwise callers could continue trying to write to {@link DelayBufferedOutputStream} + * long after {@link Channel#isClosingOrClosed} without errors. + * In the case of {@code org.jenkinsci.plugins.durabletask.Handler.output}, + * this is actively harmful since it would mean that writes apparently succeed + * and {@code last-location.txt} would move forward even though output was lost. + */ + private static final class CloseableOutputStream extends FilterOutputStream { + + /** non-null if closed */ + private Channel channel; + /** optional close cause */ + private IOException cause; + + CloseableOutputStream(OutputStream delegate) { + super(delegate); + } + + void close(Channel channel, IOException cause) { + this.channel = channel; + this.cause = cause; + // Do not call close(): ProxyOutputStream.doClose would just throw ChannelClosedException: …: channel is already closed + } + + private void checkClosed() throws IOException { + if (channel != null) { + throw new ChannelClosedException(channel, cause); + } + LOGGER.finer("not closed yet"); + } + + @Override public void write(int b) throws IOException { + checkClosed(); + out.write(b); + } + + @Override public void write(byte[] b, int off, int len) throws IOException { + checkClosed(); + out.write(b, off, len); } } diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java b/src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java new file mode 100644 index 00000000..729392fc --- /dev/null +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java @@ -0,0 +1,100 @@ +/* + * The MIT License + * + * Copyright 2023 CloudBees, Inc. + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, + * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN + * THE SOFTWARE. + */ + +package org.jenkinsci.plugins.workflow.log; + +import edu.umd.cs.findbugs.annotations.NonNull; +import hudson.model.TaskListener; +import java.io.FilterOutputStream; +import java.io.OutputStream; +import java.io.PrintStream; +import java.lang.reflect.Field; +import java.lang.reflect.InaccessibleObjectException; +import java.nio.charset.StandardCharsets; +import java.util.logging.Level; +import java.util.logging.Logger; +import org.apache.commons.io.output.ClosedOutputStream; +import org.kohsuke.accmod.Restricted; +import org.kohsuke.accmod.restrictions.Beta; + +/** + * {@link TaskListener} which can directly return an {@link OutputStream} not wrapped in a {@link PrintStream}. + * This is important for logging since the error-swallowing behavior of {@link PrintStream} is unwanted, + * and {@link PrintStream#checkError} is useless. + *

{@link #getLogger} should generally be implemented in terms of {@link #getOutputStream} + * (no autoflush, using {@link StandardCharsets#UTF_8}) + * but there is not a {@code default} implementation since the result should be cached in a field. + */ +@Restricted(Beta.class) +public interface OutputStreamTaskListener extends TaskListener { + + /** + * Returns the {@link OutputStream} from which {@link #getLogger} was constructed. + */ + @NonNull OutputStream getOutputStream(); + + /** + * Tries to call {@link #getOutputStream} and otherwise falls back to reflective access to {@link PrintStream#out} when possible, at worst returning the {@link PrintStream} itself. + */ + static @NonNull OutputStream getOutputStream(@NonNull TaskListener listener) { + if (listener instanceof OutputStreamTaskListener) { + return ((OutputStreamTaskListener) listener).getOutputStream(); + } + PrintStream ps = listener.getLogger(); + if (ps.getClass() != PrintStream.class) { + Logger.getLogger(OutputStreamTaskListener.class.getName()).warning(() -> "Unexpected PrintStream subclass " + ps.getClass().getName() + " which might override write(…); error handling is degraded unless OutputStreamTaskListener is used: " + listener.getClass().getName()); + return ps; + } + if (Runtime.version().compareToIgnoreOptional(Runtime.Version.parse("17")) >= 0) { + Logger.getLogger(OutputStreamTaskListener.class.getName()).warning(() -> "On Java 17+ error handling is degraded unless OutputStreamTaskListener is used: " + listener.getClass().getName()); + return ps; + } + Field printStreamDelegate; + try { + printStreamDelegate = FilterOutputStream.class.getDeclaredField("out"); + } catch (NoSuchFieldException x) { + Logger.getLogger(OutputStreamTaskListener.class.getName()).log(Level.WARNING, "PrintStream.out defined in Java Platform and protected, so should not happen.", x); + return ps; + } + try { + printStreamDelegate.setAccessible(true); + } catch (InaccessibleObjectException x) { + Logger.getLogger(OutputStreamTaskListener.class.getName()).warning(() -> "Using --illegal-access=deny? Error handling is degraded unless OutputStreamTaskListener is used: " + listener.getClass().getName()); + return ps; + } + OutputStream os; + try { + os = (OutputStream) printStreamDelegate.get(ps); + } catch (IllegalAccessException x) { + Logger.getLogger(OutputStreamTaskListener.class.getName()).log(Level.WARNING, "Unexpected failure to access PrintStream.out", x); + return ps; + } + if (os == null) { + // like PrintStream.ensureOpen + return ClosedOutputStream.CLOSED_OUTPUT_STREAM; + } + return os; + } + +} diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java b/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java index bc9c664d..26d9e4ab 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java @@ -37,7 +37,6 @@ import java.io.OutputStream; import java.io.PrintStream; import java.io.Serializable; -import java.io.UnsupportedEncodingException; import java.util.ArrayList; import java.util.Collections; import java.util.List; @@ -237,7 +236,7 @@ private static OutputStream decorateAll(OutputStream base, List decorators; + private transient OutputStream out; private transient PrintStream logger; DecoratedTaskListener(@NonNull TaskListener delegate, @NonNull List decorators) { @@ -262,14 +262,18 @@ private static final class DecoratedTaskListener implements BuildListener { this.decorators = decorators; } + @NonNull + @Override public OutputStream getOutputStream() { + if (out == null) { + out = decorateAll(OutputStreamTaskListener.getOutputStream(delegate), decorators); + } + return out; + } + @NonNull @Override public PrintStream getLogger() { if (logger == null) { - try { - logger = new PrintStream(decorateAll(delegate.getLogger(), decorators), false, "UTF-8"); - } catch (UnsupportedEncodingException x) { - throw new AssertionError(x); - } + logger = new PrintStream(getOutputStream(), false, StandardCharsets.UTF_8); } return logger; } @@ -280,7 +284,7 @@ private static final class DecoratedTaskListener implements BuildListener { } - private static final class CloseableTaskListener implements BuildListener, AutoCloseable { + private static final class CloseableTaskListener implements BuildListener, AutoCloseable, OutputStreamTaskListener { static BuildListener of(BuildListener mainDelegate, TaskListener closeDelegate) { if (closeDelegate instanceof AutoCloseable) { @@ -301,6 +305,12 @@ private CloseableTaskListener(@NonNull TaskListener mainDelegate, @NonNull TaskL assert closeDelegate instanceof AutoCloseable; } + @NonNull + @Override + public OutputStream getOutputStream() { + return OutputStreamTaskListener.getOutputStream(mainDelegate); + } + @NonNull @Override public PrintStream getLogger() { return mainDelegate.getLogger(); From 89dc1508ac78aab57fb93fd128fb60ef6b5ea216 Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Thu, 13 Jul 2023 18:58:24 -0400 Subject: [PATCH 2/4] Better `CloseableOutputStream.toString` --- .../jenkinsci/plugins/workflow/log/BufferedBuildListener.java | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java b/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java index 89e57694..d7794ee5 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java @@ -141,6 +141,10 @@ private void checkClosed() throws IOException { out.write(b, off, len); } + @Override public String toString() { + return "CloseableOutputStream[" + out + "]"; + } + } } From 9b7f964aad7076033337eb137664a8aab84dd39b Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Thu, 13 Jul 2023 19:12:45 -0400 Subject: [PATCH 3/4] `OutputStreamTaskListener.Default` for convenience --- .../workflow/log/BufferedBuildListener.java | 15 ++------------- .../log/OutputStreamTaskListener.java | 19 ++++++++++++++++--- .../workflow/log/TaskListenerDecorator.java | 11 +---------- 3 files changed, 19 insertions(+), 26 deletions(-) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java b/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java index d7794ee5..34a61c0f 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/BufferedBuildListener.java @@ -24,8 +24,6 @@ package org.jenkinsci.plugins.workflow.log; -import edu.umd.cs.findbugs.annotations.NonNull; -import edu.umd.cs.findbugs.annotations.SuppressFBWarnings; import hudson.CloseProofOutputStream; import hudson.model.BuildListener; import hudson.remoting.Channel; @@ -37,7 +35,6 @@ import java.io.IOException; import java.io.OutputStream; import java.io.PrintStream; -import java.nio.charset.StandardCharsets; import java.util.logging.Logger; import org.jenkinsci.remoting.SerializableOnlyOverRemoting; @@ -45,30 +42,22 @@ * Unlike {@link StreamTaskListener} this does not set {@code autoflush} on the reconstructed {@link PrintStream}. * It also wraps on the remote side in {@link DelayBufferedOutputStream}. */ -final class BufferedBuildListener implements BuildListener, Closeable, SerializableOnlyOverRemoting, OutputStreamTaskListener { +final class BufferedBuildListener extends OutputStreamTaskListener.Default implements BuildListener, Closeable, SerializableOnlyOverRemoting { private static final Logger LOGGER = Logger.getLogger(BufferedBuildListener.class.getName()); private final OutputStream out; - @SuppressFBWarnings(value = "SE_BAD_FIELD", justification = "using Replacement anyway, fields here are irrelevant") - private final PrintStream ps; BufferedBuildListener(OutputStream out) { this.out = out; - ps = new PrintStream(out, false, StandardCharsets.UTF_8); } @Override public OutputStream getOutputStream() { return out; } - @NonNull - @Override public PrintStream getLogger() { - return ps; - } - @Override public void close() throws IOException { - ps.close(); + getLogger().close(); } private Object writeReplace() { diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java b/src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java index 729392fc..54b72e8f 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/OutputStreamTaskListener.java @@ -42,9 +42,6 @@ * {@link TaskListener} which can directly return an {@link OutputStream} not wrapped in a {@link PrintStream}. * This is important for logging since the error-swallowing behavior of {@link PrintStream} is unwanted, * and {@link PrintStream#checkError} is useless. - *

{@link #getLogger} should generally be implemented in terms of {@link #getOutputStream} - * (no autoflush, using {@link StandardCharsets#UTF_8}) - * but there is not a {@code default} implementation since the result should be cached in a field. */ @Restricted(Beta.class) public interface OutputStreamTaskListener extends TaskListener { @@ -97,4 +94,20 @@ public interface OutputStreamTaskListener extends TaskListener { return os; } + /** + * Convenience implementation handling {@link #getLogger}. + */ + abstract class Default implements OutputStreamTaskListener { + + private transient PrintStream ps; + + @Override public synchronized PrintStream getLogger() { + if (ps == null) { + ps = new PrintStream(getOutputStream(), false, StandardCharsets.UTF_8); + } + return ps; + } + + } + } diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java b/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java index 26d9e4ab..2d2d2c16 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/TaskListenerDecorator.java @@ -236,7 +236,7 @@ private static OutputStream decorateAll(OutputStream base, List decorators; private transient OutputStream out; - private transient PrintStream logger; DecoratedTaskListener(@NonNull TaskListener delegate, @NonNull List decorators) { this.delegate = delegate; @@ -270,14 +269,6 @@ private static final class DecoratedTaskListener implements BuildListener, Outpu return out; } - @NonNull - @Override public PrintStream getLogger() { - if (logger == null) { - logger = new PrintStream(getOutputStream(), false, StandardCharsets.UTF_8); - } - return logger; - } - @Override public String toString() { return "DecoratedTaskListener[" + delegate + decorators + "]"; } From 12f6b094cead7aef96b57a0bf1d689147d678a15 Mon Sep 17 00:00:00 2001 From: Jesse Glick Date: Thu, 27 Jul 2023 19:23:15 -0400 Subject: [PATCH 4/4] Tone down logging, copying utility from https://github.com/jenkinsci/remoting/pull/657 --- .../workflow/log/GCFlushedOutputStream.java | 21 ++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) diff --git a/src/main/java/org/jenkinsci/plugins/workflow/log/GCFlushedOutputStream.java b/src/main/java/org/jenkinsci/plugins/workflow/log/GCFlushedOutputStream.java index 7e47b7ab..0123213c 100644 --- a/src/main/java/org/jenkinsci/plugins/workflow/log/GCFlushedOutputStream.java +++ b/src/main/java/org/jenkinsci/plugins/workflow/log/GCFlushedOutputStream.java @@ -35,6 +35,10 @@ import java.util.logging.Logger; 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.util.Timer; /** @@ -58,6 +62,21 @@ final class GCFlushedOutputStream extends FilterOutputStream { return "GCFlushedOutputStream[" + out + "]"; } + // 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(GCFlushedOutputStream::isClosedChannelException); + } + } + /** * Flushes streams prior to garbage collection. * ({@link BufferedOutputStream} does not do this automatically.) @@ -78,7 +97,7 @@ private static final class FlushRef extends PhantomReference