From 157594c26daed3a34804f1778f979e40ec422301 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Thu, 6 Feb 2025 11:09:07 +0100 Subject: [PATCH 01/19] 8349206: j.u.l.Handler classes create deadlock risk via synchronized publish() method. 1. Remove synchronization of calls to publish() in Handlers in java.util.logging package. 2. Add explanatory comments to various affected methods. 3. Add a test to ensure deadlocks no longer occur. Note that this change does not address issue in MemoryHandler (see JDK-8349208). --- .../java/util/logging/FileHandler.java | 18 +- .../classes/java/util/logging/Formatter.java | 23 ++- .../classes/java/util/logging/Handler.java | 7 +- .../java/util/logging/SocketHandler.java | 6 +- .../java/util/logging/StreamHandler.java | 23 ++- .../java/util/logging/LoggingDeadlock5.java | 189 ++++++++++++++++++ 6 files changed, 249 insertions(+), 17 deletions(-) create mode 100644 test/jdk/java/util/logging/LoggingDeadlock5.java diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index 3c36a21516c07..ca67c05b8b7b5 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -1,5 +1,6 @@ /* - * Copyright (c) 2000, 2024, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2024, 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 @@ -739,14 +740,21 @@ private synchronized void rotate() { * silently ignored and is not published */ @Override - public synchronized void publish(LogRecord record) { + public void publish(LogRecord record) { if (!isLoggable(record)) { return; } + // JDK-8349206: DO NOT lock during publishing to avoid deadlock risk when + // invoking toString() on user parameters. super.publish(record); - flush(); - if (limit > 0 && (meter.written >= limit || meter.written < 0)) { - rotate(); + // We must lock around the check of meter.xxx fields, and the call to + // rotate(), and since flush() is also synchronized on the same instance, + // we might as well lock around everything. + synchronized(this) { + flush(); + if (limit > 0 && (meter.written >= limit || meter.written < 0)) { + rotate(); + } } } diff --git a/src/java.logging/share/classes/java/util/logging/Formatter.java b/src/java.logging/share/classes/java/util/logging/Formatter.java index a5696b257d124..09447734fc0bb 100644 --- a/src/java.logging/share/classes/java/util/logging/Formatter.java +++ b/src/java.logging/share/classes/java/util/logging/Formatter.java @@ -1,5 +1,6 @@ /* - * Copyright (c) 2000, 2020, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2020, 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 @@ -36,6 +37,9 @@ * Some formatters (such as the XMLFormatter) need to wrap head * and tail strings around a set of formatted records. The getHeader * and getTail methods can be used to obtain these strings. + *

+ * See individual method documentation for information about object + * locking and synchronization for implementations of this class. * * @since 1.4 */ @@ -55,6 +59,9 @@ protected Formatter() { * localized and formatted version of the LogRecord's message field. * It is recommended to use the {@link Formatter#formatMessage} * convenience method to localize and format the message field. + *

+ * This method is expected to be invoked without any logging + * related locks held (since is calls back to user code). * * @param record the log record to be formatted. * @return the formatted log record @@ -67,6 +74,10 @@ protected Formatter() { *

* This base class returns an empty string, but this may be * overridden by subclasses. + *

+ * This method may be invoked with handler related locks held + * and must not be implemented in such a way as to risk + * deadlocks, such as by calling back into user code. * * @param h The target handler (can be null) * @return header string @@ -80,6 +91,10 @@ public String getHead(Handler h) { *

* This base class returns an empty string, but this may be * overridden by subclasses. + *

+ * This method may be invoked with handler related locks held + * and must not be implemented in such a way as to risk + * deadlocks, such as by calling back into user code. * * @param h The target handler (can be null) * @return tail string @@ -106,6 +121,12 @@ public String getTail(Handler h) { * java.text.MessageFormat is used to format the string. *

  • Otherwise no formatting is performed. * + *

    + * This method is expected to be invoked without any logging + * related locks held (since is calls back to user code). Any + * overridden implementation of this method must avoid locking + * around any calls to {@link Object#toString()} on parameters, or + * {@code super.formatMessage()}. * * @param record the log record containing the raw message * @return a localized and formatted message diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 7b93e517e972a..e4ddac4acb721 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -1,5 +1,6 @@ /* - * Copyright (c) 2000, 2024, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2024, 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 @@ -123,6 +124,10 @@ protected Handler() { } *

    * The {@code Handler} is responsible for formatting the message, when and * if necessary. The formatting should include localization. + *

    + * To avoid deadlock risk, this method should not be invoked with any + * logging related locks held, and must not be implemented as a synchronized + * method. * * @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..375def2364771 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,6 @@ /* - * Copyright (c) 2000, 2024, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2024, 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 @@ -172,10 +173,11 @@ public synchronized void close() { * silently ignored and is not published */ @Override - public synchronized void publish(LogRecord record) { + public void publish(LogRecord record) { if (!isLoggable(record)) { return; } + // JDK-8349206: Do NOT synchronize around the parent's publish() method. 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..4b1798980d352 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,6 @@ /* - * Copyright (c) 2000, 2024, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2024, 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 @@ -184,10 +185,14 @@ public synchronized void setEncoding(String encoding) * 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; } + // 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); @@ -199,12 +204,14 @@ 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(getFormatter().getHead(this)); + doneHeader = true; + } + writer.write(msg); } - writer.write(msg); } catch (Exception ex) { // We don't want to throw an exception here, but we // report the exception to any registered ErrorManager. diff --git a/test/jdk/java/util/logging/LoggingDeadlock5.java b/test/jdk/java/util/logging/LoggingDeadlock5.java new file mode 100644 index 0000000000000..3fd0bf08b6905 --- /dev/null +++ b/test/jdk/java/util/logging/LoggingDeadlock5.java @@ -0,0 +1,189 @@ +/* + * 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 + * @compile -XDignore.symbol.file LoggingDeadlock5.java + * @run main/othervm/timeout=10 LoggingDeadlock5 + */ + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.time.Duration; +import java.util.concurrent.Semaphore; +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 { + + // 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 ""; + } + }; + + // A handler which *should* cause a deadlock by synchronizing publish(). + private static final Handler SELF_TEST_HANDLER = new Handler() { + @Override + public synchronized void publish(LogRecord record) { + TEST_FORMATTER.formatMessage(record); + } + + @Override + public void flush() { + } + + @Override + public void close() { + } + }; + + public static void main(String[] args) throws InterruptedException, IOException { + // Self test that deadlocks are correct caught (and don't lock the entire test). + new DeadLocker(SELF_TEST_HANDLER).checkDeadlock(true); + + // In theory, we should test FileHandler and SocketHandler here as well + // because, while they are just subclasses of StreamHandler, they could + // be adding locking around the call to super.publish(). However, they + // are quite problematic in a test environment since they need to create + // files and open sockets. They are not being tested for now. + StreamHandler streamHandler = new StreamHandler(new ByteArrayOutputStream(0), TEST_FORMATTER); + streamHandler.setEncoding(StandardCharsets.UTF_8.name()); + new DeadLocker(streamHandler).checkDeadlock(false); + + // Any other problematic handler classes can be easily added here if + // they are simple enough to be constructed in a test environment. + } + + private static class DeadLocker { + private final static Duration JOIN_WAIT = Duration.ofMillis(500); + + private final Semaphore readyToDeadlock = new Semaphore(0); + private final Semaphore userLockIsHeld = new Semaphore(0); + private final Logger logger = Logger.getAnonymousLogger(); + private final Handler handlerUnderTest; + private final Object userLock = new Object(); + private boolean deadlockEncountered = true; + + DeadLocker(Handler handlerUnderTest) { + this.handlerUnderTest = handlerUnderTest; + + this.logger.setUseParentHandlers(false); + this.logger.addHandler(handlerUnderTest); + this.logger.setLevel(Level.INFO); + this.handlerUnderTest.setLevel(Level.INFO); + } + + void checkDeadlock(boolean expectDeadlock) throws InterruptedException { + // Note: Even though the message format string isn't used in the + // test formatter, it must be a valid log format string (Logger + // detects if there are no "{n}" placeholders and skips calling + // the formatter otherwise). + Thread t1 = runAsDaemon(() -> logger.log(Level.INFO, "Hello {0}", new Argument())); + readyToDeadlock.acquireUninterruptibly(); + // First thread is blocked until userLockIsHeld is released in t2. + Thread t2 = runAsDaemon(this::locksThenLogs); + + // If deadlock occurs, the join() calls both return false. + int threadsBlocked = 0; + if (!t1.join(JOIN_WAIT)) { + threadsBlocked += 1; + } + if (!t2.join(JOIN_WAIT)) { + threadsBlocked += 1; + } + // These indicate test problems, not a failure of the code under test. + errorIf(threadsBlocked == 1, "Inconsistent number of blocked threads."); + errorIf(deadlockEncountered != (threadsBlocked == 2), + "Deadlock reporting should coincide with number of blocked threads."); + + // This is the actual test assertion. + if (expectDeadlock != deadlockEncountered) { + String issue = expectDeadlock ? "Expected deadlock but none occurred" : "Unexpected deadlock"; + throw new AssertionError(errorMsg(issue)); + } + } + + void locksThenLogs() { + synchronized (userLock) { + userLockIsHeld.release(); + logger.log(Level.INFO, "This will cause a deadlock if the Handler locks!"); + } + } + + void calledFromToString() { + this.readyToDeadlock.release(); + this.userLockIsHeld.acquireUninterruptibly(); + synchronized (userLock) { + this.deadlockEncountered = false; + } + } + + class Argument { + @Override + public String toString() { + calledFromToString(); + return ""; + } + } + + String errorMsg(String msg) { + return String.format("Handler deadlock test [%s]: %s", handlerUnderTest.getClass().getName(), msg); + } + + void errorIf(boolean condition, String msg) { + if (condition) { + throw new RuntimeException(errorMsg("TEST ERROR - " + msg)); + } + } + } + + static Thread runAsDaemon(Runnable job) { + Thread thread = new Thread(job); + thread.setDaemon(true); + thread.start(); + return thread; + } +} From 0ce8341cca762a8fe055100af04bcf68bfd9e5a7 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Thu, 6 Feb 2025 18:55:49 +0100 Subject: [PATCH 02/19] Adjust copyright back to just start + current years. --- .../share/classes/java/util/logging/FileHandler.java | 8 ++++---- .../share/classes/java/util/logging/Formatter.java | 3 +-- .../share/classes/java/util/logging/Handler.java | 3 +-- .../share/classes/java/util/logging/SocketHandler.java | 3 +-- .../share/classes/java/util/logging/StreamHandler.java | 3 +-- 5 files changed, 8 insertions(+), 12 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index ca67c05b8b7b5..f280b8d375cb8 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -1,6 +1,5 @@ /* - * Copyright (c) 2000, 2024, 2025, 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 @@ -744,8 +743,9 @@ public void publish(LogRecord record) { if (!isLoggable(record)) { return; } - // JDK-8349206: DO NOT lock during publishing to avoid deadlock risk when - // invoking toString() on user parameters. + // JDK-8349206: Do NOT synchronize around the parent's publish() method. + // StreamHandler will lock, as needed, to protect writes to the metered + // stream. super.publish(record); // We must lock around the check of meter.xxx fields, and the call to // rotate(), and since flush() is also synchronized on the same instance, diff --git a/src/java.logging/share/classes/java/util/logging/Formatter.java b/src/java.logging/share/classes/java/util/logging/Formatter.java index 09447734fc0bb..91bca48030915 100644 --- a/src/java.logging/share/classes/java/util/logging/Formatter.java +++ b/src/java.logging/share/classes/java/util/logging/Formatter.java @@ -1,6 +1,5 @@ /* - * Copyright (c) 2000, 2020, 2025, 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 diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index e4ddac4acb721..9e87f74afae32 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -1,6 +1,5 @@ /* - * Copyright (c) 2000, 2024, 2025, 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 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 375def2364771..1c6d7fdfcc90a 100644 --- a/src/java.logging/share/classes/java/util/logging/SocketHandler.java +++ b/src/java.logging/share/classes/java/util/logging/SocketHandler.java @@ -1,6 +1,5 @@ /* - * Copyright (c) 2000, 2024, 2025, 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 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 4b1798980d352..1576c8be17a8a 100644 --- a/src/java.logging/share/classes/java/util/logging/StreamHandler.java +++ b/src/java.logging/share/classes/java/util/logging/StreamHandler.java @@ -1,6 +1,5 @@ /* - * Copyright (c) 2000, 2024, 2025, 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 From f857704c0904d2e19d845fb768a38f984d7724fe Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Thu, 6 Feb 2025 19:01:23 +0100 Subject: [PATCH 03/19] Re-adjust the comment about parent locking. --- .../share/classes/java/util/logging/FileHandler.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index f280b8d375cb8..8c0f07fcc9c5f 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -744,8 +744,8 @@ public void publish(LogRecord record) { return; } // JDK-8349206: Do NOT synchronize around the parent's publish() method. - // StreamHandler will lock, as needed, to protect writes to the metered - // stream. + // StreamHandler will lock the instance, as needed, to protect writes to + // the metered stream. super.publish(record); // We must lock around the check of meter.xxx fields, and the call to // rotate(), and since flush() is also synchronized on the same instance, From e897bdcfad9760d5a4416930729a0ece6914a3c8 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Mon, 10 Feb 2025 13:14:08 +0100 Subject: [PATCH 04/19] Making sure handlers are closed in tests and adding FileHandler test. --- .../java/util/logging/FileHandler.java | 4 +-- .../java/util/logging/LoggingDeadlock5.java | 30 ++++++++++++++----- 2 files changed, 24 insertions(+), 10 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index 8c0f07fcc9c5f..9c4cb5cb0729f 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -747,8 +747,8 @@ public void publish(LogRecord record) { // StreamHandler will lock the instance, as needed, to protect writes to // the metered stream. super.publish(record); - // We must lock around the check of meter.xxx fields, and the call to - // rotate(), and since flush() is also synchronized on the same instance, + // We must lock around the check of meter.xxx fields and the call to + // rotate(), and since flush() is also synchronized on the same instance // we might as well lock around everything. synchronized(this) { flush(); diff --git a/test/jdk/java/util/logging/LoggingDeadlock5.java b/test/jdk/java/util/logging/LoggingDeadlock5.java index 3fd0bf08b6905..24c6ba1a99f79 100644 --- a/test/jdk/java/util/logging/LoggingDeadlock5.java +++ b/test/jdk/java/util/logging/LoggingDeadlock5.java @@ -33,9 +33,11 @@ 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; @@ -51,6 +53,7 @@ * 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() { @@ -84,19 +87,30 @@ public static void main(String[] args) throws InterruptedException, IOException // Self test that deadlocks are correct caught (and don't lock the entire test). new DeadLocker(SELF_TEST_HANDLER).checkDeadlock(true); - // In theory, we should test FileHandler and SocketHandler here as well - // because, while they are just subclasses of StreamHandler, they could - // be adding locking around the call to super.publish(). However, they - // are quite problematic in a test environment since they need to create - // files and open sockets. They are not being tested for now. - StreamHandler streamHandler = new StreamHandler(new ByteArrayOutputStream(0), TEST_FORMATTER); - streamHandler.setEncoding(StandardCharsets.UTF_8.name()); - new DeadLocker(streamHandler).checkDeadlock(false); + // In theory, we should test SocketHandler here as well because, while + // it is just a subclass, it could be adding locking around the call to + // super.publish(). However, it is problematic in a test environment + // since it needs to open sockets. It is not being tested for now. + assertNoDeadlock(new StreamHandler(new ByteArrayOutputStream(0), TEST_FORMATTER)); + + // Single log file in current directory, no rotation. JTreg will delete + // temporary files after test completion. + assertNoDeadlock(new FileHandler("temp_log_file")); // Any other problematic handler classes can be easily added here if // they are simple enough to be constructed in a test environment. } + static void assertNoDeadlock(Handler handler) throws InterruptedException, UnsupportedEncodingException { + try { + handler.setEncoding(UTF_8); + new DeadLocker(handler).checkDeadlock(false); + } finally { + // Handlers may have open resources, so must be closed. + handler.close(); + } + } + private static class DeadLocker { private final static Duration JOIN_WAIT = Duration.ofMillis(500); From 5ba71dcd4a4e42cfef4f64ea2d50a667331a4ace Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Mon, 10 Feb 2025 13:14:08 +0100 Subject: [PATCH 05/19] Making sure handlers are closed in tests and adding FileHandler test. --- .../java/util/logging/FileHandler.java | 4 +-- .../java/util/logging/LoggingDeadlock5.java | 32 +++++++++++++------ 2 files changed, 25 insertions(+), 11 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index 8c0f07fcc9c5f..9c4cb5cb0729f 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -747,8 +747,8 @@ public void publish(LogRecord record) { // StreamHandler will lock the instance, as needed, to protect writes to // the metered stream. super.publish(record); - // We must lock around the check of meter.xxx fields, and the call to - // rotate(), and since flush() is also synchronized on the same instance, + // We must lock around the check of meter.xxx fields and the call to + // rotate(), and since flush() is also synchronized on the same instance // we might as well lock around everything. synchronized(this) { flush(); diff --git a/test/jdk/java/util/logging/LoggingDeadlock5.java b/test/jdk/java/util/logging/LoggingDeadlock5.java index 3fd0bf08b6905..03d3bc7689698 100644 --- a/test/jdk/java/util/logging/LoggingDeadlock5.java +++ b/test/jdk/java/util/logging/LoggingDeadlock5.java @@ -33,9 +33,11 @@ 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; @@ -51,6 +53,7 @@ * 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() { @@ -81,22 +84,33 @@ public void close() { }; public static void main(String[] args) throws InterruptedException, IOException { - // Self test that deadlocks are correct caught (and don't lock the entire test). + // Self test that deadlocks are correctly caught (and don't deadlock the test itself). new DeadLocker(SELF_TEST_HANDLER).checkDeadlock(true); - // In theory, we should test FileHandler and SocketHandler here as well - // because, while they are just subclasses of StreamHandler, they could - // be adding locking around the call to super.publish(). However, they - // are quite problematic in a test environment since they need to create - // files and open sockets. They are not being tested for now. - StreamHandler streamHandler = new StreamHandler(new ByteArrayOutputStream(0), TEST_FORMATTER); - streamHandler.setEncoding(StandardCharsets.UTF_8.name()); - new DeadLocker(streamHandler).checkDeadlock(false); + // In theory, we should test SocketHandler here as well because, while + // it is just a subclass, it could be adding locking around the call to + // super.publish(). However, it is problematic in a test environment + // since it needs to open sockets. It is not being tested for now. + assertNoDeadlock(new StreamHandler(new ByteArrayOutputStream(0), TEST_FORMATTER)); + + // Single log file in current directory, no rotation. JTreg will delete + // temporary files after test completion. + assertNoDeadlock(new FileHandler("temp_log_file")); // Any other problematic handler classes can be easily added here if // they are simple enough to be constructed in a test environment. } + static void assertNoDeadlock(Handler handler) throws InterruptedException, UnsupportedEncodingException { + try { + handler.setEncoding(UTF_8); + new DeadLocker(handler).checkDeadlock(false); + } finally { + // Handlers may have open resources, so must be closed. + handler.close(); + } + } + private static class DeadLocker { private final static Duration JOIN_WAIT = Duration.ofMillis(500); From 6beb0c882ec5638f8fe82e9d33e6570fe78646d7 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Wed, 12 Feb 2025 15:31:23 +0100 Subject: [PATCH 06/19] Reverted comments in Formatter and re-worked the comment in Handler to be more direct. --- .../classes/java/util/logging/Formatter.java | 22 +------------------ .../classes/java/util/logging/Handler.java | 6 ++--- 2 files changed, 4 insertions(+), 24 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/Formatter.java b/src/java.logging/share/classes/java/util/logging/Formatter.java index 91bca48030915..a5696b257d124 100644 --- a/src/java.logging/share/classes/java/util/logging/Formatter.java +++ b/src/java.logging/share/classes/java/util/logging/Formatter.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2025, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2020, 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 @@ -36,9 +36,6 @@ * Some formatters (such as the XMLFormatter) need to wrap head * and tail strings around a set of formatted records. The getHeader * and getTail methods can be used to obtain these strings. - *

    - * See individual method documentation for information about object - * locking and synchronization for implementations of this class. * * @since 1.4 */ @@ -58,9 +55,6 @@ protected Formatter() { * localized and formatted version of the LogRecord's message field. * It is recommended to use the {@link Formatter#formatMessage} * convenience method to localize and format the message field. - *

    - * This method is expected to be invoked without any logging - * related locks held (since is calls back to user code). * * @param record the log record to be formatted. * @return the formatted log record @@ -73,10 +67,6 @@ protected Formatter() { *

    * This base class returns an empty string, but this may be * overridden by subclasses. - *

    - * This method may be invoked with handler related locks held - * and must not be implemented in such a way as to risk - * deadlocks, such as by calling back into user code. * * @param h The target handler (can be null) * @return header string @@ -90,10 +80,6 @@ public String getHead(Handler h) { *

    * This base class returns an empty string, but this may be * overridden by subclasses. - *

    - * This method may be invoked with handler related locks held - * and must not be implemented in such a way as to risk - * deadlocks, such as by calling back into user code. * * @param h The target handler (can be null) * @return tail string @@ -120,12 +106,6 @@ public String getTail(Handler h) { * java.text.MessageFormat is used to format the string. *

  • Otherwise no formatting is performed. * - *

    - * This method is expected to be invoked without any logging - * related locks held (since is calls back to user code). Any - * overridden implementation of this method must avoid locking - * around any calls to {@link Object#toString()} on parameters, or - * {@code super.formatMessage()}. * * @param record the log record containing the raw message * @return a localized and formatted message diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 9e87f74afae32..9c76e7e37e038 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -124,9 +124,9 @@ protected Handler() { } * The {@code Handler} is responsible for formatting the message, when and * if necessary. The formatting should include localization. *

    - * To avoid deadlock risk, this method should not be invoked with any - * logging related locks held, and must not be implemented as a synchronized - * method. + * Implementations of this method should avoid synchronizing this method + * directly (via the synchronized keyword) or holding any locks around the + * formatting of user arguments. * * @param record description of the log event. A null record is * silently ignored and is not published From 601e88fda78168f60ff69e72fef260500697def7 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Wed, 12 Feb 2025 16:11:41 +0100 Subject: [PATCH 07/19] Tweaking the comment in Handler. --- .../share/classes/java/util/logging/Handler.java | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 9c76e7e37e038..3f760787a1dd8 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -124,9 +124,8 @@ protected Handler() { } * The {@code Handler} is responsible for formatting the message, when and * if necessary. The formatting should include localization. *

    - * Implementations of this method should avoid synchronizing this method - * directly (via the synchronized keyword) or holding any locks around the - * formatting of user arguments. + * Implementations of this method should avoid holding any locks around the + * formatting of {@code LogRecord}. * * @param record description of the log event. A null record is * silently ignored and is not published From 11ba770153dc256ca54e04c08517c055c780aa4f Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Fri, 14 Feb 2025 16:15:05 +0100 Subject: [PATCH 08/19] Reworking FileHandler so rotation occurs synchronously after the last log entry is written. --- .../java/util/logging/FileHandler.java | 50 +++++++++++++------ .../java/util/logging/LoggingDeadlock5.java | 2 +- 2 files changed, 35 insertions(+), 17 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index 9c4cb5cb0729f..87e0c1cd47b2a 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -166,10 +166,20 @@ public class FileHandler extends StreamHandler { * A metered stream is a subclass of OutputStream that * (a) forwards all its output to a target stream * (b) keeps track of how many bytes have been written + * + * The only calls to this class come from StreamHandler, which locks its + * handler instance around any calls it makes. */ - private static final class MeteredStream extends OutputStream { + private final class MeteredStream extends OutputStream { final OutputStream out; long written; + // We need to know when the current file is about to be rotated to avoid + // recursive calls to write() when the tail() is written. + // + // Each metered stream is monotonic and gets replaced rather than reset, + // so this flag only goes from false->true on each instance and indicates + // when we're flushing, closing and no longer using this instance. + boolean isRotating = false; MeteredStream(OutputStream out, long written) { this.out = out; @@ -180,18 +190,26 @@ private static final class MeteredStream extends OutputStream { public void write(int b) throws IOException { out.write(b); written++; + flushOrRotateIfFull(); } @Override public void write(byte buff[]) throws IOException { out.write(buff); written += buff.length; + flushOrRotateIfFull(); } + // This is the only write() method we actually expect to be called from + // StreamHandler's OutputStreamWriter (since it only calls write(String) + // on its stream). Apart from writing the head/tail entries to log files, + // there should be a 1-to-1 match between emitted log entries and calls + // to this method, so flushing for each write is not unreasonable. @Override public void write(byte buff[], int off, int len) throws IOException { out.write(buff,off,len); written += len; + flushOrRotateIfFull(); } @Override @@ -203,6 +221,20 @@ public void flush() throws IOException { public void close() throws IOException { out.close(); } + + /** + * Always called with the owning handler instance locked. + */ + private void flushOrRotateIfFull() throws IOException { + boolean shouldRotate = meter.written >= limit || meter.written < 0; + if (!isRotating && shouldRotate) { + isRotating = true; + // Calling rotate() will always flush() before closing the stream. + rotate(); + } else { + flush(); + } + } } private void open(File fname, boolean append) throws IOException { @@ -740,22 +772,8 @@ private synchronized void rotate() { */ @Override public void publish(LogRecord record) { - if (!isLoggable(record)) { - return; - } - // JDK-8349206: Do NOT synchronize around the parent's publish() method. - // StreamHandler will lock the instance, as needed, to protect writes to - // the metered stream. + // Stub method kept to preserve historical API shape. super.publish(record); - // We must lock around the check of meter.xxx fields and the call to - // rotate(), and since flush() is also synchronized on the same instance - // we might as well lock around everything. - synchronized(this) { - flush(); - if (limit > 0 && (meter.written >= limit || meter.written < 0)) { - rotate(); - } - } } /** diff --git a/test/jdk/java/util/logging/LoggingDeadlock5.java b/test/jdk/java/util/logging/LoggingDeadlock5.java index 03d3bc7689698..299c7c8043c61 100644 --- a/test/jdk/java/util/logging/LoggingDeadlock5.java +++ b/test/jdk/java/util/logging/LoggingDeadlock5.java @@ -28,7 +28,7 @@ * @modules java.base/sun.util.logging * java.logging * @compile -XDignore.symbol.file LoggingDeadlock5.java - * @run main/othervm/timeout=10 LoggingDeadlock5 + * @run main/othervm LoggingDeadlock5 */ import java.io.ByteArrayOutputStream; From 0c6ec9ae27b8de7c6deb939ecb4740f45e9ba353 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Tue, 18 Feb 2025 13:43:18 +0100 Subject: [PATCH 09/19] Revert to original state (no stream hooks). --- .../java/util/logging/FileHandler.java | 50 ++++++------------- 1 file changed, 16 insertions(+), 34 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index 87e0c1cd47b2a..9c4cb5cb0729f 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -166,20 +166,10 @@ public class FileHandler extends StreamHandler { * A metered stream is a subclass of OutputStream that * (a) forwards all its output to a target stream * (b) keeps track of how many bytes have been written - * - * The only calls to this class come from StreamHandler, which locks its - * handler instance around any calls it makes. */ - private final class MeteredStream extends OutputStream { + private static final class MeteredStream extends OutputStream { final OutputStream out; long written; - // We need to know when the current file is about to be rotated to avoid - // recursive calls to write() when the tail() is written. - // - // Each metered stream is monotonic and gets replaced rather than reset, - // so this flag only goes from false->true on each instance and indicates - // when we're flushing, closing and no longer using this instance. - boolean isRotating = false; MeteredStream(OutputStream out, long written) { this.out = out; @@ -190,26 +180,18 @@ private final class MeteredStream extends OutputStream { public void write(int b) throws IOException { out.write(b); written++; - flushOrRotateIfFull(); } @Override public void write(byte buff[]) throws IOException { out.write(buff); written += buff.length; - flushOrRotateIfFull(); } - // This is the only write() method we actually expect to be called from - // StreamHandler's OutputStreamWriter (since it only calls write(String) - // on its stream). Apart from writing the head/tail entries to log files, - // there should be a 1-to-1 match between emitted log entries and calls - // to this method, so flushing for each write is not unreasonable. @Override public void write(byte buff[], int off, int len) throws IOException { out.write(buff,off,len); written += len; - flushOrRotateIfFull(); } @Override @@ -221,20 +203,6 @@ public void flush() throws IOException { public void close() throws IOException { out.close(); } - - /** - * Always called with the owning handler instance locked. - */ - private void flushOrRotateIfFull() throws IOException { - boolean shouldRotate = meter.written >= limit || meter.written < 0; - if (!isRotating && shouldRotate) { - isRotating = true; - // Calling rotate() will always flush() before closing the stream. - rotate(); - } else { - flush(); - } - } } private void open(File fname, boolean append) throws IOException { @@ -772,8 +740,22 @@ private synchronized void rotate() { */ @Override public void publish(LogRecord record) { - // Stub method kept to preserve historical API shape. + if (!isLoggable(record)) { + return; + } + // JDK-8349206: Do NOT synchronize around the parent's publish() method. + // StreamHandler will lock the instance, as needed, to protect writes to + // the metered stream. super.publish(record); + // We must lock around the check of meter.xxx fields and the call to + // rotate(), and since flush() is also synchronized on the same instance + // we might as well lock around everything. + synchronized(this) { + flush(); + if (limit > 0 && (meter.written >= limit || meter.written < 0)) { + rotate(); + } + } } /** From 01157cb946ba95d1ea7e125c2bcb2ae19da395cf Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Thu, 20 Feb 2025 16:22:53 +0100 Subject: [PATCH 10/19] Updating code and tests according to feedback and discussions. --- .../java/util/logging/ConsoleHandler.java | 1 + .../java/util/logging/FileHandler.java | 21 ++-- .../classes/java/util/logging/Formatter.java | 10 ++ .../classes/java/util/logging/Handler.java | 37 ++++++ .../java/util/logging/SocketHandler.java | 3 - .../java/util/logging/StreamHandler.java | 11 ++ .../Handler/StreamHandlerLockingTest.java | 105 ++++++++++++++++++ .../java/util/logging/TestStreamHandler.java | 54 +++++++++ .../java/util/logging/LoggingDeadlock5.java | 1 - 9 files changed, 225 insertions(+), 18 deletions(-) create mode 100644 test/jdk/java/util/logging/Handler/StreamHandlerLockingTest.java create mode 100644 test/jdk/java/util/logging/Handler/java.logging/java/util/logging/TestStreamHandler.java diff --git a/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java b/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java index cab4805b9e739..f52a62ea23b34 100644 --- a/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java +++ b/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java @@ -92,6 +92,7 @@ public ConsoleHandler() { */ @Override public void publish(LogRecord record) { + // JDK-8349206: Do NOT synchronize around the parent's publish() method. super.publish(record); flush(); } diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index 9c4cb5cb0729f..bba31bdf8b0c6 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -740,21 +740,14 @@ private synchronized void rotate() { */ @Override public void publish(LogRecord record) { - if (!isLoggable(record)) { - return; - } - // JDK-8349206: Do NOT synchronize around the parent's publish() method. - // StreamHandler will lock the instance, as needed, to protect writes to - // the metered stream. super.publish(record); - // We must lock around the check of meter.xxx fields and the call to - // rotate(), and since flush() is also synchronized on the same instance - // we might as well lock around everything. - synchronized(this) { - flush(); - if (limit > 0 && (meter.written >= limit || meter.written < 0)) { - rotate(); - } + } + + @Override + void synchronousPostWriteHook() { + flush(); + if (limit > 0 && (meter.written >= limit || meter.written < 0)) { + rotate(); } } diff --git a/src/java.logging/share/classes/java/util/logging/Formatter.java b/src/java.logging/share/classes/java/util/logging/Formatter.java index a5696b257d124..a01ce572f1272 100644 --- a/src/java.logging/share/classes/java/util/logging/Formatter.java +++ b/src/java.logging/share/classes/java/util/logging/Formatter.java @@ -67,6 +67,11 @@ protected Formatter() { *

    * This base class returns an empty string, but this may be * overridden by subclasses. + *

    + * Note that this method is often called with an associated {@link Handler} + * instance locked so, to avoid deadlock risk, it is important to avoid + * making callbacks to unknown user-provided arguments (e.g. log record + * parameters captured from previous calls to {@link #format(LogRecord)}. * * @param h The target handler (can be null) * @return header string @@ -80,6 +85,11 @@ public String getHead(Handler h) { *

    * This base class returns an empty string, but this may be * overridden by subclasses. + *

    + * Note that this method is often called with an associated {@link Handler} + * instance locked so, to avoid deadlock risk, it is important to avoid + * making callbacks to unknown user-provided arguments (e.g. log record + * parameters captured from previous calls to {@link #format(LogRecord)}. * * @param h The target handler (can be null) * @return tail string diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 3f760787a1dd8..013b21b3d5191 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -43,6 +43,43 @@ * and {@code Level}. See the specific documentation for each concrete * {@code Handler} class. * + *

    Subclass Implementation Notes

    + * + * When implementing new {@code Handler} subclasses, it is important to + * understand the potential effects of synchronization. + *

    + * Logging can occur concurrently in many threads, so a general principle + * is to synchronize as little as necessary to minimize thread contention. + *

    + * As such, the following pattern is often used in the core {@code Handler} + * classes: + *

    + * For example, this prevents thread contention around calls to + * {@link #isLoggable(LogRecord)} while allowing code synchronized on the + * {@code Handler} instance to set a new log level. + *

    + * Another principle is to avoid synchronizing {@code Handler} instances (or + * holding any other locks) while processing user-provided arguments, such as + * {@link LogRecord} parameters. + *

    + * This applies most directly to the {@link #publish(LogRecord)} method, where + * user arguments are processed. Holding a lock when calling {@code toString()} + * on log arguments creates an inevitable deadlock risk. + *

    + * A consequence of this is that the {@link #publish(LogRecord)} method of + * {@code Handler} subclasses should typically never be synchronized. However, + * {@code Handler} subclasses can synchronize within their + * {@link #publish(LogRecord)} implementation to protect internal state. + *

    + * If you have requirements for a {@code Handler} which do not match the + * synchronization behaviour in classes such as {@link StreamHandler}, + * {@link FileHandler} or {@link Formatter} then, in order to have complete + * control of synchronization, it is recommended to subclass {@code Handler} + * directly. * * @since 1.4 */ 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 1c6d7fdfcc90a..9240910f2f611 100644 --- a/src/java.logging/share/classes/java/util/logging/SocketHandler.java +++ b/src/java.logging/share/classes/java/util/logging/SocketHandler.java @@ -173,9 +173,6 @@ public synchronized void close() { */ @Override public void publish(LogRecord record) { - if (!isLoggable(record)) { - return; - } // JDK-8349206: Do NOT synchronize around the parent's publish() method. 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 1576c8be17a8a..5628bebba14ea 100644 --- a/src/java.logging/share/classes/java/util/logging/StreamHandler.java +++ b/src/java.logging/share/classes/java/util/logging/StreamHandler.java @@ -210,6 +210,7 @@ public void publish(LogRecord record) { doneHeader = true; } writer.write(msg); + synchronousPostWriteHook(); } } catch (Exception ex) { // We don't want to throw an exception here, but we @@ -218,6 +219,15 @@ public 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. + } /** * Check if this {@code Handler} would actually log a given {@code LogRecord}. @@ -255,6 +265,7 @@ public synchronized void flush() { } } + // Called synchronously. private void flushAndClose() { Writer writer = this.writer; if (writer != null) { 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 index 299c7c8043c61..6d75c84839a7b 100644 --- a/test/jdk/java/util/logging/LoggingDeadlock5.java +++ b/test/jdk/java/util/logging/LoggingDeadlock5.java @@ -27,7 +27,6 @@ * @summary j.u.l.Handler classes create deadlock risk via synchronized publish() method. * @modules java.base/sun.util.logging * java.logging - * @compile -XDignore.symbol.file LoggingDeadlock5.java * @run main/othervm LoggingDeadlock5 */ From f425f3fb46281f5886bb048c1b9da2f5177cfab3 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Mon, 24 Feb 2025 12:55:01 +0100 Subject: [PATCH 11/19] Adding @implNote to new JavaDoc. --- .../classes/java/util/logging/Formatter.java | 18 ++++++++++-------- .../classes/java/util/logging/Handler.java | 14 +++++++------- 2 files changed, 17 insertions(+), 15 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/Formatter.java b/src/java.logging/share/classes/java/util/logging/Formatter.java index a01ce572f1272..51b977509220c 100644 --- a/src/java.logging/share/classes/java/util/logging/Formatter.java +++ b/src/java.logging/share/classes/java/util/logging/Formatter.java @@ -68,10 +68,11 @@ protected Formatter() { * This base class returns an empty string, but this may be * overridden by subclasses. *

    - * Note that this method is often called with an associated {@link Handler} - * instance locked so, to avoid deadlock risk, it is important to avoid - * making callbacks to unknown user-provided arguments (e.g. log record - * parameters captured from previous calls to {@link #format(LogRecord)}. + * @implNote Note that this method is often called with an associated + * {@link Handler} instance locked so, to avoid deadlock risk, it is + * important to avoid making callbacks to unknown user-provided arguments + * (e.g. log record parameters captured from previous calls to + * {@link #format(LogRecord)}. * * @param h The target handler (can be null) * @return header string @@ -86,10 +87,11 @@ public String getHead(Handler h) { * This base class returns an empty string, but this may be * overridden by subclasses. *

    - * Note that this method is often called with an associated {@link Handler} - * instance locked so, to avoid deadlock risk, it is important to avoid - * making callbacks to unknown user-provided arguments (e.g. log record - * parameters captured from previous calls to {@link #format(LogRecord)}. + * @implNote Note that this method is often called with an associated + * {@link Handler} instance locked so, to avoid deadlock risk, it is + * important to avoid making callbacks to unknown user-provided arguments + * (e.g. log record parameters captured from previous calls to + * {@link #format(LogRecord)}. * * @param h The target handler (can be null) * @return tail string diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 013b21b3d5191..ddeb2058fef02 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -45,8 +45,8 @@ * *

    Subclass Implementation Notes

    * - * When implementing new {@code Handler} subclasses, it is important to - * understand the potential effects of synchronization. + * @implNote When implementing new {@code Handler} subclasses, it is important + * to understand the potential effects of synchronization. *

    * Logging can occur concurrently in many threads, so a general principle * is to synchronize as little as necessary to minimize thread contention. @@ -62,9 +62,9 @@ * {@link #isLoggable(LogRecord)} while allowing code synchronized on the * {@code Handler} instance to set a new log level. *

    - * Another principle is to avoid synchronizing {@code Handler} instances (or - * holding any other locks) while processing user-provided arguments, such as - * {@link LogRecord} parameters. + * @implNote Another principle is to avoid synchronizing {@code Handler} + * instances (or holding any other locks) while processing user-provided + * arguments, such as {@link LogRecord} parameters. *

    * This applies most directly to the {@link #publish(LogRecord)} method, where * user arguments are processed. Holding a lock when calling {@code toString()} @@ -161,8 +161,8 @@ protected Handler() { } * The {@code Handler} is responsible for formatting the message, when and * if necessary. The formatting should include localization. *

    - * Implementations of this method should avoid holding any locks around the - * formatting of {@code LogRecord}. + * @implNote Implementations of this method should avoid holding any locks + * around the formatting of {@code LogRecord}. * * @param record description of the log event. A null record is * silently ignored and is not published From 19e84728d10a7459886e2d53ae4c059de564b57d Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Mon, 24 Feb 2025 14:04:36 +0100 Subject: [PATCH 12/19] Tweaking @implNote for better rendering. --- .../share/classes/java/util/logging/Handler.java | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index ddeb2058fef02..3be4012bb4d75 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -43,8 +43,6 @@ * and {@code Level}. See the specific documentation for each concrete * {@code Handler} class. * - *

    Subclass Implementation Notes

    - * * @implNote When implementing new {@code Handler} subclasses, it is important * to understand the potential effects of synchronization. *

    @@ -62,9 +60,9 @@ * {@link #isLoggable(LogRecord)} while allowing code synchronized on the * {@code Handler} instance to set a new log level. *

    - * @implNote Another principle is to avoid synchronizing {@code Handler} - * instances (or holding any other locks) while processing user-provided - * arguments, such as {@link LogRecord} parameters. + * Another principle is to avoid synchronizing {@code Handler} instances + * (or holding any other locks) while processing user-provided arguments, + * such as {@link LogRecord} parameters. *

    * This applies most directly to the {@link #publish(LogRecord)} method, where * user arguments are processed. Holding a lock when calling {@code toString()} From 35984b0997af3dd0eb3e002ed702e4fa6a08df0a Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Thu, 27 Feb 2025 13:43:27 +0100 Subject: [PATCH 13/19] Rewording notes and spec changes in docs. Small change to read formatter once in streamhander methods. Reverting Formatter doc changes for now. --- .../classes/java/util/logging/Formatter.java | 12 ----- .../classes/java/util/logging/Handler.java | 44 +++---------------- .../java/util/logging/StreamHandler.java | 19 ++++++-- 3 files changed, 22 insertions(+), 53 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/Formatter.java b/src/java.logging/share/classes/java/util/logging/Formatter.java index 51b977509220c..a5696b257d124 100644 --- a/src/java.logging/share/classes/java/util/logging/Formatter.java +++ b/src/java.logging/share/classes/java/util/logging/Formatter.java @@ -67,12 +67,6 @@ protected Formatter() { *

    * This base class returns an empty string, but this may be * overridden by subclasses. - *

    - * @implNote Note that this method is often called with an associated - * {@link Handler} instance locked so, to avoid deadlock risk, it is - * important to avoid making callbacks to unknown user-provided arguments - * (e.g. log record parameters captured from previous calls to - * {@link #format(LogRecord)}. * * @param h The target handler (can be null) * @return header string @@ -86,12 +80,6 @@ public String getHead(Handler h) { *

    * This base class returns an empty string, but this may be * overridden by subclasses. - *

    - * @implNote Note that this method is often called with an associated - * {@link Handler} instance locked so, to avoid deadlock risk, it is - * important to avoid making callbacks to unknown user-provided arguments - * (e.g. log record parameters captured from previous calls to - * {@link #format(LogRecord)}. * * @param h The target handler (can be null) * @return tail string diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 3be4012bb4d75..0ac1d5822c500 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -43,41 +43,10 @@ * and {@code Level}. See the specific documentation for each concrete * {@code Handler} class. * - * @implNote When implementing new {@code Handler} subclasses, it is important - * to understand the potential effects of synchronization. - *

    - * Logging can occur concurrently in many threads, so a general principle - * is to synchronize as little as necessary to minimize thread contention. - *

    - * As such, the following pattern is often used in the core {@code Handler} - * classes: - *

    - * For example, this prevents thread contention around calls to - * {@link #isLoggable(LogRecord)} while allowing code synchronized on the - * {@code Handler} instance to set a new log level. - *

    - * Another principle is to avoid synchronizing {@code Handler} instances - * (or holding any other locks) while processing user-provided arguments, - * such as {@link LogRecord} parameters. - *

    - * This applies most directly to the {@link #publish(LogRecord)} method, where - * user arguments are processed. Holding a lock when calling {@code toString()} - * on log arguments creates an inevitable deadlock risk. - *

    - * A consequence of this is that the {@link #publish(LogRecord)} method of - * {@code Handler} subclasses should typically never be synchronized. However, - * {@code Handler} subclasses can synchronize within their - * {@link #publish(LogRecord)} implementation to protect internal state. - *

    - * If you have requirements for a {@code Handler} which do not match the - * synchronization behaviour in classes such as {@link StreamHandler}, - * {@link FileHandler} or {@link Formatter} then, in order to have complete - * control of synchronization, it is recommended to subclass {@code Handler} - * directly. + * @implNote Implementations of {@code Handler} should be thread-safe. Handlers + * are expected to be invoked concurrently from arbitrary threads. However, + * over-use of synchronization may result in unwanted thread contention, + * performance issues or even deadlocking. * * @since 1.4 */ @@ -159,8 +128,9 @@ protected Handler() { } * The {@code Handler} is responsible for formatting the message, when and * if necessary. The formatting should include localization. *

    - * @implNote Implementations of this method should avoid holding any locks - * around the formatting of {@code LogRecord}. + * @implNote 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/StreamHandler.java b/src/java.logging/share/classes/java/util/logging/StreamHandler.java index 5628bebba14ea..3f05cddc1f0dd 100644 --- a/src/java.logging/share/classes/java/util/logging/StreamHandler.java +++ b/src/java.logging/share/classes/java/util/logging/StreamHandler.java @@ -180,6 +180,13 @@ 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}. + * * @param record description of the log event. A null record is * silently ignored and is not published */ @@ -188,13 +195,16 @@ 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. @@ -206,7 +216,7 @@ public void publish(LogRecord record) { synchronized(this) { Writer writer = this.writer; if (!doneHeader) { - writer.write(getFormatter().getHead(this)); + writer.write(formatter.getHead(this)); doneHeader = true; } writer.write(msg); @@ -269,12 +279,13 @@ public synchronized void flush() { 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) { From 6051c690bf71b0812909860d2c30fdaa8d85c873 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Thu, 27 Feb 2025 17:56:57 +0100 Subject: [PATCH 14/19] Make class level docs just docs (no annotation). --- .../share/classes/java/util/logging/Handler.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 0ac1d5822c500..f8054b6769dc7 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -42,9 +42,9 @@ * default values for the {@code Handler}'s {@code Filter}, {@code Formatter}, * and {@code Level}. See the specific documentation for each concrete * {@code Handler} class. - * - * @implNote Implementations of {@code Handler} should be thread-safe. Handlers - * are expected to be invoked concurrently from arbitrary threads. However, + *

    + * Implementations of {@code Handler} should be thread-safe. Handlers are + * expected to be invoked concurrently from arbitrary threads. However, * over-use of synchronization may result in unwanted thread contention, * performance issues or even deadlocking. * From 147aecaed66076c7cf0d3c6296e829c9145215a3 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Thu, 27 Feb 2025 18:12:18 +0100 Subject: [PATCH 15/19] Fix @implNote to @apiNote. --- src/java.logging/share/classes/java/util/logging/Handler.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index f8054b6769dc7..34921248106ef 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -128,7 +128,7 @@ protected Handler() { } * The {@code Handler} is responsible for formatting the message, when and * if necessary. The formatting should include localization. *

    - * @implNote To avoid the risk of deadlock, implementations of this method + * @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}. * From 1bf2da42f430054f7c1a7bc64622953a1b065951 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Fri, 28 Feb 2025 15:19:52 +0100 Subject: [PATCH 16/19] Final round of comment tweaks. --- .../share/classes/java/util/logging/StreamHandler.java | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) 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 3f05cddc1f0dd..5fc70b5dde9c3 100644 --- a/src/java.logging/share/classes/java/util/logging/StreamHandler.java +++ b/src/java.logging/share/classes/java/util/logging/StreamHandler.java @@ -180,12 +180,12 @@ 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} + * @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}. + * {@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 @@ -236,7 +236,9 @@ public void publish(LogRecord record) { * please find a better name if you do ;). */ void synchronousPostWriteHook() { - // Empty by default. + // Empty by default. We could do: + // assert Thread.holdsLock(this); + // but this is already covered by unit tests. } /** @@ -275,7 +277,7 @@ public synchronized void flush() { } } - // Called synchronously. + // Called synchronously with "this" handler instance locked. private void flushAndClose() { Writer writer = this.writer; if (writer != null) { From 43c761190aa33f11d6a104aa8d526285e6251c42 Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Mon, 3 Mar 2025 11:11:03 +0100 Subject: [PATCH 17/19] Final round of comment tweaks. --- .../share/classes/java/util/logging/FileHandler.java | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/java.logging/share/classes/java/util/logging/FileHandler.java b/src/java.logging/share/classes/java/util/logging/FileHandler.java index bba31bdf8b0c6..99afe7261b1e7 100644 --- a/src/java.logging/share/classes/java/util/logging/FileHandler.java +++ b/src/java.logging/share/classes/java/util/logging/FileHandler.java @@ -745,6 +745,8 @@ public void publish(LogRecord record) { @Override void synchronousPostWriteHook() { + // no need to synchronize here, this method is called from within a + // synchronized block. flush(); if (limit > 0 && (meter.written >= limit || meter.written < 0)) { rotate(); From 15cad6edd78581642446e9485ce0e68bae6b548e Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Wed, 2 Apr 2025 15:33:53 +0200 Subject: [PATCH 18/19] Reworking user warnings about synchronization and deadlocking based on Joe's comments. --- .../classes/java/util/logging/ConsoleHandler.java | 7 ++++++- .../share/classes/java/util/logging/Handler.java | 15 +++++++++++++-- .../classes/java/util/logging/SocketHandler.java | 7 ++++++- 3 files changed, 25 insertions(+), 4 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java b/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java index f52a62ea23b34..1561c7edebf44 100644 --- a/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java +++ b/src/java.logging/share/classes/java/util/logging/ConsoleHandler.java @@ -87,12 +87,17 @@ public ConsoleHandler() { * The logging request was made initially to a {@code Logger} object, * which initialized the {@code LogRecord} and forwarded it here. * + * @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 void publish(LogRecord record) { - // JDK-8349206: Do NOT synchronize around the parent's publish() method. super.publish(record); flush(); } diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index 34921248106ef..b9171535c554d 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -42,15 +42,26 @@ * default values for the {@code Handler}'s {@code Filter}, {@code Formatter}, * and {@code Level}. See the specific documentation for each concrete * {@code Handler} class. - *

    + * + *

    Thread Safety and Deadlock Risk in Handlers

    + * * Implementations of {@code Handler} should be thread-safe. Handlers are * expected to be invoked concurrently from arbitrary threads. However, * over-use of synchronization may result in unwanted thread contention, * performance issues or even deadlocking. + *

    + * 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 never synchronize + * their {@link #publish(LogRecord)} method, or calls to {@code + * super.publish()}, since these are always 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(); 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 9240910f2f611..d20d857035777 100644 --- a/src/java.logging/share/classes/java/util/logging/SocketHandler.java +++ b/src/java.logging/share/classes/java/util/logging/SocketHandler.java @@ -168,12 +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 void publish(LogRecord record) { - // JDK-8349206: Do NOT synchronize around the parent's publish() method. super.publish(record); flush(); } From 8db4c907633fed5aa103b3c4f6aaad5096f0790a Mon Sep 17 00:00:00 2001 From: David Beaumont Date: Wed, 2 Apr 2025 23:54:36 +0200 Subject: [PATCH 19/19] Tweak wording. --- .../share/classes/java/util/logging/Handler.java | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/java.logging/share/classes/java/util/logging/Handler.java b/src/java.logging/share/classes/java/util/logging/Handler.java index b9171535c554d..8e5b3ee0a4f3c 100644 --- a/src/java.logging/share/classes/java/util/logging/Handler.java +++ b/src/java.logging/share/classes/java/util/logging/Handler.java @@ -55,10 +55,10 @@ * 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 never synchronize - * their {@link #publish(LogRecord)} method, or calls to {@code - * super.publish()}, since these are always expected to need to process and - * format user-supplied arguments. + * 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 */