GitHub user jhl221123 added a comment to the discussion: Deadlock under unusual
conditions
I have investigated this deadlock issue and would like to share a summary of my
analysis and results.
### Summary
**The issue is resolved in version `2.25.1`**. My analysis of version `2.19.0`
shows the root cause was a classic lock-order inversion deadlock.
---
### 1. Root Cause Analysis (on v2.19.0)
The deadlock occurs from a conflict between two locks:
* The Monitor Lock: The `synchronized` lock on the `RollingFileManager`
instance.
* The ReentrantLock: The internal lock within the `PrintStream` instance used
by `System.out`.
This happens when two threads attempt to acquire these locks in the exact
opposite order.
#### Path A: Monitor Lock → ReentrantLock
This path is triggered when a rollover occurs and throws an exception.
1. A thread enters a `synchronized` method like `checkRollover()`, acquiring
the **Monitor Lock** on the `RollingFileManager`.
2. Inside the rollover process, the custom `SecurityManager` throws a
`SecurityException` when `System.getenv()` is called.
3. Log4j's internal exception logging (`LowLevelLogUtil`) then attempts to
print the stack trace, which requires acquiring the **ReentrantLock**. The
thread now holds the Monitor Lock while waiting for the ReentrantLock.
<details>
<summary>Click to see relevant stack trace for Path A</summary>
```text
- parking to wait for <0x000000070fa290a0> (a
java.util.concurrent.locks.ReentrantLock$NonfairSync)
…
at jdk.internal.misc.InternalLock.lock([email protected]/InternalLock.java:74)
at java.io.PrintStream.write([email protected]/PrintStream.java:621)
…
at org.apache.logging.log4j.util.LowLevelLogUtil.log(LowLevelLogUtil.java:44)
at
org.apache.logging.log4j.util.LowLevelLogUtil.logException(LowLevelLogUtil.java:55)
at
org.apache.logging.log4j.util.EnvironmentPropertySource.logException(EnvironmentPropertySource.java:43)
at
org.apache.logging.log4j.util.EnvironmentPropertySource.containsProperty(EnvironmentPropertySource.java:103)
at
org.apache.logging.log4j.util.PropertiesUtil$Environment.get(PropertiesUtil.java:533)
at
org.apache.logging.log4j.util.PropertiesUtil$Environment.access$200(PropertiesUtil.java:444)
…
at
org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(RollingFileManager.java:394)
- locked <0x000000070e8700f8> (a
org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
at
org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:308)
- locked <0x000000070e8700f8> (a
org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
at
org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:300)
```
</details>
#### Path B: ReentrantLock → Monitor Lock
This path is triggered by a standard `System.out.println()` call in the test.
1. First, the test redirects `System.out` to a `PrintStream` that calls our
logger.
```java
PrintStream logPrintStream = new PrintStream(new OutputStream() {
// ... (implementation that calls logger.info()) ...
}, false);
System.setOut(logPrintStream);
System.setErr(logPrintStream);
```
2. A worker thread calls `System.out.println()`, which immediately acquires
the **ReentrantLock** inside the `PrintStream`.
3. The custom `OutputStream` then calls `logger.info()`. This logging attempt
eventually requires access to the `RollingFileManager`, trying to acquire the
**Monitor Lock**. The thread now holds the ReentrantLock while waiting for the
Monitor Lock.
<details>
<summary>Click to see relevant stack trace for Path B</summary>
```text
- waiting to lock <0x000000070e8700f8> (a
org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
at
org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:94)
…
at
org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:301)
at
org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
…
at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1320)
at log4j2.Log4j2DeadlockTests$1.write(Log4j2DeadlockTests.java:67)
at java.io.OutputStream.write([email protected]/OutputStream.java:167)
at java.io.PrintStream.implWrite([email protected]/PrintStream.java:643)
at java.io.PrintStream.write([email protected]/PrintStream.java:623)
…
at java.io.PrintStream.writeln([email protected]/PrintStream.java:826)
at java.io.PrintStream.println([email protected]/PrintStream.java:1168)
at log4j2.Log4j2DeadlockTests.lambda$main$0(Log4j2DeadlockTests.java:95)
```
```java
In TextEncoderHelper.java:
private static void writeEncodedText(..., final ByteBufferDestination
destination, ...) {
...
result = charsetEncoder.flush(byteBuf);
if (!result.isUnderflow()) {
synchronized(destination) { // <-- DEADLOCK POINT: Tries to acquire the
Monitor Lock held by Path A
flushRemainingBytes(charsetEncoder, destination, byteBuf);
}
}
...
}
```
</details>
When Path A and Path B execute concurrently, a deadlock is guaranteed.
---
### 2. Verification on v2.25.1
I re-ran the exact same test code against version **`2.25.1`**.
I can confirm that **the deadlock no longer occurs**. The application runs to
completion successfully. It seems that the removal of `LowLevelLogUtil` in
release `2.23.x` ultimately resolved this specific deadlock.
I'd appreciate any feedback on this analysis. Thanks!
GitHub link:
https://github.com/apache/logging-log4j2/discussions/3837#discussioncomment-13911795
----
This is an automatically sent email for [email protected].
To unsubscribe, please send an email to: [email protected]
