*Abstract:* Nested logging does not always work, it conflicts with
`log4j2.formatMsgAsync`, and I need help on fixing it.
*Problem description*
Nested logging – that is, while trying to `log()`,
exception/argument/message access invokes `log()` too – only works with
message factories that eagerly format the message. `LoggerConfig` contains
the following logic:
var logEvent = logEventFactory.createEvent();
log(logEvent); // goes to `AppenderControl#shouldSkip()`
Imagine the following:
private static final class ArgThatLogs {
@Override
public String toString() {
logger.trace("foo");
return "bar";
}
}
logger.info("{} buzz", new ArgThatLogs());
In `LoggerConfig`, if the `logEventFactory` of subject is
`ReusableLogEventFactory`, `createEvent()` will first try to format the
message (which will trigger `ArgThatLogs#toString()`, which will trigger
`logger.trace("foo")`), and then call `log(logEvent)`. Hence the logging
output will be as follows:
foo
bar buzz
If the `logEventFactory` of subject is `DefaultLogEventFactory`,
`createEvent()` will perform no formatting, `log(logEvent)` will be
invoked, and then `ArghThatLogs#toString()`, and then
`logger.trace("foo")`, and then `AppenderControl#shouldSkip()` will return
`true` due to `isRecursiveCall()` returning `true`. Hence the logging
output will be as follows:
bar buzz
Note the missing `foo` log line. As a matter of fact, all `*Nested*Test`
classes fail when `DefaultLogEventFactory` is used.
I thought of matching the behavior between the two log event factories by
making the `DefaultLogEventFactory` format the message at creation. This
would imply both message factories will be formatting the message eagerly.
(Formatting the message at the logger thread was also suggested by Nitsan
Wakart
<https://github.com/apache/logging-log4j2/issues/2220#issuecomment-1902035073>,
the JVM performance celebrity, too.)
While examining the code base on this subject, I came across the
`log4j2.formatMsgAsync` property (flag that *"will make sure the message is
formatted in the caller thread"*) and the `@AsynchronouslyFormattable`
annotation. This gets the things even more complicated:
1. These configuration knobs contradict with the *"eagerly format
messages everywhere"* feature I suggested to implement above.
2. If `log4j2.formatMsgAsync=true`, nested logging does not work
anymore. That is, postponing the message formatting to `log(logEvent)`
causes recursion and hence the nested `log(logEvent)` gets skipped.
(`DefaultLogEventFactory` fails to log the nested call exactly due to the
same reason.)
3. One would expect these configuration knobs to be effective somewhere
in my nested logging example above. But they surprisingly play no role in
this entire flow in almost all cases. That is, there is
`InternalAsyncUtil.makeMessageImmutable()` taking these configuration knobs
into account, but it is only called in async. contexts (e.g.,
`AsyncAppender` or `AsyncLogger) when a message is not reusable. It makes
sense that the configuration is taken into account only when the context is
async. But it should *not* depend on if-the-message-is-reusable
condition. That is, the fact that reusable messages are *always*
formatted eagerly violates the `log4j2.formatMsgAsync=true` condition, if
provided.
There is a performance issue in the design
of `InternalAsyncUtil.makeMessageImmutable()` too. It invokes
`Message#getFormattedMessage()` to indicate to the message that it can
format the message and cache the result, if possible. Yet,
`getFormattedMessage()` has a return type of `String`, forcing the message
to allocate a string unnecessarily.
Formatting messages asynchronously (LOG4J2-898
<https://issues.apache.org/jira/browse/LOG4J2-898>) was implemented by
Remko. AFAIC, formatting messages async. and nested logging are features
that don't always work and enabling one breaks the behaviour of the other.
A user caring about logger latency (i.e., `log4j2.formatMsgAsync=true`),
cannot have nested logging. Likewise, a user caring about nested logging
cannot have async. message formatting, since postponing message formatting
is causing recursion which eventually causes the nested logging to get
dropped. Plus, none of the features work as advertised for all cases. They
both unexpectedly don't work under certain circumstances.
AFAIK, nested logging is not a documented feature. Yet one can find several
tickets people has filed issues that were fixed by us. Hence, it is safe to
conclude that it is used.
I also don't know why recursion is not allowed in `AppenderControl`.
(Related history is too old and could not get in while migrating from SVN
to Git.)
*Summary*
Let me try to recap the story:
1. Nested logging is not a documented feature, yet expected to work by
users
2. Nested logging doesn't always work (when message formatting is
postponed either by using `DefaultLogEventFactory` or setting
`log4j2.formatMsgAsync=true`)
3. `log4j2.formatMsgAsync` and `@AsynchronouslyFormattable` don't always
work (`log4j2.formatMsgAsync=false` is ignored for reusable messages, which
are formatted always eagerly)
4. `log4j2.formatMsgAsync`/`@AsynchronouslyFormattable` and the way
currently nested logging works (e.g., eagerly formatting the message) are
conflicting features
At this stage... I am lost. I don't know what to fix. I don't know which
behaviour we shall keep/drop. I will appreciate it if you can think along
with me.
