+ * In particular, subclasses should avoid acquiring locks around code which + * calls back to arbitrary user-supplied objects, especially during log record + * formatting. Holding a lock around any such callbacks creates a deadlock risk + * between logging code and user code. + *
+ * As such, general purpose {@code Handler} subclasses should not synchronize + * their {@link #publish(LogRecord)} methods, or call {@code super.publish()} + * while holding locks, since these are typically expected to need to process + * and format user-supplied arguments. * * @since 1.4 */ - public abstract class Handler { private static final int offValue = Level.OFF.intValue(); @@ -123,6 +138,10 @@ protected Handler() { } *
* The {@code Handler} is responsible for formatting the message, when and * if necessary. The formatting should include localization. + *
+ * @apiNote To avoid the risk of deadlock, implementations of this method + * should avoid holding any locks while calling out to application code, + * such as the formatting of {@code LogRecord}. * * @param record description of the log event. A null record is * silently ignored and is not published diff --git a/src/java.logging/share/classes/java/util/logging/SocketHandler.java b/src/java.logging/share/classes/java/util/logging/SocketHandler.java index 380cc20add44f..d20d857035777 100644 --- a/src/java.logging/share/classes/java/util/logging/SocketHandler.java +++ b/src/java.logging/share/classes/java/util/logging/SocketHandler.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2024, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2025, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -168,14 +168,17 @@ public synchronized void close() { /** * Format and publish a {@code LogRecord}. * + * @implSpec This method is not synchronized, and subclasses must not define + * overridden {@code publish()} methods to be {@code synchronized} if they + * call {@code super.publish()} or format user arguments. See the + * {@linkplain Handler##threadSafety discussion in java.util.logging.Handler} + * for more information. + * * @param record description of the log event. A null record is * silently ignored and is not published */ @Override - public synchronized void publish(LogRecord record) { - if (!isLoggable(record)) { - return; - } + public void publish(LogRecord record) { super.publish(record); flush(); } diff --git a/src/java.logging/share/classes/java/util/logging/StreamHandler.java b/src/java.logging/share/classes/java/util/logging/StreamHandler.java index 31cb6605fbc79..5fc70b5dde9c3 100644 --- a/src/java.logging/share/classes/java/util/logging/StreamHandler.java +++ b/src/java.logging/share/classes/java/util/logging/StreamHandler.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2024, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2025, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -180,17 +180,31 @@ public synchronized void setEncoding(String encoding) * {@code OutputStream}, the {@code Formatter}'s "head" string is * written to the stream before the {@code LogRecord} is written. * + * @implSpec This method avoids acquiring locks during {@code LogRecord} + * formatting, but {@code this} instance is synchronized when writing to the + * output stream. To avoid deadlock risk, subclasses must not hold locks + * while calling {@code super.publish()}. Specifically, subclasses must + * not define the overridden {@code publish()} method to be + * {@code synchronized} if they call {@code super.publish()}. + * * @param record description of the log event. A null record is * silently ignored and is not published */ @Override - public synchronized void publish(LogRecord record) { - if (!isLoggable(record)) { + public void publish(LogRecord record) { + if (!isLoggable(record)) { return; } + // Read once for consistency (whether in or outside the locked region + // is not important). + Formatter formatter = getFormatter(); + // JDK-8349206: To avoid deadlock risk, it is essential that the handler + // is not locked while formatting the log record. Methods such as + // reportError() and isLoggable() are defined to be thread safe, so we + // can restrict locking to just writing the message. String msg; try { - msg = getFormatter().format(record); + msg = formatter.format(record); } catch (Exception ex) { // We don't want to throw an exception here, but we // report the exception to any registered ErrorManager. @@ -199,12 +213,15 @@ public synchronized void publish(LogRecord record) { } try { - Writer writer = this.writer; - if (!doneHeader) { - writer.write(getFormatter().getHead(this)); - doneHeader = true; + synchronized(this) { + Writer writer = this.writer; + if (!doneHeader) { + writer.write(formatter.getHead(this)); + doneHeader = true; + } + writer.write(msg); + synchronousPostWriteHook(); } - writer.write(msg); } catch (Exception ex) { // We don't want to throw an exception here, but we // report the exception to any registered ErrorManager. @@ -212,6 +229,17 @@ public synchronized void publish(LogRecord record) { } } + /** + * Overridden by other handlers in this package to facilitate synchronous + * post-write behaviour. If other handlers need similar functionality, it + * might be feasible to make this method protected (see JDK-8349206), but + * please find a better name if you do ;). + */ + void synchronousPostWriteHook() { + // Empty by default. We could do: + // assert Thread.holdsLock(this); + // but this is already covered by unit tests. + } /** * Check if this {@code Handler} would actually log a given {@code LogRecord}. @@ -249,15 +277,17 @@ public synchronized void flush() { } } + // Called synchronously with "this" handler instance locked. private void flushAndClose() { Writer writer = this.writer; if (writer != null) { + Formatter formatter = getFormatter(); try { if (!doneHeader) { - writer.write(getFormatter().getHead(this)); + writer.write(formatter.getHead(this)); doneHeader = true; } - writer.write(getFormatter().getTail(this)); + writer.write(formatter.getTail(this)); writer.flush(); writer.close(); } catch (Exception ex) { diff --git a/test/jdk/java/util/logging/Handler/StreamHandlerLockingTest.java b/test/jdk/java/util/logging/Handler/StreamHandlerLockingTest.java new file mode 100644 index 0000000000000..bc137ea431515 --- /dev/null +++ b/test/jdk/java/util/logging/Handler/StreamHandlerLockingTest.java @@ -0,0 +1,105 @@ +/* + * Copyright (c) 2025, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +/* + * @test + * @bug 8349206 + * @summary j.u.l.Handler classes create deadlock risk via synchronized publish() method. + * @modules java.base/sun.util.logging + * java.logging + * @build java.logging/java.util.logging.TestStreamHandler + * @run main/othervm StreamHandlerLockingTest + */ + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.util.logging.Formatter; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.TestStreamHandler; + +public class StreamHandlerLockingTest { + static class TestFormatter extends Formatter { + final Handler handler; + + TestFormatter(Handler handler) { + this.handler = handler; + } + + @Override + public String format(LogRecord record) { + if (Thread.holdsLock(handler)) { + throw new AssertionError("format() was called with handler locked (bad)."); + } + return record.getMessage() + "\n"; + } + + @Override + public String getHead(Handler h) { + // This is currently true, and not easy to make unsynchronized. + if (!Thread.holdsLock(handler)) { + throw new AssertionError("getHead() expected to be called with handler locked."); + } + return "--HEAD--\n"; + } + + @Override + public String getTail(Handler h) { + // This is currently true, and not easy to make unsynchronized. + if (!Thread.holdsLock(handler)) { + throw new AssertionError("getTail() expected to be called with handler locked."); + } + return "--TAIL--\n"; + } + } + + private static final String EXPECTED_LOG = + String.join("\n","--HEAD--", "Hello World", "Some more logging...", "And we're done!", "--TAIL--", ""); + + public static void main(String[] args) throws IOException { + ByteArrayOutputStream out = new ByteArrayOutputStream(); + TestStreamHandler handler = new TestStreamHandler(out); + TestFormatter formatter = new TestFormatter(handler); + handler.setFormatter(formatter); + + handler.publish(log("Hello World")); + handler.publish(log("Some more logging...")); + handler.publish(log("And we're done!")); + handler.close(); + + // Post write callback should have happened once per publish call (with lock held). + if (handler.callbackCount != 3) { + throw new AssertionError("Unexpected callback count: " + handler.callbackCount); + } + + String logged = out.toString("UTF-8"); + if (!EXPECTED_LOG.equals(logged)) { + throw new AssertionError("Unexpected log contents: " + logged); + } + } + + static LogRecord log(String msg) { + return new LogRecord(Level.INFO, msg); + } +} diff --git a/test/jdk/java/util/logging/Handler/java.logging/java/util/logging/TestStreamHandler.java b/test/jdk/java/util/logging/Handler/java.logging/java/util/logging/TestStreamHandler.java new file mode 100644 index 0000000000000..9446773f3fdbe --- /dev/null +++ b/test/jdk/java/util/logging/Handler/java.logging/java/util/logging/TestStreamHandler.java @@ -0,0 +1,54 @@ +/* + * Copyright (c) 2025, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +package java.util.logging; + +import java.io.OutputStream; +import java.io.UnsupportedEncodingException; + +/** + * A trivial UTF-8 stream handler subclass class to capture whether the + * (package protected) post-write callback method is synchronized. + */ +public class TestStreamHandler extends StreamHandler { + + public int callbackCount = 0; + + public TestStreamHandler(OutputStream out) { + setOutputStream(out); + try { + setEncoding("UTF-8"); + } catch (UnsupportedEncodingException e) { + throw new RuntimeException(e); + } + } + + @Override + void synchronousPostWriteHook() { + if (!Thread.holdsLock(this)) { + throw new AssertionError( + String.format("Post write callback [index=%d] was invoked without handler locked.", callbackCount)); + } + callbackCount++; + } +} diff --git a/test/jdk/java/util/logging/LoggingDeadlock5.java b/test/jdk/java/util/logging/LoggingDeadlock5.java new file mode 100644 index 0000000000000..6d75c84839a7b --- /dev/null +++ b/test/jdk/java/util/logging/LoggingDeadlock5.java @@ -0,0 +1,202 @@ +/* + * Copyright (c) 2025, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +/* + * @test + * @bug 8349206 + * @summary j.u.l.Handler classes create deadlock risk via synchronized publish() method. + * @modules java.base/sun.util.logging + * java.logging + * @run main/othervm LoggingDeadlock5 + */ + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.UnsupportedEncodingException; +import java.nio.charset.StandardCharsets; +import java.time.Duration; +import java.util.concurrent.Semaphore; +import java.util.logging.FileHandler; +import java.util.logging.Formatter; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; +import java.util.logging.StreamHandler; + +/** + * This test verifies that logging Handler implementations no longer suffer + * from the deadlock risk outlined in JDK-8349206. + * + *
This test should reliably cause, and detect, deadlocks in a timely
+ * manner if the problem occurs, and SHOULD NOT time out.
+ */
+public class LoggingDeadlock5 {
+ private static final String UTF_8 = StandardCharsets.UTF_8.name();
+
+ // Formatter which calls toString() on all arguments.
+ private static final Formatter TEST_FORMATTER = new Formatter() {
+ @Override
+ public String format(LogRecord record) {
+ // All we care about is that our formatter will invoke toString() on user arguments.
+ for (Object p : record.getParameters()) {
+ var unused = p.toString();
+ }
+ return "