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

[David Beaumont]

On Thu, 27 Feb 2025 14:07:17 GMT, Jason Mehrens <duke at openjdk.org> wrote:

>> Need to update to have single call to getFormatter().
>
>>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."
> 3. 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").
> 4. Logging api has supplier methods that allow callers to format arguments early on using String.format.
> 5. 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.

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

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

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