We observe at times ArrayIndexOutofBoundsException during creating of pipeline.
Here we use log4j2 pattern as PatternLayout for processing the logs.
From the logs it is unclear, is it something with log event not matching the pattern configured in log4j2 properties or issue with JRuby runtime
Versions:
LogStash: 8.13.0
Jruby: 9.4.5
JDK: 11
Logs:
[logstash.runner] Starting Logstash {'logstash.version'=>'8.13.0', 'jruby.version'=>'jruby 9.4.5.0 (3.1.4) 2023-11-02 1abae2700f OpenJDK 64-Bit Server VM 11.0.23+9-suse-150000.3.113.1-x8664 on 11.0.23+9-suse-150000.3.113.1-x8664 +indy +jit [x86_64-linux]'}
[logstash.runner] JVM bootstrap flags: [-XX:InitialRAMPercentage=25.00, -XX:MinRAMPercentage=50.00, -XX:MaxRAMPercentage=25.00, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djruby.compile.invokedynamic=true, -XX:+HeapDumpOnOutOfMemoryError, -Djava.security.egd=file:/dev/urandom, -Dlog4j2.isThreadContextMapInheritable=true, -Dlogstash.jackson.stream-read-constraints.max-string-length=200000000, -Dlogstash.jackson.stream-read-constraints.max-number-length=10000, -Dlog4j2.formatMsgNoLookups=true, -Djava.io.tmpdir=/opt/logstash/resource/tmp, -XX:InitialRAMPercentage=67.000000, -XX:MaxRAMPercentage=67.000000, -XX:MinRAMPercentage=67.000000, -Djruby.regexp.interruptible=true, -Djdk.io.File.enableADS=true, --add-opens=java.base/java.security=ALL-UNNAMED, --add-opens=java.base/java.io=ALL-UNNAMED, --add-opens=java.base/java.nio.channels=ALL-UNNAMED, --add-opens=java.base/sun.nio.ch=ALL-UNNAMED, --add-opens=java.management/sun.management=ALL-UNNAMED, -Dio.netty.allocator.maxOrder=11]
[logstash.runner] Jackson default value override `logstash.jackson.stream-read-constraints.max-string-length` configured to `200000000`
[logstash.runner] Jackson default value override `logstash.jackson.stream-read-constraints.max-number-length` configured to `10000`
[logstash.settings] Creating directory {:setting=>'path.queue', :path=>'/opt/logstash/data/queue'}
[logstash.settings] Creating directory {:setting=>'path.dead_letter_queue', :path=>'/opt/logstash/data/dead_letter_queue'}
[logstash.agent] No persistent UUID file found. Generating new UUID {:uuid=>'112b0b23-1b34-457a-884b-416d32291f68', :path=>'/opt/logstash/data/uuid'}
[logstash.agent] Successfully started Logstash API endpoint {:port=>9600, :ssl_enabled=>false}
[org.reflections.Reflections] Reflections took 310 ms to scan 1 urls, producing 132 keys and 468 values
/opt/logstash/vendor/bundle/jruby/3.1.0/gems/amazing_print-1.6.0/lib/amazing_print/formatter.rb:37: warning: previous definition of cast was here
"[org.logstash.ackedqueue.QueueUpgrade] No PQ version file found, upgrading to PQ v2."}
[logstash.javapipeline] Pipeline `opensearch` is configured with `pipeline.ecs_compatibility: disabled` setting. All plugins in this pipeline will default to `ecs_compatibility => disabled` unless explicitly configured otherwise.
[logstash.outputs.opensearch] New OpenSearch output {:class=>'LogStash::Outputs::OpenSearch', :hosts=>['//eric-data-search-engine-tls:9200']}
2024-06-23T14:05:26.911011884Z WARNING: An illegal reflective access operation has occurred
2024-06-23T14:05:26.912388399Z WARNING: Illegal reflective access by org.jruby.javasupport.binding.ConstantField (file:/opt/logstash/vendor/jruby/lib/jruby.jar) to field sun.security.x509.X509CertImpl.SIG
2024-06-23T14:05:26.914422709Z WARNING: Please consider reporting this to the maintainers of org.jruby.javasupport.binding.ConstantField
2024-06-23T14:05:26.917132633Z WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
2024-06-23T14:05:26.918542830Z WARNING: All illegal access operations will be denied in a future release
[logstash.outputs.opensearch] OpenSearch pool URLs updated {:changes=>{:removed=>[], :added=>[https://eric-data-search-engine-tls:9200/]}}
[logstash.outputs.opensearch] Attempted to resurrect connection to dead OpenSearch instance, but got an error {:url=>'https://eric-data-search-engine-tls:9200/', :exception=>LogStash::Outputs::OpenSearch::HttpClient::Pool::HostUnreachableError, :message=>'OpenSearch Unreachable: [https://eric-data-search-engine-tls:9200/][Manticore::SocketException] Connect to eric-data-search-engine-tls:9200 [eric-data-search-engine-tls/10.104.97.251] failed: Connection refused (Connection refused)'}
[logstash.javapipeline] Starting pipeline {:pipeline_id=>'opensearch', 'pipeline.workers'=>2, 'pipeline.batch.size'=>2048, 'pipeline.batch.delay'=>50, 'pipeline.max_inflight'=>4096, 'pipeline.sources'=>['/opt/logstash/resource/searchengine.conf'], :thread=>'#<Thread:0x5d34949c /opt/logstash/logstash-core/lib/logstash/java_pipeline.rb:134 run>'}
[org.logstash.ackedqueue.QueueUpgrade] No PQ version file found, upgrading to PQ v2.
[logstash.javapipeline] Pipeline `logstash` is configured with `pipeline.ecs_compatibility: disabled` setting. All plugins in this pipeline will default to `ecs_compatibility => disabled` unless explicitly configured otherwise.
[org.logstash.instrument.metrics.gauge.LazyDelegatingGauge] A gauge metric of an unknown type (org.jruby.specialized.RubyArrayOneObject) has been created for key: send_to. This may result in invalid serialization. It is recommended to log an issue to the responsible developer/development team.
[logstash.javapipeline] Starting pipeline {:pipeline_id=>'logstash', 'pipeline.workers'=>2, 'pipeline.batch.size'=>2048, 'pipeline.batch.delay'=>50, 'pipeline.max_inflight'=>4096, 'pipeline.sources'=>['/opt/logstash/resource/logstash.conf'], :thread=>'#<Thread:0x2af1a73b /opt/logstash/logstash-core/lib/logstash/java_pipeline.rb:134 run>'}
[logstash.javapipeline] Pipeline Java execution initialization time {'seconds'=>4.49}
[logstash.javapipeline] Pipeline started {'pipeline.id'=>'opensearch'}
2024-06-23T14:05:33.221796419Z 2024-06-23 14:05:33,136 Converge PipelineAction::Create<opensearch> ERROR An exception occurred processing Appender plain_console java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 80
2024-06-23T14:05:33.223630682Z at org.jruby.runtime.ThreadContext.popFrame(ThreadContext.java:559)
2024-06-23T14:05:33.225363144Z at org.jruby.internal.runtime.methods.MixedModeIRMethod.post(MixedModeIRMethod.java:70)
2024-06-23T14:05:33.227129377Z at org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:166)
2024-06-23T14:05:33.228871137Z at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:151)
2024-06-23T14:05:33.230644216Z at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:212)
2024-06-23T14:05:33.232302875Z at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:456)
2024-06-23T14:05:33.233886766Z at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:195)
2024-06-23T14:05:33.235651503Z at org.jruby.RubyBasicObject.rbInspect(RubyBasicObject.java:1096)
2024-06-23T14:05:33.237376403Z at org.jruby.RubyObject.inspect(RubyObject.java:452)
2024-06-23T14:05:33.239035252Z at org.jruby.RubyHash$3.visit(RubyHash.java:915)
2024-06-23T14:05:33.240639672Z at org.jruby.RubyHash$3.visit(RubyHash.java:911)
2024-06-23T14:05:33.242218307Z at org.jruby.RubyHash.visitLimited(RubyHash.java:760)
2024-06-23T14:05:33.310513186Z at org.jruby.RubyHash.visitAll(RubyHash.java:745)
2024-06-23T14:05:33.312662293Z at org.jruby.RubyHash.inspectHash(RubyHash.java:906)
2024-06-23T14:05:33.314850915Z at org.jruby.RubyHash.inspect(RubyHash.java:945)
2024-06-23T14:05:33.316378116Z at org.jruby.RubyHash.to_s(RubyHash.java:1011)
2024-06-23T14:05:33.318075090Z at org.jruby.RubyHash$INVOKER$i$0$0$to_s.call(RubyHash$INVOKER$i$0$0$to_s.gen)
2024-06-23T14:05:33.319934171Z at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:456)
2024-06-23T14:05:33.321629326Z at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:195)
2024-06-23T14:05:33.323293441Z at org.jruby.RubyObject.toRubyString(RubyObject.java:244)
2024-06-23T14:05:33.325063174Z at org.jruby.RubyObject.toString(RubyObject.java:253)
2024-06-23T14:05:33.327739168Z at java.base/java.lang.String.valueOf(String.java:2951)
2024-06-23T14:05:33.328917261Z at org.logstash.log.StructuredMessage.getFormattedMessage(StructuredMessage.java:86)
2024-06-23T14:05:33.330547879Z at org.apache.logging.log4j.core.pattern.MessagePatternConverter$SimpleMessagePatternConverter.format(MessagePatternConverter.java:122)
2024-06-23T14:05:33.332365482Z at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:44)
2024-06-23T14:05:33.336098129Z at org.apache.logging.log4j.core.pattern.RegexReplacementConverter.format(RegexReplacementConverter.java:93)
2024-06-23T14:05:33.336117919Z at org.apache.logging.log4j.core.layout.PatternLayout$NoFormatPatternSerializer.toSerializable(PatternLayout.java:343)
2024-06-23T14:05:33.337684956Z at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:241)
2024-06-23T14:05:33.411091768Z at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:226)
2024-06-23T14:05:33.413063083Z at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:60)
2024-06-23T14:05:33.414969877Z at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197)
2024-06-23T14:05:33.416925259Z at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190)
2024-06-23T14:05:33.418683689Z at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181)
2024-06-23T14:05:33.420515564Z at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
2024-06-23T14:05:33.422204147Z at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
2024-06-23T14:05:33.423992187Z at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
2024-06-23T14:05:33.425645914Z at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
2024-06-23T14:05:33.427480396Z at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:542)
2024-06-23T14:05:33.436376084Z at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:500)
2024-06-23T14:05:33.436414877Z at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483)
2024-06-23T14:05:33.436419373Z at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:533)
2024-06-23T14:05:33.436422705Z at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)
2024-06-23T14:05:33.436425879Z at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483)
2024-06-23T14:05:33.439150791Z at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
2024-06-23T14:05:33.511955407Z at org.apache.logging.log4j.core.config.DefaultReliabilityStrategy.log(DefaultReliabilityStrategy.java:63)
2024-06-23T14:05:33.519783400Z at org.apache.logging.log4j.core.Logger.log(Logger.java:161)
2024-06-23T14:05:33.519811886Z at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2205)
2024-06-23T14:05:33.519816565Z at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2159)
2024-06-23T14:05:33.519819943Z at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2142)
2024-06-23T14:05:33.520195261Z at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2034)
2024-06-23T14:05:33.525889413Z at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1899)
2024-06-23T14:05:33.525930387Z at org.apache.logging.log4j.spi.AbstractLogger.error(AbstractLogger.java:866)
2024-06-23T14:05:33.525934801Z at org.logstash.log.LoggerExt.rubyError(LoggerExt.java:127)
2024-06-23T14:05:33.527144873Z at org.logstash.log.LoggerExt$INVOKER$i$0$1$rubyError.call(LoggerExt$INVOKER$i$0$1$rubyError.gen)
2024-06-23T14:05:33.528865930Z at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:829)
2024-06-23T14:05:33.530558746Z at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:228)
2024-06-23T14:05:33.532210983Z at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:476)
2024-06-23T14:05:33.533791719Z at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:293)
2024-06-23T14:05:33.535588594Z at org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:328)
2024-06-23T14:05:33.537164319Z at org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:66)
2024-06-23T14:05:33.538819672Z at org.jruby.ir.interpreter.Interpreter.INTERPRET_BLOCK(Interpreter.java:116)
2024-06-23T14:05:33.540555320Z at org.jruby.runtime.MixedModeIRBlockBody.commonYieldPath(MixedModeIRBlockBody.java:136)
2024-06-23T14:05:33.542198243Z at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:66)
2024-06-23T14:05:33.543955665Z at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:58)
2024-06-23T14:05:33.545565869Z at org.jruby.runtime.Block.call(Block.java:144)
2024-06-23T14:05:33.611348778Z at org.jruby.RubyProc.call(RubyProc.java:352)
2024-06-23T14:05:33.613295452Z at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:111)
2024-06-23T14:05:33.615955314Z at java.base/java.lang.Thread.run(Thread.java:829)
2024-06-23T14:05:33.616875885Z
2024-06-23T14:05:33.618679944Z warning: thread "Converge PipelineAction::Create<opensearch>" terminated with exception (report_on_exception is true):
2024-06-23T14:05:33.620404065Z java.lang.ArrayIndexOutOfBoundsException: Index -2 out of bounds for length 80
2024-06-23T14:05:33.622025372Z at org.jruby.runtime.ThreadContext.popFrameReal(ThreadContext.java:570)
2024-06-23T14:05:33.623683498Z at org.jruby.runtime.ThreadContext.postYield(ThreadContext.java:1171)
2024-06-23T14:05:33.625334046Z at org.jruby.runtime.IRBlockBody.postYield(IRBlockBody.java:188)
2024-06-23T14:05:33.627007415Z at org.jruby.runtime.MixedModeIRBlockBody.commonYieldPath(MixedModeIRBlockBody.java:139)
2024-06-23T14:05:33.628655592Z at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:66)
2024-06-23T14:05:33.630292494Z at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:58)
2024-06-23T14:05:33.632214909Z at org.jruby.runtime.Block.call(Block.java:144)
2024-06-23T14:05:33.633802311Z at org.jruby.RubyProc.call(RubyProc.java:352)
2024-06-23T14:05:33.635515422Z at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:111)
2024-06-23T14:05:33.637167982Z at java.base/java.lang.Thread.run(Thread.java:829)
[logstash.runner] An unexpected error occurred! {:error=>#<Java::JavaLang::ArrayIndexOutOfBoundsException: Index -2 out of bounds for length 80>, :backtrace=>['org.jruby.runtime.ThreadContext.popFrameReal(ThreadContext.java:570)', 'org.jruby.runtime.ThreadContext.postYield(ThreadContext.java:1171)', 'org.jruby.runtime.IRBlockBody.postYield(IRBlockBody.java:188)', 'org.jruby.runtime.MixedModeIRBlockBody.commonYieldPath(MixedModeIRBlockBody.java:139)', 'org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:66)', 'org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:58)', 'org.jruby.runtime.Block.call(Block.java:144)', 'org.jruby.RubyProc.call(RubyProc.java:352)', 'org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:111)', 'java.base/java.lang.Thread.run(Thread.java:829)']}
[logstash.javapipeline] Waiting for input plugin to close {:pipeline_id=>'opensearch', :thread=>'#<Thread:0x5d34949c /opt/logstash/logstash-core/lib/logstash/java_pipeline.rb:134 run>'}
[logstash.outputs.opensearch] Error while performing resurrection {:error_message=>'Connection pool shut down', :class=>'Manticore::ClientStoppedException', :backtrace=>['/opt/logstash/vendor/bundle/jruby/3.1.0/gems/manticore-0.9.1-java/lib/manticore/response.rb:36:in `block in initialize'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/manticore-0.9.1-java/lib/manticore/response.rb:79:in `call'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/manticore_adapter.rb:175:in `perform_request'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/pool.rb:272:in `perform_request_to_url'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/pool.rb:226:in `health_check_request'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/pool.rb:233:in `block in healthcheck!'', 'org/jruby/RubyHash.java:1601:in `each'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/pool.rb:231:in `healthcheck!'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/pool.rb:219:in `block in start_resurrectionist'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/pool.rb:141:in `until_stopped'', '/opt/logstash/vendor/bundle/jruby/3.1.0/gems/logstash-output-opensearch-2.0.2.E001-java/lib/logstash/outputs/opensearch/http_client/pool.rb:218:in `block in start_resurrectionist'']
[logstash.javapipeline] Pipeline Java execution initialization time {'seconds'=>2.82}
[logstash.javapipeline] Pipeline worker error, the pipeline will be stopped {:pipeline_id=>'opensearch', :error=>'', :exception=>Java::OrgJrubyExceptions::ThreadKill, :backtrace=>[], :thread=>'#<Thread:0x5d34949c /opt/logstash/logstash-core/lib/logstash/java_pipeline.rb:134 sleep>'}
[logstash.agent] An exception happened when converging configuration {:exception=>Java::JavaLang::ArrayIndexOutOfBoundsException, :message=>'Index -2 out of bounds for length 80'}