Deadlock on ingest attachment nodes during log rollover

[Rassyan]

Elasticsearch Version

8.16.1

Installed Plugins

No response

Java Version

bundled

OS Version

Problem Description

Summary

The issue observed here is exactly the same as in #91964 and remains unresolved. There is a reproducible Java-level deadlock in Elasticsearch ingest attachment nodes during log rollover. This deadlock causes ingest nodes to hang indefinitely, and is especially likely to occur under heavy ingest/logging load. After reviewing #93878 discussions, it is clear that the community has focused on logging loss, logging bridges, and permission issues related to log4j, but has not identified or addressed the potential for a JVM-level deadlock caused by log4j2's RollingFileManager and BufferedWriter lock cycle.

Details

• Elasticsearch version: 8.16.1
• log4j2 version: 2.19.0 (bundled)
• Node type: Dedicated ingest node

jstack evidence

Below is a minimal excerpt from a real production jstack, showing the deadlock:

Found one Java-level deadlock:
=============================
"elasticsearch[1751529376016684232][cluster_coordination][T#1]":
  waiting to lock monitor 0x00007f3f214190e0 (object 0x00000010012ae8f0, a org.apache.logging.log4j.core.appender.rolling.RollingFileManager),
  which is held by "elasticsearch[1751529376016684232][write][T#16]"

"elasticsearch[1751529376016684232][write][T#16]":
  waiting to lock monitor 0x00007f3f02e4a000 (object 0x0000001011305730, a java.io.BufferedWriter),
  which is held by "elasticsearch[1751529376016684232][write][T#15]"

"elasticsearch[1751529376016684232][write][T#15]":
  waiting to lock monitor 0x00007f3f214190e0 (object 0x00000010012ae8f0, a org.apache.logging.log4j.core.appender.rolling.RollingFileManager),
  which is held by "elasticsearch[1751529376016684232][write][T#16]"

Impact

• Ingest nodes become permanently stuck, requiring a process restart.
• All ingest pipelines and possibly cluster coordination are affected.

Attachments

• Full jstack available upon request.

Steps to Reproduce

1. Use attachment processor
2. Almost always during log rollover under ingest load

As #93878 (comment) said

Logs (if relevant)

jstack.txt

[Rassyan]

@joegallo @masseyke , since you have participated in related discussions before, could you please take a look at this new issue? Your input would be greatly appreciated. Thank you!

[masseyke]

@Rassyan is there any chance that you have tika logging enabled in your elasticsearch config? It's been a long time since I've looked at this, but it seems like that was the one remaining potential source of problems that we were aware of. I saw a very similar deadlock a while back. It only happened if I had log4j 2.18.0 or newer and had tika logging enabled (it's off by default in elasticsearch, unless someone has changed that recently). Here's what I saw:

Found one Java-level deadlock:
=============================
"elasticsearch[keiths-mbp.lan][masterService#updateTask][T#1]":
  waiting to lock monitor 0x0000600005bbd930 (object 0x000000175b341a08, a org.apache.logging.log4j.core.appender.rolling.RollingFileManager),
  which is held by "elasticsearch[keiths-mbp.lan][write][T#15]"

"elasticsearch[keiths-mbp.lan][write][T#15]":
  waiting to lock monitor 0x0000600005bd0000 (object 0x000000175b82a3d8, a java.io.BufferedWriter),
  which is held by "elasticsearch[keiths-mbp.lan][write][T#1]"

"elasticsearch[keiths-mbp.lan][write][T#1]":
  waiting to lock monitor 0x0000600005bcf810 (object 0x000000175b828358, a java.io.PrintStream),
  which is held by "elasticsearch[keiths-mbp.lan][write][T#15]"

[masseyke]

I think that this is a log4j bug, and I think that it only happens if appender.rolling.strategy.fileIndex is set to nomax (which is what elasticsearch does) and if rollover is happening very frequently (which it is, if tika logging is enabled). If I can get it into a reproducible test, I'll open a log4j bug. I have not tested this, but I think you could avoid this if you either disabled tika-related logging (the settings in https://github.com/elastic/elasticsearch/blob/main/modules/ingest-attachment/src/main/config/log4j2.properties) or increase your log rollover size.

[masseyke]

It looks like this deadlock also requires that a call to System.getEnv() throw a SecurityException. Unfortunately that is not possible in the current JDK (the security manager has been removed). So I can't create a test case to reproduce this on Java 21+. But the good news is that this also means that this deadlock can't occur on newer versions of Elasticsearch that run on versions of Java that don't have the security manager.

[elasticsearchmachine]

Pinging @elastic/es-data-management (Team:Data Management)

[Rassyan]

@Rassyan is there any chance that you have tika logging enabled in your elasticsearch config? It's been a long time since I've looked at this, but it seems like that was the one remaining potential source of problems that we were aware of. I saw a very similar deadlock a while back. It only happened if I had log4j 2.18.0 or newer and had tika logging enabled (it's off by default in elasticsearch, unless someone has changed that recently). Here's what I saw:

Found one Java-level deadlock:
=============================
"elasticsearch[keiths-mbp.lan][masterService#updateTask][T#1]":
  waiting to lock monitor 0x0000600005bbd930 (object 0x000000175b341a08, a org.apache.logging.log4j.core.appender.rolling.RollingFileManager),
  which is held by "elasticsearch[keiths-mbp.lan][write][T#15]"

"elasticsearch[keiths-mbp.lan][write][T#15]":
  waiting to lock monitor 0x0000600005bd0000 (object 0x000000175b82a3d8, a java.io.BufferedWriter),
  which is held by "elasticsearch[keiths-mbp.lan][write][T#1]"

"elasticsearch[keiths-mbp.lan][write][T#1]":
  waiting to lock monitor 0x0000600005bcf810 (object 0x000000175b828358, a java.io.PrintStream),
  which is held by "elasticsearch[keiths-mbp.lan][write][T#15]"

Never changed. Same as changes of #93878

logger.org_apache_pdfbox.name = org.apache.pdfbox
logger.org_apache_pdfbox.level = off

logger.org_apache_poi.name = org.apache.poi
logger.org_apache_poi.level = off

logger.org_apache_fontbox.name = org.apache.fontbox
logger.org_apache_fontbox.level = off

logger.org_apache_xmlbeans.name = org.apache.xmlbeans
logger.org_apache_xmlbeans.level = off

log4j2.properties.txt

[Rassyan]

@masseyke Thank you for your detailed analysis. To help investigate the logging deadlock, we’ve verified the following:

• Log files failed to roll over during deadlock (confirmed via logs/ directory state)
• Zero new logs generated after deadlock occurred
• Java version: openjdk 21.0.1 2023-11-02 LTS
• Log4j version: 2.19.0 (bundled with Elasticsearch 8.16.1)
• ​Deadlock Path Confirmed: The log snippet shows the critical sequence: System.getenv() → SecurityException → Log4j debug logging → RollingFileManager.rollover()
• POI Component's Role: While Tika logging is disabled, we observe frequent org.apache.poi.hdgf.chunks.Chunk warnings during document parsing. These likely accelerated log growth and rollover triggers.

[Rassyan]

It looks like this deadlock also requires that a call to System.getEnv() throw a SecurityException. Unfortunately that is not possible in the current JDK (the security manager has been removed). So I can't create a test case to reproduce this on Java 21+. But the good news is that this also means that this deadlock can't occur on newer versions of Elasticsearch that run on versions of Java that don't have the security manager.

We've confirmed the deadlock occurs in our JDK 21 environment (Openjdk 21.0.1) because SecurityManager remains active despite JEP 411 - Elasticsearch explicitly enables it before v8.19 (#127727)

The deadlock flow seems like:

graph TD
    ThreadA[Thread A: Log Roller] -->|Holds| LockA[RollingFileManager Lock]
    ThreadB[Thread B: Log Writer] -->|Holds| LockB
    ThreadA -->|Triggers| SecurityException
    SecurityException -->|Requires logging| DebugLog[Debug Log]
    DebugLog -->|Waits for| LockB[BufferedWriter Lock]
    
    ThreadB -->|Reaches threshold| NeedRollover[Needs Rollover]
    NeedRollover -->|Waits for| LockA

Loading

Hope #93878 (comment) can help you reproduce.

[masseyke]

Thanks. I was able to reproduce it (or something very close), and have started a log4j discussion at apache/logging-log4j2#3837. In the meantime, does disabling poi and pdfbox logging avoid the problem for you?