Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
20 commits
Select commit Hold shift + click to select a range
157594c
8349206: j.u.l.Handler classes create deadlock risk via synchronized …
david-beaumont Feb 6, 2025
0ce8341
Adjust copyright back to just start + current years.
david-beaumont Feb 6, 2025
f857704
Re-adjust the comment about parent locking.
david-beaumont Feb 6, 2025
e897bdc
Making sure handlers are closed in tests and adding FileHandler test.
david-beaumont Feb 10, 2025
5ba71dc
Making sure handlers are closed in tests and adding FileHandler test.
david-beaumont Feb 10, 2025
c35e519
Merge remote-tracking branch 'origin/JDK-8349206-1' into JDK-8349206-1
david-beaumont Feb 10, 2025
6beb0c8
Reverted comments in Formatter and re-worked the comment in Handler t…
david-beaumont Feb 12, 2025
601e88f
Tweaking the comment in Handler.
david-beaumont Feb 12, 2025
11ba770
Reworking FileHandler so rotation occurs synchronously after the last…
david-beaumont Feb 14, 2025
0c6ec9a
Revert to original state (no stream hooks).
david-beaumont Feb 18, 2025
01157cb
Updating code and tests according to feedback and discussions.
david-beaumont Feb 20, 2025
f425f3f
Adding @implNote to new JavaDoc.
david-beaumont Feb 24, 2025
19e8472
Tweaking @implNote for better rendering.
david-beaumont Feb 24, 2025
35984b0
Rewording notes and spec changes in docs.
david-beaumont Feb 27, 2025
6051c69
Make class level docs just docs (no annotation).
david-beaumont Feb 27, 2025
147aeca
Fix @implNote to @apiNote.
david-beaumont Feb 27, 2025
1bf2da4
Final round of comment tweaks.
david-beaumont Feb 28, 2025
43c7611
Final round of comment tweaks.
david-beaumont Mar 3, 2025
15cad6e
Reworking user warnings about synchronization and deadlocking based o…
david-beaumont Apr 2, 2025
8db4c90
Tweak wording.
david-beaumont Apr 2, 2025
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -87,6 +87,12 @@ 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
*/
Expand Down
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -739,11 +739,14 @@ private synchronized void rotate() {
* 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);
}

@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();
Expand Down
23 changes: 21 additions & 2 deletions src/java.logging/share/classes/java/util/logging/Handler.java
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -43,10 +43,25 @@
* and {@code Level}. See the specific documentation for each concrete
* {@code Handler} class.
*
* <h2><a id=threadSafety>Thread Safety and Deadlock Risk in Handlers</a></h2>
*
* 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.
* <p>
* 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.
* <p>
* 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();

Expand Down Expand Up @@ -123,6 +138,10 @@ protected Handler() { }
* <p>
* The {@code Handler} is responsible for formatting the message, when and
* if necessary. The formatting should include localization.
* <p>
* @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
Expand Down
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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();
}
Expand Down
52 changes: 41 additions & 11 deletions src/java.logging/share/classes/java/util/logging/StreamHandler.java
Original file line number Diff line number Diff line change
@@ -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
Expand Down Expand Up @@ -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.
Expand All @@ -199,19 +213,33 @@ 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;

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well spotted :) Yes, it's a theoretical risk, but not at the same level as that of log record formatting.

My original draft push of this PR had comments about lock expectations here, but I was asked to not change the JavaDoc on Formatter.

The getHead() and getTail() methods could cause deadlock, but only because of code directly associated with their implementation. They don't have any access to a log record (and no reason to have access to log records), so they aren't going to be calling into completely arbitrary user code.

It's also unlikely that a formatter implementation will do a lot of complex work in these methods since, semantically, they are called an arbitrary number of times (according to configuration) and at arbitrary times, so they really cannot meaningfully rely on user runtime data or much beyond things like timestamps and counters.

So while, in theory, it could be an issue, it's an issue that can almost certainly be fixed by the author of the Formatter class itself. This is contrasted with the issue at hand, which is inherent in the handler code and cannot be fixed in any other reasonable way by the user of the logging library.

I'd be happy to move the head/tail acquisition out of the locked regions if it were deemed a risk, but that's never something I've observed as an issue (I spent 10 years doing Java logging stuff and saw the publish() deadlock, but never issues with head/tail stuff). It's also hard to move it out, because tail writing happens in close(), called from flush(), both of which are much more expected to be synchronized, so you'd probably want to get and cache the tail() string when the file was opened.

Copy link
Contributor Author

@david-beaumont david-beaumont Feb 14, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As for the example you gave there, that is interesting. Keeping an unformatted log record around for any time after the log statement that created it has exited would be quite problematic (it prevents GC of arbitrary things).

If I were doing some kind of summary tail entry, I'd pull, format (user args) and cache anything I needed out of the log record when I had it, but not keep it around. Then when the tail is written I'd just have what I need ready to go.

But yes, right now, with or without this PR, that code looks like it's got a deadlock risk.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Need to update to have single call to getFormatter().

Copy link

@jmehrens jmehrens Feb 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Keeping an unformatted log record around for any time after the log statement that created it has exited would be quite problematic (it prevents GC of arbitrary things).

I've always leaned on:

  1. The words written in LogRecord API that once a record is given to the logging api it owns that record. Thefore, don't attach things you own to that record. "Don't leave your belongings in the rental car when returning it."
  2. Passing arbitrary objects to the logging API is a security risk because I can create a filter/handler/Formatter that casts the arguments and manipulates them. E.G. Map::clear, Map::put("user","root").
  3. Logging api has supplier methods that allow callers to format arguments early on using String.format.
  4. LogRecord records a timestamp. Passing string representation at time of logging both snapshots near the timestamp and makes a mutable argument safer for exposure to unknown classes.

That said, I'll probably create PRs for MailHandler and CollectorFormatter to optionally support deep cloning of the LogRecord via serialization before it is stored. Doing so would switch the params to string without tampering with the source record. MemoryHander could do the same and effectively become a non-caching (pushLevel=ALL) TransformHandler to decorate Handers that over synchronize.

Copy link
Contributor Author

@david-beaumont david-beaumont Feb 28, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd have to disagree with the points you make.

The fact is that loggers are never expected to modify the passed parameters. To ask people to "disown" the parameters they pass to a logger requires that your best advice on how to write a log statement with mutable values must look something like:

  if (logger.isEnabled(level)) {
    // Avoid copying parameters when logging is disabled.
    var arg1Copy = arg1.defensiveCopy();
    var arg2Copy = arg2.defensiveCopy();
    logger.log(level, "foo={0}, bar={1}", arg1Copy, arg2Copy);
  }

as opposed to:

    logger.log(level, "foo={0}, bar={1}", arg1, arg2);

The former is, in my opinion, a pretty awful user experience, error prone, and (more to the point) something that almost nobody ever does in real code because, reasonably, they trust the internal logger classes not to be malicious.

The comment about the record being owned by the logger means that it can't be cached and reused, or passed to different log statements etc. It doesn't give logging classes any freedom to modify the log statement parameters.

The other issue with "defer processing to another thread", even if you do format in the original thread, is that either:

  1. You format just the arguments to strings -- Now things like {0,date} are broken because you turned date/time arguments into strings what are no longer formattable with the original format string.
  2. You format the entire message -- Now any handlers downstream cannot use the format message (the thing with the placeholders in) as a key to identify the log statements, which is sometimes really important for analysis.

It's just really hard (maybe impossible) to create any general solution where a log record (as opposed to some custom semi-flattened form) can be safely used between threads without this being visible in some way to users.

So my (personal) strong advice for Handler implementations is:

  1. Never let the log record you are given escape the call to publish().
  2. You can store metadata from the log record "on the side", but only for non user-supplied arguments.

So, if you wanted to use something like MemoryHandler, subclass it and override publish() to make new log records to pass into its queue, which contain only flat formatted information (and even then you might break assumptions of a downstream handler).

However, if you are formatting everything in the publish() method, you don't really get much of a win from using MemoryHandler anymore, unless you only expect special-case logging by the users, so maybe it's not even worth it.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The former is, in my opinion, a pretty awful user experience...

Specifically, I'm referring to this, with awareness of the above described limitations:

//String.format is var-arg
logger.log(Level.SEVERE, () -> { return String.format("foo=%s bar=%s", arg1, arg2); });

//logger is not var-arg     
if (logger.isLoggable(lvl)) { //if arg1 and arg2 known to be never null
    logger.log(lvl, "foo={0} bar={1}", new Object[]{arg1.toString(), arg2.toString()});
}
         
//logger is not var-arg
if (logger.isLoggable(lvl)) { //if arg1 and arg2 are nullable
    logger.log(lvl, "foo={0} bar={1}", new Object[]{Objects.toString(arg1), Objects.toString(arg2)});
}

How did you worked around this deadlock issue prior to this patch? That would be awesome information to add to the JIRA ticket for those that would like this patch but are unable to upgrade.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The only workaround is to early format parameters, either at the call site or in the logger/handler.
This bug has been around for a very long time, and I suspect that it hasn't been a serious issue for people because, in general, most toString() implementations are non-locking and most log statements are disabled most of the time. It's also a probabilistic deadlock which requires some instance to be being accessed by two threads concurrently. I have however witnessed it causing issues in real production systems.

}
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.
reportError(null, ex, ErrorManager.WRITE_FAILURE);
}
}

/**
* 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}.
Expand Down Expand Up @@ -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) {
Expand Down
105 changes: 105 additions & 0 deletions test/jdk/java/util/logging/Handler/StreamHandlerLockingTest.java
Original file line number Diff line number Diff line change
@@ -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);
}
}
Original file line number Diff line number Diff line change
@@ -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++;
}
}
Loading