Java process keeps restarting on Elasticsearch input

[ThomasArdal]

I'm experiencing problems with Logstash 1.5.6 on Java JRE 1.8.0_40 when trying to set up a simple Elasticsearch input to stdout output. My configuration looks like this:

input {
    elasticsearch {
        hosts => "http://myelasticsearchhost:1025/"
        index => "logstash-*"
        size => 100
        scroll => "5m"
        docinfo => true
    }
}
output {
    stdout { codec => json }
}

I've installed Logstash as a Windows service as described here.

When starting the service, the Java process uses a lot of CPU for about 10 seconds. This is normal (?) and also happens if I setup a simple stdin -> stdout. After 10 seconds, the Java process is shut down and a new one is started. The new process uses a lot of CPU, runs for 10 seconds and same thing happens.

I'm not sure if this is normal behavior with the Elasticsearch input (guess not?). If I run the simple stdin -> stdout test as a service, the same Java process is kept running.

I've tried running jstack on the Java process pid, which gives the following result:

2016-03-18 11:32:25
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.40-b25 mixed mode):

"jnr.ffi.util.ref.internal.Finalizer" #15 daemon prio=10 os_prio=2 tid=0x0000000018ac0800 nid=0x2684 in Object.wait() [0x000000001a3ff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d54b1490> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(Unknown Source)
        - locked <0x00000000d54b1490> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(Unknown Source)
        at jnr.ffi.util.ref.internal.Finalizer.run(Finalizer.java:128)

"Ruby-0-JIT-1" #12 daemon prio=1 os_prio=-2 tid=0x00000000185a1000 nid=0x23dc runnable [0x0000000019edf000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ClassLoader.defineClass1(Native Method)
        at java.lang.ClassLoader.defineClass(Unknown Source)
        at org.jruby.util.ClassCache$OneShotClassLoader.defineClass(ClassCache.java:74)
        at org.jruby.util.ClassCache.defineClass(ClassCache.java:117)
        at org.jruby.util.ClassCache.cacheClassByKey(ClassCache.java:98)
        at org.jruby.compiler.JITCompiler$JITTask.run(JITCompiler.java:256)
        at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
        at java.util.concurrent.FutureTask.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)

"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x000000001571e800 nid=0x2054 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #9 daemon prio=9 os_prio=2 tid=0x000000001568f000 nid=0x1bb8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #8 daemon prio=9 os_prio=2 tid=0x0000000015683000 nid=0x19c0 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=2 tid=0x0000000015681800 nid=0x1de8 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" #6 daemon prio=5 os_prio=2 tid=0x000000001567d000 nid=0x1d64 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #5 daemon prio=9 os_prio=2 tid=0x000000001494e000 nid=0x684runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (Concurrent GC)" #4 daemon prio=9 os_prio=0 tid=0x000000001494c800 nid=0x18c8 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000001493d800 nid=0x4d8 in Object.wait() [0x000000001564e000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d53f5178> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(Unknown Source)
        - locked <0x00000000d53f5178> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(Unknown Source)
        at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000014936800 nid=0x478 in Object.wait() [0x000000001544f000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000d4d39700> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Unknown Source)
        at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
        - locked <0x00000000d4d39700> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0x0000000001182800 nid=0x2430 runnable [0x00000000014aa000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.Class.getDeclaredConstructors0(Native Method)
        at java.lang.Class.privateGetDeclaredConstructors(Unknown Source)
        at java.lang.Class.getConstructor0(Unknown Source)
        at java.lang.Class.getConstructor(Unknown Source)
        at org.jruby.internal.runtime.methods.InvocationMethodFactory.getAnnotatedMethod(InvocationMethodFactory.java:896)
        at org.jruby.RubyModule.defineAnnotatedMethod(RubyModule.java:839)
        at org.jruby.RubyModule.defineAnnotatedMethod(RubyModule.java:802)
        at org.jruby.anno.TypePopulator$DefaultTypePopulator.populate(TypePopulator.java:96)
        at org.jruby.RubyModule.defineAnnotatedMethodsIndividually(RubyModule.java:796)
        at org.jruby.RubyModule.defineAnnotatedMethods(RubyModule.java:667)
        at org.jruby.ext.openssl.ASN1.createASN1(ASN1.java:701)
        at org.jruby.ext.openssl.OpenSSL.createOpenSSL(OpenSSL.java:80)
        at org.jruby.ext.openssl.OpenSSL.load(OpenSSL.java:51)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(JavaMethod.java:451)
        at org.jruby.javasupport.JavaMethod.invokeStaticDirect(JavaMethod.java:363)
        at org.jruby.java.invokers.StaticMethodInvoker.call(StaticMethodInvoker.java:50)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
        at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
        at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
        at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
        at org.jruby.ast.RootNode.interpret(RootNode.java:129)
        at org.jruby.evaluator.ASTInterpreter.INTERPRET_ROOT(ASTInterpreter.java:121)
        at org.jruby.Ruby.runInterpreter(Ruby.java:884)
        at org.jruby.Ruby.loadFile(Ruby.java:2833)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.loadScript(LibrarySearcher.java:264)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.load(LibrarySearcher.java:252)
        at org.jruby.runtime.load.LibrarySearcher$FoundLibrary.load(LibrarySearcher.java:51)
        at org.jruby.runtime.load.LoadService.tryLoadingLibraryOrScript(LoadService.java:892)
        at org.jruby.runtime.load.LoadService.requireCommon(LoadService.java:465)
        at org.jruby.runtime.load.LoadService.require(LoadService.java:414)
        at org.jruby.RubyKernel.requireCommon(RubyKernel.java:1047)
        at org.jruby.RubyKernel.require19(RubyKernel.java:1040)
        at org.jruby.RubyKernel$INVOKER$s$1$0$require19.call(RubyKernel$INVOKER$s$1$0$require19.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:350)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
        at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
        at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
        at org.jruby.ast.RootNode.interpret(RootNode.java:129)
        at org.jruby.evaluator.ASTInterpreter.INTERPRET_ROOT(ASTInterpreter.java:121)
        at org.jruby.Ruby.runInterpreter(Ruby.java:884)
        at org.jruby.Ruby.loadFile(Ruby.java:2833)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.loadScript(LibrarySearcher.java:264)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.load(LibrarySearcher.java:252)
        at org.jruby.runtime.load.LibrarySearcher$FoundLibrary.load(LibrarySearcher.java:51)
        at org.jruby.runtime.load.LoadService.tryLoadingLibraryOrScript(LoadService.java:892)
        at org.jruby.runtime.load.LoadService.requireCommon(LoadService.java:465)
        at org.jruby.runtime.load.LoadService.require(LoadService.java:414)
        at org.jruby.RubyKernel.requireCommon(RubyKernel.java:1047)
        at org.jruby.RubyKernel.require19(RubyKernel.java:1040)
        at org.jruby.RubyKernel$INVOKER$s$1$0$require19.call(RubyKernel$INVOKER$s$1$0$require19.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:350)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
        at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
        at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
        at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
        at org.jruby.ast.RootNode.interpret(RootNode.java:129)
        at org.jruby.evaluator.ASTInterpreter.INTERPRET_ROOT(ASTInterpreter.java:121)
        at org.jruby.Ruby.runInterpreter(Ruby.java:884)
        at org.jruby.Ruby.loadFile(Ruby.java:2833)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.loadScript(LibrarySearcher.java:264)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.load(LibrarySearcher.java:252)
        at org.jruby.runtime.load.LibrarySearcher$FoundLibrary.load(LibrarySearcher.java:51)
        at org.jruby.runtime.load.LoadService.tryLoadingLibraryOrScript(LoadService.java:892)
        at org.jruby.runtime.load.LoadService.requireCommon(LoadService.java:465)
        at org.jruby.runtime.load.LoadService.require(LoadService.java:414)
        at org.jruby.RubyKernel.requireCommon(RubyKernel.java:1047)
        at org.jruby.RubyKernel.require19(RubyKernel.java:1040)
        at org.jruby.RubyKernel$INVOKER$s$1$0$require19.call(RubyKernel$INVOKER$s$1$0$require19.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:350)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
        at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
        at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
        at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
        at org.jruby.ast.RootNode.interpret(RootNode.java:129)
        at org.jruby.evaluator.ASTInterpreter.INTERPRET_ROOT(ASTInterpreter.java:121)
        at org.jruby.Ruby.runInterpreter(Ruby.java:884)
        at org.jruby.Ruby.loadFile(Ruby.java:2833)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.loadScript(LibrarySearcher.java:264)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.load(LibrarySearcher.java:252)
        at org.jruby.runtime.load.LibrarySearcher$FoundLibrary.load(LibrarySearcher.java:51)
        at org.jruby.runtime.load.LoadService.tryLoadingLibraryOrScript(LoadService.java:892)
        at org.jruby.runtime.load.LoadService.requireCommon(LoadService.java:465)
        at org.jruby.runtime.load.LoadService.require(LoadService.java:414)
        at org.jruby.RubyKernel.requireCommon(RubyKernel.java:1047)
        at org.jruby.RubyKernel.require19(RubyKernel.java:1040)
        at org.jruby.RubyKernel$INVOKER$s$1$0$require19.call(RubyKernel$INVOKER$s$1$0$require19.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:350)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
        at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
        at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
        at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
        at org.jruby.ast.RootNode.interpret(RootNode.java:129)
        at org.jruby.evaluator.ASTInterpreter.INTERPRET_ROOT(ASTInterpreter.java:121)
        at org.jruby.Ruby.runInterpreter(Ruby.java:884)
        at org.jruby.Ruby.loadFile(Ruby.java:2833)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.loadScript(LibrarySearcher.java:264)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.load(LibrarySearcher.java:252)
        at org.jruby.runtime.load.LibrarySearcher$FoundLibrary.load(LibrarySearcher.java:51)
        at org.jruby.runtime.load.LoadService.tryLoadingLibraryOrScript(LoadService.java:892)
        at org.jruby.runtime.load.LoadService.requireCommon(LoadService.java:465)
        at org.jruby.runtime.load.LoadService.require(LoadService.java:414)
        at org.jruby.RubyKernel.requireCommon(RubyKernel.java:1047)
        at org.jruby.RubyKernel.require19(RubyKernel.java:1040)
        at org.jruby.RubyKernel$INVOKER$s$1$0$require19.call(RubyKernel$INVOKER$s$1$0$require19.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:350)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
        at org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
        at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
        at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
        at org.jruby.ast.RootNode.interpret(RootNode.java:129)
        at org.jruby.evaluator.ASTInterpreter.INTERPRET_ROOT(ASTInterpreter.java:121)
        at org.jruby.Ruby.runInterpreter(Ruby.java:884)
        at org.jruby.Ruby.loadFile(Ruby.java:2833)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.loadScript(LibrarySearcher.java:264)
        at org.jruby.runtime.load.LibrarySearcher$ResourceLibrary.load(LibrarySearcher.java:252)
        at org.jruby.runtime.load.LibrarySearcher$FoundLibrary.load(LibrarySearcher.java:51)
        at org.jruby.runtime.load.LoadService.tryLoadingLibraryOrScript(LoadService.java:892)
        at org.jruby.runtime.load.LoadService.requireCommon(LoadService.java:465)
        at org.jruby.runtime.load.LoadService.require(LoadService.java:414)
        at org.jruby.RubyKernel.requireCommon(RubyKernel.java:1047)
        at org.jruby.RubyKernel.require19(RubyKernel.java:1040)
        at org.jruby.RubyKernel$INVOKER$s$1$0$require19.call(RubyKernel$INVOKER$s$1$0$require19.gen)
        at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:350)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:61)
        at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
        at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
        at d_3a_.Program_20_Files_20_28_x86_29_.Logstash.logstash_minus_1_dot_5_dot_6.lib.bootstrap.environment.__file__(d:\Program Files (x86)\Logstash\logstash-1.5.6\lib\bootstrap\environment.rb:48)
        at d_3a_.Program_20_Files_20_28_x86_29_.Logstash.logstash_minus_1_dot_5_dot_6.lib.bootstrap.environment.load(d:\Program Files (x86)\Logstash\logstash-1.5.6\lib\bootstrap\environment.rb)
        at org.jruby.Ruby.runScript(Ruby.java:857)
        at org.jruby.Ruby.runScript(Ruby.java:850)
        at org.jruby.Ruby.runNormally(Ruby.java:729)
        at org.jruby.Ruby.runFromMain(Ruby.java:578)
        at org.jruby.Main.doRunFromMain(Main.java:393)
        at org.jruby.Main.internalRun(Main.java:288)
        at org.jruby.Main.run(Main.java:217)
        at org.jruby.Main.main(Main.java:197)

"VM Thread" os_prio=2 tid=0x000000001492e800 nid=0x2a4c runnable

"Gang worker#0 (Parallel GC Threads)" os_prio=2 tid=0x0000000001192800 nid=0x20a4 runnable

"Gang worker#1 (Parallel GC Threads)" os_prio=2 tid=0x0000000001194000 nid=0x10d8 runnable

"Gang worker#2 (Parallel GC Threads)" os_prio=2 tid=0x0000000001196000 nid=0xac8 runnable

"Gang worker#3 (Parallel GC Threads)" os_prio=2 tid=0x0000000001197800 nid=0x10e8 runnable

"Concurrent Mark-Sweep GC Thread" os_prio=2 tid=0x00000000011db000 nid=0x2978 runnable

"VM Periodic Task Thread" os_prio=2 tid=0x0000000015721000 nid=0x22dc waiting on condition

JNI global references: 46

I also tried setting LS_HEAP_SIZE to 4g, thinking it could be a memory issue, but the Java process never uses more than 200 mb.

[jordansissel]

The Elasticsearch input will only do one scan query. Once that completes, that input will terminate. If that is the only input, then Logstash will see that all inputs have completed as a signal to shutdown. If you have Windows services automatically restarting Logstash, then this could be why it keeps restarting?

[ThomasArdal]

@jordansissel The Windows service isn't set to restart. But the NSSM process keeps running and I guess there's something in that setup that restarts the Java process once it closes down. I don't think it is NSSM, because that one is configured to start logstash.bat.

[jordansissel]

Hmm. @ThomasArdal Can you run logstash.bat manually from powershell or a command prompt? I wonder if it's starting up and then failing due to a configuration problem.

[ThomasArdal]

@jordansissel When running from command prompt, it's closing down when everything is outputted to stdout. No configuration problem, but it tells me that it's something when running as a service using nssm then.

I'm thinking about scheduling it rather than running it as a service. I don't want it to start new Java processes every 10 seconds anyway.

I think this issue can be closed. It's not a bug 😄

[ThomasArdal]

Thank you very much for your quick reply!

[jordansissel]

@ThomasArdal ok cool. I hope you get things resolved :) If not, pop on into the discuss forums at https://discuss.elastic.co/ and start a new Logstash topic.