Broken logger initialization in 2.24.1

[kelunik]

Description

LoggerContext / LoggerRegistry don't play well together in using weak references, which can result in a null logger if the GC kicks in at a bad timing.

Configuration

Version: 2.24.1

Operating system: Linux / macOS

JDK: 21.0.4

Logs

java.lang.NullPointerException

Cannot invoke "org.apache.logging.log4j.spi.ExtendedLogger.logIfEnabled(String, org.apache.logging.log4j.Level, org.apache.logging.log4j.Marker, String)" because "this.logger" is null

at org.apache.logging.slf4j.Log4jLogger.warn(Log4jLogger.java:233)
at <internal company code>

Reproduction

• LoggerContext keeps a local reference to newLogger, but this isn't safe to keep a reference (see below).
• LoggerRegistry.putIfAbsent takes the instance and creates a WeakReference from it.
• Unfortunate GC timing might result in the weak reference being cleared and the following getLogger call returning null

Optimizing transformations of a program can be designed that reduce the number of objects that are reachable to be less than those which would naively be considered reachable. For example, a Java compiler or code generator may choose to set a variable or parameter that will no longer be used to null to cause the storage for such an object to be potentially reclaimable sooner.

https://docs.oracle.com/javase/specs/jls/se21/html/jls-12.html#jls-12.6.1

Fix

#2936 should fix this, but is currently unreleased.

Reference.reachabilityFence would also fix this, but is JDK 9+ only.

See also: https://shipilev.net/jvm/anatomy-quarks/8-local-var-reachability/

[kelunik]

Full reproducer: https://gist.github.com/kelunik/be51e5e2fdf746bbc86383b922bbb05e

[ppkarwasz]

@kelunik,

Thank you for the report.

The LoggerRegistry implementation was changed in 2.25.0-SNAPSHOT. Can you check if that fixes your issue?
Our snapshots are located in the https://repository.apache.org/snapshots/ Maven repository (see also our download page).

[centic9]

We hit a similar issues at Apache POI, there it happens reproducibly if log4j-core 2.24.0 and log4j-api 2.24.1 are used.

Reproducer: Run "./gradlew runWriteFile -PpoiVersion=5.4.0" in a checkout of https://github.com/centic9/poi-reproduce

This version-mismatch happens if a library like Apache POI upgrades "api" to the latest version, but projects using it do not upgrade log4j-core along the way. This is likely a common situation.

Is this also fixed in 2.25.0-SNAPSHOT or is this something else which we should report as a separate issue?

Edit: I verified with current 2.25.0-SNAPSHOT and this problem still reproduces, so I reported #3196 to discuss this as a separate issue.

[anuragagarwal561994]

@ppkarwasz when the version 2.25 will be released? And is 2.23 devoid of this bug?

[centic9]

As far as I couuld reproduce, it will not be fixed by current 2.25.0-SNAPSHOT, therefore I created bug #3196 for the issue with mixed "api" and "core" versions.

[ppkarwasz]

@anuragagarwal561994,

The bug was introduced in #2961 and it only affects Log4j API 2.24.1 and all the implementations that use LoggerRegistry.

Regarding the 2.25.0, we have a backlog of releases to make, so it might not happen before December. @vy, what do you think about releasing 2.24.2 with a fix to this problem?

[anuragagarwal561994]

Thanks for the change @ppkarwasz when can we expect the release for the same.

[ppkarwasz]

@anuragagarwal561994,

Thanks for the change @ppkarwasz when can we expect the release for the same.

I am planning a 2.24.2 release for Monday morning, provided that #3209 and #3210 will get reviews by then. See also this dev@logging thread.

As always, you are invited to review PRs, run release candidates in your tests and vote on releases. A motivated -1 on a release candidate can prevent faulty software from being released to the public.