Out of Memory right after staring logstash

[halolk (Ke)]

Hi guys,

My company is running a logstash instance to ingest logs from customer by several input conf files, it crashed after about 1 day due to OOM, and then every time I try to start it again, it crash by OOM immediately:

WARNING: Could not find logstash.yml which is typically located in $LS_HOME/config or /etc/logstash. You can specify the path using --path.settings. Continuing using the defaults
Could not find log4j2 configuration at path /usr/share/logstash/config/log4j2.properties. Using default config which logs errors to the console
[WARN ] 2019-05-03 01:30:29.110 [LogStash::Runner] multilocal - Ignoring the 'pipelines.yml' file because modules or command line options are specified
[INFO ] 2019-05-03 01:30:29.645 [LogStash::Runner] runner - Starting Logstash {"logstash.version"=>"6.3.2"}
java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid29256.hprof ...
Heap dump file created [142110250 bytes in 0.812 secs]
[ERROR] 2019-05-03 01:30:31.433 [LogStash::Runner] Logstash - java.lang.OutOfMemoryError: Java heap space

This is strange because I have the jvm setting as -Xms1g and -Xmx1g, but the memory dump is only 142 MB, and after I increase java heap to 2g, it's still the same. Then I increased java heap to 4g, it didn't get OOM but throwing the following error messages all the time:

[ERROR] 2019-05-02 01:09:35.262 [Ruby-0-Thread-1: /usr/share/logstash/lib/bootstrap/environment.rb:6] sourceloader - Could not fetch all the sources {:exception=>Java::JavaLang::NegativeArraySizeException, :message=>"", :backtrace=>["org.jruby.util.ByteList.ensure(ByteList.java:341)", "org.jruby.RubyString.modify(RubyString.java:950)", "org.jruby.RubyString.modifyExpand(RubyString.java:960)", "org.jruby.util.io.EncodingUtils.setStrBuf(EncodingUtils.java:1117)", "org.jruby.util.io.OpenFile.fread(OpenFile.java:1755)", "org.jruby.util.io.OpenFile.readAll(OpenFile.java:1669)", "org.jruby.RubyIO.read(RubyIO.java:3009)", "org.jruby.RubyIO.read(RubyIO.java:2993)", "org.jruby.RubyIO.read19(RubyIO.java:3607)", "usr.share.logstash.logstash_minus_core.lib.logstash.config.source.local.RUBY$block$read$1(/usr/share/logstash/logstash-core/lib/logstash/config/source/local.rb:73)", "org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)", "org.jruby.runtime.BlockBody.yield(BlockBody.java:114)", "org.jruby.runtime.Block.yield(Block.java:165)", "org.jruby.RubyArray.each(RubyArray.java:1734)", "usr.share.logstash.logstash_minus_core.lib.logstash.config.source.local.RUBY$method$read$0(/usr/share/logstash/logstash-core/lib/logstash/config/source/local.rb:63)", "usr.share.logstash.logstash_minus_core.lib.logstash.config.source.local.RUBY$method$read$0(/usr/share/logstash/logstash-core/lib/logstash/config/source/local.rb:96)", "usr.share.logstash.logstash_minus_core.lib.logstash.config.source.local.RUBY$method$local_pipeline_configs$0(/usr/share/logstash/logstash-core/lib/logstash/config/source/local.rb:192)", "usr.share.logstash.logstash_minus_core.lib.logstash.config.source.local.RUBY$method$pipeline_configs$0(/usr/share/logstash/logstash-core/lib/logstash/config/source/local.rb:163)", "usr.share.logstash.logstash_minus_core.lib.logstash.config.source_loader.RUBY$block$fetch$3(/usr/share/logstash/logstash-core/lib/logstash/config/source_loader.rb:62)", "org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)", "org.jruby.runtime.BlockBody.yield(BlockBody.java:114)", "org.jruby.runtime.Block.yield(Block.java:165)", "org.jruby.RubyArray.collect(RubyArray.java:2472)", "org.jruby.RubyArray.collect19(RubyArray.java:2481)", "usr.share.logstash.logstash_minus_core.lib.logstash.config.source_loader.RUBY$method$fetch$0(/usr/share/logstash/logstash-core/lib/logstash/config/source_loader.rb:61)", "usr.share.logstash.logstash_minus_core.lib.logstash.agent.RUBY$method$converge_state_and_update$0(/usr/share/logstash/logstash-core/lib/logstash/agent.rb:138)", "usr.share.logstash.logstash_minus_core.lib.logstash.agent.RUBY$block$execute$1(/usr/share/logstash/logstash-core/lib/logstash/agent.rb:106)", "org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)", "org.jruby.runtime.Block.call(Block.java:124)", "org.jruby.RubyProc.call(RubyProc.java:289)", "org.jruby.RubyProc.call19(RubyProc.java:273)", "usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.stud_minus_0_dot_0_dot_23.lib.stud.interval.RUBY$method$interval$0(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/stud-0.0.23/lib/stud/interval.rb:18)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)", "usr.share.logstash.logstash_minus_core.lib.logstash.agent.RUBY$method$execute$0(/usr/share/logstash/logstash-core/lib/logstash/agent.rb:95)", "usr.share.logstash.logstash_minus_core.lib.logstash.agent.RUBY$method$execute$0$VARARGS(/usr/share/logstash/logstash-core/lib/logstash/agent.rb)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:77)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:93)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)", "usr.share.logstash.logstash_minus_core.lib.logstash.runner.RUBY$block$execute$5(/usr/share/logstash/logstash-core/lib/logstash/runner.rb:363)", "org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)", "org.jruby.runtime.Block.call(Block.java:124)", "org.jruby.RubyProc.call(RubyProc.java:289)", "org.jruby.RubyProc.call19(RubyProc.java:273), "org.jruby.RubyProc$INVOKER$i$0$0$cal
l19.call(RubyProc$INVOKER$i$0$0$call19.gen)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:145)", "usr.share.logstash.vendor.bundle.jruby.$2_dot_3_dot_0.gems.stud_minus_0_dot_0_dot_23.lib.stud.task.RUBY$block$initialize$1(/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/stud-0.0.23/lib/stud/task.rb:24)", "org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:145)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:71)", "org.jruby.runtime.Block.call(Block.java:124)", "org.jruby.RubyProc.call(RubyProc.java:289)", "org.jruby.RubyProc.call(RubyProc.java:246)", "org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:104)", "java.lang.Thread.run(Thread.java:748)"]}

We are running logstash by:
sudo nohup /usr/share/logstash/bin/logstash -f ./logstash/conf/ -w 3 --config.reload.automatic > /var/log/logstash/logstash1.log &
There are 4 conf files in the ./logstash/conf/ directory
And logstash version is 6.3.2

I did some search on web but still cannot figure out what happened. Also looked at the 142M memory dump through VisualVM, didn't find any dominating object, all objects look fine. Please help and thanks in advance!

[warkolm (Mark Walkom)]

Please format your code/logs/config using the </> button, or markdown style back ticks. It helps to make things easy to read which helps us help you

Can you share your config?

[Badger]

At the risk of running all the way off the end of the plank and into the ocean...

With a 1 GB or 2 GB heap you run out of heap when you only have 142 MB of heap allocated. That suggests you are trying to allocate an object that is over 1.9 GB.

With a 4 GB heap you get a negative array size exception, which suggests you are trying to allocate an array with a size greater than 2 GB.

Since the memory allocation fails with a 2 GB heap the non-allocated object will not show up in the heap dump.

If you enable "--log.level debug" you should get this debug message immediately before you get the failure. Perhaps that will help... Is there a heap dump in the conf directory?

[halolk (Ke)]

Thanks Mark! I'm new to this community and is not aware about this rule, next time will format my post properly

We ran multiple config files so I don't know which one is causing the problem, and now the problem is fixed by reinstall logstash (the problem occurred on production environment so we finally decided to fix it asap), so won't share it for now.

BTW I usually feel it's hard to debug problems happened in logstash, is there any general guideline to debug it if some problem happens? Thanks!

[halolk (Ke)]

Hi Badger, thank you! Although the problem is fixed by reinstall logstash (it occurred on production environment so we finally decided to fix it by any way. And unfortunately the heap dump is also gone after that), your response is still enlightening. Do you know in which case logstash can try to allocate a huge array?
It's possible that some binary data can corrupt log file and cause one line to have huge size, I have seen this in spark logs. Maybe that's one possible cause of this error? (BTW We were ingesting logs from network and user devices, not spark, I have never seen huge log from them. And the log files sizes look reasonable to me)

[Badger]

My guess is that you were examining the configuration, and consequently started logstash from path.config. That could result in logstash dropping a heap dump into path.config. By default logstash will concatenate all the files in path.config into a configuration. If one of them is a heap dump then it would likely run out of memory.

[halolk (Ke)]

Ah thanks a lot! I think it makes sense. I know logstash will concatenate all files in conf directory but
thought it will only look for text files with *.conf name.