RFR: 8349206: j.u.l.Handler classes create deadlock risk via synchronized publish() method [v10]

[David Beaumont]

On Sun, 2 Mar 2025 03:16:02 GMT, Jason Mehrens <duke at openjdk.org> wrote:

>> 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 reall...
>
>>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.

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.

-------------

PR Review Comment: https://git.openjdk.org/jdk/pull/23491#discussion_r1977228065