Elasticsearch ingestnode crashes on a specific document?

Hey! I wrote a small application for our company which indexes all documents on our file server with the ingest attachment processor. In 7.x (as an extra plugin) it was working fine, since the change to 8.x (buildin ingest attachment) the ingest node crashes every time.

The indexer application runs just fine, doesn't get any errors, and the cluster accepts every new document even if the ingest node has crashed. Which makes it hard to find the document that kills the node.

β†’ systemctl status elasticsearch.service
● elasticsearch.service - Elasticsearch
     Loaded: loaded (/lib/systemd/system/elasticsearch.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/elasticsearch.service.d
             └─startup-timeout.conf
     Active: active (running) since Fri 2022-11-18 04:02:58 CET; 6 days ago
       Docs: https://www.elastic.co
   Main PID: 883 (java)
      Tasks: 159 (limit: 19122)
     Memory: 12.7G
     CGroup: /system.slice/elasticsearch.service
             β”œβ”€ 883 /usr/share/elasticsearch/jdk/bin/java -Xms4m -Xmx64m -XX:+UseSerialGC -Dcli.name=server -Dcli.script=/usr/share/elasticsearch/bin/elasticsearch -Dcli.libs=lib/tools/server-cli -Des.path.ho>
             β”œβ”€1140 /usr/share/elasticsearch/jdk/bin/java -Des.networkaddress.cache.ttl=60 -Des.networkaddress.cache.negative.ttl=10 -Djava.security.manager=allow -XX:+AlwaysPreTouch -Xss1m -Djava.awt.headles>
             └─1178 /usr/share/elasticsearch/modules/x-pack-ml/platform/linux-x86_64/bin/controller

Nov 18 04:00:51 ldc-data04 systemd[1]: Starting Elasticsearch...
Nov 18 04:02:58 ldc-data04 systemd[1]: Started Elasticsearch.
Nov 24 09:25:23 ldc-data04 systemd-entrypoint[1140]: 2022-11-24 09:25:23,003 elasticsearch[ldc-data04][system_write][T#2] ERROR Recursive call to appender rolling
Nov 24 09:25:23 ldc-data04 systemd-entrypoint[1140]: 2022-11-24 09:25:23,074 elasticsearch[ldc-data04][system_write][T#2] ERROR Recursive call to appender rolling
Nov 24 09:25:23 ldc-data04 systemd-entrypoint[1140]: 2022-11-24 09:25:23,131 elasticsearch[ldc-data04][system_write][T#2] ERROR Recursive call to appender rolling
Nov 24 09:25:23 ldc-data04 systemd-entrypoint[1140]: 2022-11-24 09:25:23,174 elasticsearch[ldc-data04][system_write][T#2] ERROR Recursive call to appender rolling

The service keeps running, but no new documents can get processed.

Also, the log file explodes and has over 30mb, that's a little much for around 5000 successfully ingested documents. At the end are mostly "java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "getenv.*")" exceptions and the last stacktrace is also cutted.

[2022-11-24T09:25:23,276][INFO ][o.a.p.h.c.Chunk          ] [ldc-data04] Command of type 31 not processed!
[2022-11-24T09:25:23,290][WARN ][stderr                   ] [ldc-data04] The system environment variables are not available to Log4j due to security restrictions: java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "getenv.*")
[2022-11-24T09:25:23,290][WARN ][stderr                   ] [ldc-data04] java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "getenv.*")
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.security.AccessControlContext.checkPermission(AccessControlContext.java:485)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.security.AccessController.checkPermission(AccessController.java:1068)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:411)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.lang.System.getenv(System.java:1198)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.util.EnvironmentPropertySource.containsProperty(EnvironmentPropertySource.java:99)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.util.PropertiesUtil$Environment.get(PropertiesUtil.java:513)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.util.PropertiesUtil$Environment.access$200(PropertiesUtil.java:434)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.util.PropertiesUtil.getStringProperty(PropertiesUtil.java:382)
[2022-11-24T09:25:23,291][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.util.PropertiesUtil.getBooleanProperty(PropertiesUtil.java:169)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.status.StatusLogger.isDebugPropertyEnabled(StatusLogger.java:143)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.status.StatusLogger.isEnabled(StatusLogger.java:426)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.status.StatusLogger.isEnabled(StatusLogger.java:354)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1914)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:463)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.PatternProcessor.formatFileName(PatternProcessor.java:291)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.PatternProcessor.formatFileName(PatternProcessor.java:278)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.AbstractRolloverStrategy.getEligibleFiles(AbstractRolloverStrategy.java:94)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.AbstractRolloverStrategy.getEligibleFiles(AbstractRolloverStrategy.java:87)
[2022-11-24T09:25:23,292][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy.rollover(DefaultRolloverStrategy.java:524)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(RollingFileManager.java:504)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(RollingFileManager.java:394)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:308)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:300)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:675)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:633)
[2022-11-24T09:25:23,293][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:616)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:552)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j.core@8.5.1/org.apache.logging.log4j.core.Logger.log(Logger.java:161)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2106)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.internal.DefaultLogBuilder.logMessage(DefaultLogBuilder.java:234)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.internal.DefaultLogBuilder.log(DefaultLogBuilder.java:162)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.chunks.Chunk.processCommands(Chunk.java:184)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.chunks.ChunkFactory.createChunk(ChunkFactory.java:207)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.streams.ChunkStream.findChunks(ChunkStream.java:66)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.streams.PointerContainingStream.findChildren(PointerContainingStream.java:70)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.streams.PointerContainingStream.findChildren(PointerContainingStream.java:77)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.streams.PointerContainingStream.findChildren(PointerContainingStream.java:77)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.HDGFDiagram.<init>(HDGFDiagram.java:89)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.poi.hdgf.extractor.VisioTextExtractor.<init>(VisioTextExtractor.java:52)
[2022-11-24T09:25:23,294][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.OfficeParser.parse(OfficeParser.java:232)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.OfficeParser.parse(OfficeParser.java:175)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.CompositeParser.parse(CompositeParser.java:298)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.AutoDetectParser.parse(AutoDetectParser.java:180)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.DelegatingParser.parse(DelegatingParser.java:71)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.extractor.ParsingEmbeddedDocumentExtractor.parseEmbedded(ParsingEmbeddedDocumentExtractor.java:108)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.ooxml.AbstractOOXMLExtractor.handleEmbeddedFile(AbstractOOXMLExtractor.java:406)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.ooxml.AbstractOOXMLExtractor.handleEmbeddedOLE(AbstractOOXMLExtractor.java:351)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.ooxml.AbstractOOXMLExtractor.handleEmbeddedPart(AbstractOOXMLExtractor.java:267)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.ooxml.AbstractOOXMLExtractor.handleEmbeddedParts(AbstractOOXMLExtractor.java:217)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.ooxml.AbstractOOXMLExtractor.getXHTML(AbstractOOXMLExtractor.java:138)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.ooxml.OOXMLExtractorFactory.parse(OOXMLExtractorFactory.java:242)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.microsoft.ooxml.OOXMLParser.parse(OOXMLParser.java:115)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.ParserDecorator.parse(ParserDecorator.java:152)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.CompositeParser.parse(CompositeParser.java:298)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.parser.AutoDetectParser.parse(AutoDetectParser.java:180)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.apache.tika.Tika.parseToString(Tika.java:525)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.ingest.attachment.TikaImpl.lambda$parse$0(TikaImpl.java:97)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.security.AccessController.doPrivileged(AccessController.java:712)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.ingest.attachment.TikaImpl.parse(TikaImpl.java:96)
[2022-11-24T09:25:23,295][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.ingest.attachment.AttachmentProcessor.execute(AttachmentProcessor.java:116)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.ingest.CompoundProcessor.innerExecute(CompoundProcessor.java:174)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.ingest.CompoundProcessor.execute(CompoundProcessor.java:152)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.ingest.Pipeline.execute(Pipeline.java:129)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.ingest.IngestDocument.executePipeline(IngestDocument.java:831)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.ingest.IngestService.innerExecute(IngestService.java:895)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.ingest.IngestService.executePipelines(IngestService.java:745)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.ingest.IngestService$1.doRun(IngestService.java:707)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:892)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at org.elasticsearch.server@8.5.1/org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.lang.Thread.run(Thread.java:1589)
[2022-11-24T09:25:23,296][WARN ][stderr                   ] [ldc-data04] The system environment variables are not available to Log4j due to security restrictions: java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "getenv.*")
[2022-11-24T09:25:23,297][WARN ][stderr                   ] [ldc-data04] java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "getenv.*")
[2022-11-24T09:25:23,297][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.security.AccessControlContext.checkPermission(AccessControlContext.java:485)
[2022-11-24T09:25:23,297][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.security.AccessController.checkPermission(AccessController.java:1068)
[2022-11-24T09:25:23,297][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:411)
[2022-11-24T09:25:23,297][WARN ][stderr                   ] [ldc-data04] 	at java.base/java.lang.System.getenv(System.java:1198)
[2022-11-24T09:25:23,297][WARN ][stderr                   ] [ldc-data04] 	at org.apache.logging.log4j@2.18.0/org.apache.logging.log4j.util.EnvironmentPropertySource.containsProperty(EnvironmentPropertySource.java:99)

Compressed Logfile

I don't know enough to help here, but I think it'd be worth you raising an issue on GitHub as this sounds like anomalous behaviour.

Already done github issue

Could be fixed with 8.5.3, I'm waiting for the release.

1 Like