Do not extract caller data in async worker when includeCallerData is false

[seonwooj0810]

Fixes #1059

Root cause

When AsyncAppender.includeCallerData is false, the caller (business) thread deliberately skips caller-data extraction in preprocess. However, if a downstream layout references %C, %M or %L, the pattern converters call LoggingEvent.getCallerData() from the async worker thread. Since callerDataArray is still null, getCallerData() lazily extracts it there — walking the worker thread's stack. This wastes CPU (the whole point of includeCallerData=false is to avoid that cost) and produces bogus ? values that have nothing to do with the real logging call site.

Change

• Add a LoggingEvent.allowCallerDataExtraction flag (default true). getCallerData() only lazily extracts when the flag is set.
• AsyncAppender.preprocess clears the flag when includeCallerData is false, so the worker thread no longer extracts caller data.

The existing caller-data converters (ClassOfCallerConverter, MethodOfCallerConverter, LineOfCallerConverter, CallerDataConverter) already treat absent caller data as not-available, so with the flag cleared they emit ? without paying the extraction cost. getCallerData() could already return null (CallerData.extract returns null for a null throwable), so no caller gains a new null case.

Test evidence

Added AsyncAppenderTest.notIncludingCallerDataPreventsExtractionEvenWhenLayoutRequestsIt: an async appender with includeCallerData=false feeding an OutputStreamAppender whose layout is %L. It asserts the event has no caller data after processing and that the layout emits the not-available marker. The test fails before this change (hasCallerData() returns true — caller data was extracted on the worker thread) and passes after it.

Verification done: built logback-core/logback-classic and ran the full logback-classic test suite (443 tests, 0 failures/errors) plus the new regression test (JDK 21, maven.compiler.release=11); confirmed the new test fails without the production change and passes with it.

---

This contribution was prepared with automated assistance and reviewed before submission.

[ceki]

@seonwooj0810 Thank you for another thoughtful PR. May I ask which AI agent and AI model you are using?

First, I must say that this PR shows that there is an existing problem deserving attention.

It fixes a misconfiguration issue at the price of slight increase of complexity and does not completely solve the issue. For example, if AsyncAppender is configured before some other appender, say AppenderB, and AsyncAppender calls setAllowCallerDataExtraction(false) on an event, AppenderB will not extract caller data.

It should be noted that this is also the case in the current code. AppenderB, will use the corrupt callerDataArray in the event filled in by AsyncAppender. Hence, the existence of a problem deserving attention.

I think it is preferable to alert the user about the AsyncAppender misconfiguration at configuration time rather than try to incompletely correct the misconfiguration later at runtime. The detection of the discrepancy can be done using a similar technique to that in #1056 "Detect file collisions in SiftingAppender nested appenders".

Alternatively, instead of just alerting about the discrepancy, we could automatically set AsyncAppender#includeCallerData to true when the underlying appender needs caller data. However, I think simply alerting the user with a warning message is the safer choice.

[seonwooj0810]

Thanks for the careful read — and for the direct question, happy to answer it.

Tooling. This is Claude Code (Anthropic's CLI agent), currently on Claude Opus 5, driven by a small harness of mine: it scouts issues, builds and tests a candidate fix locally, and drafts the PR text and follow-up replies. The account is mine and I'm accountable for everything submitted under it. If you'd like the disclosure in the PR description worded differently — or want these marked in some particular way for this project — say so and I'll follow that convention from here on.

Substance. Agreed, and your sibling-appender example is the decisive one: with ASYNC and AppenderB both attached to the same logger, ASYNC.preprocess clearing the flag on the shared event breaks AppenderB, and today's code corrupts it for AppenderB instead. Neither is something a runtime patch in preprocess can honestly fix. Warning at configuration time is the right trade — I'll drop LoggingEvent.allowCallerDataExtraction and revert preprocess to its current form.

One design question before I rewrite, because following #1056 literally runs into an ordering problem.

FileCollisionAnalyser is registered on AppenderModel in the DEPENDENCY_ANALYSIS phase, and DefaultProcessor.analyseDependencies walks the model tree pre-order in document order. That works for file collisions because the analyser only ever looks inside the appender's own subtree, or compares against appenders already seen earlier in the document. An AsyncAppender check is different: it has to follow <appender-ref> to a sibling <appender> model, which may be declared later in the file, so a per-AppenderModel analyser can't resolve it. Two ways out:

(a) Register the analyser on the root ConfigurationModel instead, walk the subtree once to build a name → AppenderModel map, then check each AsyncAppender model against its refs. Stays entirely in the Joran/model world like #1056 and adds no public API; the cost is that "does this appender need caller data" has to be decided from the <pattern> body text.

(b) Do the check in AsyncAppender.start(). By then the referenced appenders have been attached from the appender bag — and AppenderModelHandler.postHandle starts an appender before putting it there, so their PatternLayouts are already compiled. That makes the question exact rather than textual: walk the converter chain for ClassOfCallerConverter / MethodOfCallerConverter / LineOfCallerConverter / FileOfCallerConverter / CallerDataConverter, the same way EnsureExceptionHandling walks it for ThrowableHandlingConverter (recursing into CompositeConverter). It also covers programmatic configuration. The cost is one small public accessor for the compiled head converter on PatternLayoutBase.

I lean towards (b) for accuracy and for the non-XML case, but (a) is closer to what you suggested and keeps the public surface unchanged. Which would you prefer? I'll hold the rewrite until you say — either is a small change and I can push it quickly.

[ceki]

@seonwooj0810 Thank you for your thoughtful reply.

My suggestion to mimic #1056 "Detect file collisions in SiftingAppender nested appenders" was a bit misleading. Sorry about that.

I think the FileCollisionAnalyser#checkForCollisions() method is a better source of inspiration.

Specifically, a new analyser (say CallerContradictionAnalyser) associated with AppenderModel instances could populate a Map<String, Boolean> (for example named CALLER_CONTRADICTION_MAP). For an AppenderModel named "A1" that outputs caller data (via conversion words such as %C, %F, or %L), the analyser would set "A1" to Boolean.TRUE. If any other appender, say "A2," explicitly signals that it does not want caller data; for instance if A2 is an AsyncAppender and includeCallerData=false, the analyser would set "A2" to Boolean.FALSE. Looking at the map we could then detect the conflict and warn the user.

This contradiction-detection approach is more general than the specific case of an appender nested inside an AsyncAppender, where the inner one wants caller data and the outer one does not.

Does the above make sense? I’d love to hear what you think.

[seonwooj0810]

Yes, the CallerContradictionAnalyser design makes sense and I think it is the right approach. Let me map it to the concrete implementation I have in mind, so you can correct any misunderstanding before I write code.

What I would build

A new CallerContradictionAnalyser registered on AppenderModel in the DEPENDENCY_ANALYSIS phase (like FileCollisionAnalyser), operating on a shared Map<String, Boolean> CALLER_CONTRADICTION_MAP stored in mic.getObjectMap().

For each AppenderModel the handler sees:

1. Detect TRUE (wants caller data): Walk the appender's sub-models looking for a <pattern> or <encoder>/<pattern> element whose body text contains any of the caller-data conversion words (%C, %class, %F, %file, %L, %line, %M, %method, %caller). If found, put name → TRUE in the map.

2. Detect FALSE (suppresses caller data): If the className resolves to AsyncAppender and a sub-element <includeCallerData>false</includeCallerData> (or its abbreviated form) is present, put name → FALSE in the map. Then walk the appender's <appender-ref> children and check each referenced name in the map: if any ref maps to TRUE, emit a warning.

This covers the document-order case that logback XML almost always follows: inner (pattern) appenders are declared first so they are in the map when the outer AsyncAppender is processed.

One question about the edge case

If an inner appender is declared after its enclosing AsyncAppender in XML, step 2's ref-lookup will miss it (the ref name is not yet in the map). I see three options, listed from simplest to most robust:

• (a) Accept it. Document-order is the norm; the rare reversed-order configuration won't get the warning but won't misbehave either. Matches the implicit contract already in FileCollisionAnalyser (declaration order determines which file appender is flagged as the collider).
• (b) Two-pass. Register also on ConfigurationModel in a later phase (e.g., POST_DEPENDENCY_ANALYSIS, if one exists), iterate the full model tree a second time and check any remaining FALSE appenders against refs now fully populated.
• (c) Defer. Collect FALSE appenders without complete refs into a "pending" list; on ConfigurationModel handle, resolve the remaining refs against the fully-built map.

I lean toward (a) for simplicity unless you see common configs that would miss the warning. Which do you prefer?

Once you confirm the approach I will also drop the runtime flag (allowCallerDataExtraction) from the current diff and rewrite the test to verify a warning is emitted at config time instead.

[ceki]

Allow me go off on a tangent regarding order independence in configuration declarations.

In the analysis phase, AppenderDeclarationAnalyser computes which appenders are declared, and AppenderRefDependencyAnalyser maps which components (such as loggers and AsyncAppender) depend on other appenders.

Thus, in the second processing phase, models are processed only after their dependencies have been processed. This holds independently of the location of their declarations in the XML. This guarantees that the model corresponding to an AsyncAppender is processed only after the appender it references has been started.

However, since CallerContradictionAnalyser is activated only in the DEPENDENCY_ANALYSIS phase, we need not assume which of the models—the AsyncAppender model or the model for the appender it depends on—will be invoked first.

This should not be a problem as long as CallerContradictionAnalyser also checks for contradictions when TRUE is detected. The algorithm outlined above should therefore be modified as follows:

For each AppenderModel the handler sees:

• Detect TRUE (wants caller data): Walk the appender's sub-models looking for a <pattern> or <encoder>/<pattern> element whose body text contains any of the caller-data conversion words (%C, %class, %F, %file, %L, %line, %M, %method, %caller), or if includeCallerData is set to true. If found, put name → TRUE in the map, then walk the map and check whether any entry has the value FALSE. If a contradiction is found, emit a warning.

• Detect FALSE (suppresses caller data): If the class name resolves to AsyncAppender and a sub-element includeCallerData is set to false, put name → FALSE in the map, then walk the map and check whether any entry has the value TRUE. If a contradiction is found, emit a warning.

If multiple appenders have contradicting wishes, the algorithm above will emit multiple partial warnings.

It would probably be cleaner to have CallerContradictionAnalyser only populate the contradiction map per AppenderModel, and to have another analyser (say, CallerContradictionWarnAnalyser) associated with ConfigurationModel.class warn about contradictions in its postHandle() method.

Unfortunately, DefaultProcessor#analyseDependencies does not invoke postHandle() on analysers. I will fix that in a subsequent commit.

Does the above make sense?

[seonwooj0810]

Yes, that makes complete sense. Let me summarize my understanding to confirm we're aligned:

Bi-directional map check (order-independence):

• On detecting TRUE (caller-data needed): record name → TRUE in the map, then scan the map for any existing FALSE entry → emit warning if found.
• On detecting FALSE (AsyncAppender with includeCallerData=false): record name → FALSE in the map, then scan the map for any existing TRUE entry → emit warning if found.

This way, regardless of which AppenderModel the analyser visits first, the contradiction is always detected.

Two-analyser split:

• CallerContradictionAnalyser (per-AppenderModel): populates the contradiction map only.
• CallerContradictionWarnAnalyser (per-ConfigurationModel, in postHandle()): walks the completed map and emits all warnings.

This is cleaner because the warning step runs exactly once, after all appender models have been analysed. I'll wait for the DefaultProcessor#analyseDependencies fix that makes postHandle() callable on analysers before wiring the second analyser up. In the meantime, I can prototype CallerContradictionAnalyser itself against this spec — would that be helpful, or would you prefer I hold until the framework patch lands?

[ceki]

@seonwooj0810 Commits e22a528 and 500a46a fix the issue regarding postHandle calls of analyzers.

[seonwooj0810]

Thank you for the framework patches! I confirmed both commits are in upstream/master and rebased the branch.

I've now replaced the runtime flag approach entirely with the CallerContradictionAnalyser design we agreed on:

CallerContradictionAnalyser (AppenderModel) — on handle():

• If appender is AsyncAppender and includeCallerData is absent or false (the default): records the appender name and its <appender-ref> set in ASYNC_SUPPRESSES_CALLER_DATA_MAP
• If appender has a <pattern> containing a caller-data converter (%C/%M/%L/%F/%l/%class/%method/%line/%file/%caller): records the name in NEEDS_CALLER_DATA_SET

CallerContradictionWarnAnalyser (ConfigurationModel) — in postHandle(), runs after all children have been visited:

• Iterates the suppresses map; for each AsyncAppender's referenced names, emits a WARN if the name is in the needs-caller-data set

Both registered in ModelClassToModelHandlerLinker. Three test cases: WARN triggered, no WARN when includeCallerData=true, no WARN when pattern has no caller-data converters — all green.

Pushed as 3c76ed9ad (force-push justified by the rebase and design change). Please let me know if the structure matches your expectations.

[ceki]

@seonwooj0810 Thank you for this PR.

It seems to me that these logic of CallerContradictionWarnAnalyser/CallerContradictionWarnAnalyser can be simplified by ignoring any references to appenders in AsyncAppender.

The fact that an appender is referenced by AsyncAppender is not the key factor here. If appenderA wants caller data, and asyncAppender does not, there is a contradiction, independently of whether appenderA is referenced by asyncAppender or not.

We did not take into account the case of the user setting AsyncApppender.includeCallerData to true but no appenders making use of caller data. I think we failed to consider this case.

I think we need to distinguish data gathered from AsyncAppender and data gather from regular appenders.
If we call W_TRUE, T_FALSE for data gathered by AsyncAppender and TRUE data gathered from other appender, then contradiction can be computed as follows.

Given a set S containing elements from the set {W_TRUE, W_FALSE, TRUE}, here is a method called contradiction(S) resulting in the string "GOOD" or "BAD". It follows the following logic:

• Empty set is allowed; call to contradiction(S) should result in "GOOD".
• TRUE elements can exist alone; call to contradiction(S) should result in "GOOD".
• one or more W_TRUE elements can coexist with one or more TRUE elements; call to contradiction(S) should result in "GOOD".
• W_FALSE cannot be allowed to coexist with W_TRUE; call to contradiction(S) should result in "BAD".
• W_FALSE cannot be allowed to coexist with TRUE; call to contradiction(S) should result in "BAD".
• W_TRUE alone is not allowed. call to contradiction(S) should result in "BAD".
   

import java.util.Set;

public enum Element {
    W_TRUE, W_FALSE, TRUE
}

public class ContradictionChecker {

    /**
     * Returns "GOOD" or "BAD" according to the following rules:
     * - Empty set                                  → "GOOD"
     * - Only TRUE (one or more)                    → "GOOD"
     * - W_TRUE together with TRUE                  → "GOOD"
     * - W_FALSE together with W_TRUE               → "BAD"
     * - W_FALSE together with TRUE                 → "BAD"
     * - Only W_TRUE (no TRUE)                      → "BAD"
     * - Only W_FALSE                               → "GOOD"   (not forbidden by the stated rules)
     */
    public static String contradiction(Set<Element> S) {
        boolean hasWTrue  = S.contains(Element.W_TRUE);
        boolean hasWFalse = S.contains(Element.W_FALSE);
        boolean hasTrue   = S.contains(Element.TRUE);

        // W_FALSE may not coexist with either W_TRUE or TRUE
        if (hasWFalse && (hasWTrue || hasTrue)) {
            return "BAD";
        }

        // W_TRUE is not allowed without at least one TRUE
        if (hasWTrue && !hasTrue) {
            return "BAD";
        }

        // All remaining cases are consistent
        return "GOOD";
    }
}

Please let me know if the above makes sense. Also would you like to submit a PR for this?

[ceki]

@seonwooj0810 Given that the release logback version 1.6.2 is being held by this item, I will go on and fix it without further ado. I should note that your PR has laid the necessary infrastructure to fix this issue. Thank you for that.

[ceki]

Commit b1a80d6 adds CallerInstructionLogic which groups the core logic behind contradiction analysis.