On Sun, 2 Mar 2025 03:16:02 GMT, Jason Mehrens <d...@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
