Logstash: Error in netflow module org.jruby.gen.RubyObject4 cannot be cast to org.jruby.RubyFixnum

[tiempososcuros]

Hi. I am having the following errors with the netflow module in Logstash 7.4.0 in CentOS 7.6.1810. Could you help me solve the error?
Thanks

Configuration File:
logstash.yml.txt

Logs:
Oct 08 15:17:13 nebula.informaxster.tk logstash[9207]: [2019-10-08T15:17:13,081][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600} Oct 08 15:21:01 nebula.informaxster.tk logstash[9207]: [2019-10-08T15:21:01,601][ERROR][logstash.inputs.udp ][module-netflow] Exception in inputworker {"exception"=>java.lang.ClassCastException: org.jruby.gen.RubyObject4 cannot be cast to org.jruby.RubyFixnum, "backtrace"=>["org.jruby.runtime.invokedynamic.MathLinker.fixnum_op_equal(MathLinker.java:237)", "java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:627)", "org.jruby.runtime.invokedynamic.MathLinker.fixnumOperator(MathLinker.java:171)", "usr.share.logstash.vendor.bundle.jruby.$2_dot_5_dot_0.gems.logstash_minus_codec_minus_netflow_minus_4_dot_2_dot_1.lib.logstash.codecs.netflow.RUBY$method$decode$0(/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-codec-netflow-4.2.1/lib/logstash/codecs/netflow.rb:85)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:91)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:114)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:156)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:386)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:184)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:191)", "org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:337)", "org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)", "org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:92)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:204)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:191)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:208)", "usr.share.logstash.vendor.bundle.jruby.$2_dot_5_dot_0.gems.logstash_minus_input_minus_udp_minus_3_dot_3_dot_4.lib.logstash.inputs.udp.RUBY$block$run$2(/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-input-udp-3.3.4/lib/logstash/inputs/udp.rb:63)", "org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:136)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:77)", "org.jruby.runtime.Block.call(Block.java:129)", "org.jruby.RubyProc.call(RubyProc.java:295)", "org.jruby.RubyProc.call(RubyProc.java:274)", "org.jruby.RubyProc.call(RubyProc.java:270)", "org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)", "java.lang.Thread.run(Thread.java:748)"]}

[fredbcode]

Yes, same issue here with 7.4.0 and cluster elastic 7.4.0
Ubuntu 18.04

[fredbcode]

Although there are a lot of "[ERROR][logstash.inputs.udp ][module-netflow] Exception in inputworker" in syslog indexing seems to work, maybe not at 100%

[dpedestrian]

I get a similar error and other problems using udp input module with netflow codec in logstash 7.4. I however also get nullpointer exception. I was forced to downgrade to 7.3.2 in order to retain function. The elastiflow project is having issues with this version as well it seems. With that, I looked into netflow on logstash a bit and found that elastic may be deprecating the udp input module/netflow codec via logstash and implementing the input via filebeat module instead. This will require a lot of rework for those already sunk into using logstash method, but it is at least "standard" field definitions.

Edit: It looks like this is the "module" not he "codec" for input on logstash. My mistake.

Elastiflow:
https://github.com/robcowart/elastiflow/issues/427

Logstash deprecating netflow:
https://github.com/elastic/logstash/issues/11104

[colinsurprenant]

This seems to be a logstash core regression introduced in 7.4; it is confirmed that this error, although originating from the netflow codec, occurs only in 7.4 but not in 7.3 using the same netflow codec version (reported for netflow codec 4.2.1).

Does anyone here have a way to reproduce the problem in a systematic way?

[kares]

seems like it might not be the same cause as https://github.com/jruby/jruby/issues/5910
as a "work-around" things should work when indy is disabled (under JRuby 9.2.8.0),
will be looking at this a bit more but in the meantime here's a reproducer:

require 'logstash/codecs/netflow/util'

threads = []
100.times do |i|
  threads << Thread.start do
    #if i % 2 == 1
      payload = "\u0000\u0001"
      header = Header.read(payload)
      header.version == 5
    #end
  end
end

threads.each &:join

... with 100 threads (do not forget -Xcompile.invokedynamic) I usually get 3-4 failures

[colinsurprenant]

👀

[colinsurprenant]

Thanks @kares! I confirm the reproduction; it triggers with -Xcompile.invokedynamic on 9.2.8.0 and not on 9.2.7.0.

[colinsurprenant]

I just tried with JRuby master (ruby 9.2.9.0-SNAPSHOT) with the fix jruby/jruby#5919 for jruby/jruby#5910 and the problem still reproduces.

As you mentioned @kares, the bindata gem seems to be doing a lot which might not be thread safe WRT to the class definition etc - this is something we might want to look into but OTOH this problem did not surface in 9.2.7.0 - WDYT?

[kares]

yeah, I thought it to be some kind of thread-safety issue by looking at Bindata's class internals.
but than the Header instance is not being shared between threads so I am leaning towards JRuby.
I know some pieces that changed in regard to (fixnum) indy in 9.2.8.0 ... will look into that - hopefully we can reduce the reproducer further until the cause is obvious :)

[kares]

the issue's cause should be fixed on JRuby master (9.2.9.0-SNAPSHOT) ...
not sure how to do a full-blown test using LS but the reproducer above is working.

[jsvd]

I tested with the latest snapshot by configuring versions.yml:

---
logstash: 8.0.0
logstash-core: 8.0.0
logstash-core-plugin-api: 2.1.16

jruby:
  version: 9.2.8.0
  sha1: 5b0b73b3d696afaeac92e6f8879dedcc63ac39d8

jruby-runtime-override:
  url: https://oss.sonatype.org/content/repositories/snapshots/org/jruby/jruby-dist/9.2.9.0-SNAPSHOT/jruby-dist-9.2.9.0-20191024.130518-80-bin.tar.gz
  version: 9.2.9.0-SNAPSHOT
  sha1: IGNORE

jrjackson: 0.4.10
jackson: 2.9.9
jackson-databind: 2.9.9.3

/tmp/logstash (git)-[master] % ./gradlew clean installDefaultGems
...
/tmp/logstash (git)-[master] % ./vendor/jruby/bin/jruby -v
jruby 9.2.9.0-SNAPSHOT (2.5.7) 2019-10-24 dc25e3f OpenJDK 64-Bit Server VM 11.0.1+13 on 11.0.1+13 +jit [darwin-x86_64]

the dc25e3f must be https://github.com/jruby/jruby/commit/dc25e3f71df49418e25dea800e7031400091e05b

Then I used a docker image that generates netflow v5 traffic:
docker run -it --rm networkstatic/nflow-generator -t 192.168.86.25 -p 9001

And started logstash:

/tmp/logstash (git)-[master] % bin/logstash  -e "input { udp { port => 9001 codec => netflow } }" --log.level=error
OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.headius.backport9.modules.Modules (file:/private/tmp/logstash/logstash-core/lib/jars/jruby-complete-9.2.8.0.jar) to field java.io.FileDescriptor.fd
WARNING: Please consider reporting this to the maintainers of com.headius.backport9.modules.Modules
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
Thread.exclusive is deprecated, use Thread::Mutex
Sending Logstash logs to /tmp/logstash/logs which is now configured via log4j2.properties
[2019-10-24T16:25:43,015][ERROR][logstash.inputs.udp      ][main] Exception in inputworker {"exception"=>java.lang.ClassCastException: class org.jruby.gen.RubyObject4 cannot be cast to class org.jruby.RubyFixnum (org.jruby.gen.RubyObject4 is in unnamed module of loader org.jruby.util.OneShotClassLoader @5835e24a; org.jruby.RubyFixnum is in unnamed module of loader 'app'), "backtrace"=>["org.jruby.runtime.invokedynamic.MathLinker.fixnum_op_equal(MathLinker.java:237)", "java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:710)", "org.jruby.runtime.invokedynamic.MathLinker.fixnumOperator(MathLinker.java:171)", "private.tmp.logstash.vendor.bundle.jruby.$2_dot_5_dot_0.gems.logstash_minus_codec_minus_netflow_minus_4_dot_2_dot_1.lib.logstash.codecs.netflow.RUBY$method$decode$0(/private/tmp/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-codec-netflow-4.2.1/lib/logstash/codecs/netflow.rb:85)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:91)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:90)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:177)", "private.tmp.logstash.logstash_minus_core.lib.logstash.codecs.delegator.RUBY$block$decode$1(/private/tmp/logstash/logstash-core/lib/logstash/codecs/delegator.rb:45)", "org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:136)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:77)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:51)", "org.jruby.runtime.Block.call(Block.java:133)", "org.logstash.instrument.metrics.MetricExt.doTime(MetricExt.java:140)", "org.logstash.instrument.metrics.AbstractSimpleMetricExt.time(AbstractSimpleMetricExt.java:45)", "org.logstash.instrument.metrics.NamespacedMetricExt.doTime(NamespacedMetricExt.java:87)", "org.logstash.instrument.metrics.AbstractNamespacedMetricExt.time(AbstractNamespacedMetricExt.java:44)", "org.logstash.instrument.metrics.AbstractNamespacedMetricExt$INVOKER$i$1$0$time.call(AbstractNamespacedMetricExt$INVOKER$i$1$0$time.gen)", "org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneBlock.call(JavaMethod.java:656)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:177)", "private.tmp.logstash.logstash_minus_core.lib.logstash.codecs.delegator.RUBY$method$decode$0(/private/tmp/logstash/logstash-core/lib/logstash/codecs/delegator.rb:44)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:117)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:156)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:386)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:184)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:191)", "org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:337)", "org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)", "org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:92)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:204)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:191)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:208)", "private.tmp.logstash.vendor.bundle.jruby.$2_dot_5_dot_0.gems.logstash_minus_input_minus_udp_minus_3_dot_3_dot_4.lib.logstash.inputs.udp.RUBY$block$run$2(/private/tmp/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-input-udp-3.3.4/lib/logstash/inputs/udp.rb:63)", "org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:136)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:77)", "org.jruby.runtime.Block.call(Block.java:129)", "org.jruby.RubyProc.call(RubyProc.java:295)", "org.jruby.RubyProc.call(RubyProc.java:274)", "org.jruby.RubyProc.call(RubyProc.java:270)", "org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)", "java.base/java.lang.Thread.run(Thread.java:834)"]}
...

[kares]

interesting, the error seems the same (quite sure that one should be fixed), what is suspicious is that the line number from the logs you provided do not match the 9.2.9.0-SNAPSHOT line :

class org.jruby.gen.RubyObject4 cannot be cast to class org.jruby.RubyFixnum (org.jruby.gen.RubyObject4 is in unnamed module of loader org.jruby.util.OneShotClassLoader @5835e24a; org.jruby.RubyFixnum is in unnamed module of loader 'app'), 
"backtrace"=>
["org.jruby.runtime.invokedynamic.MathLinker.fixnum_op_equal(MathLinker.java:237)"

https://github.com/jruby/jruby/blob/master/core/src/main/java/org/jruby/runtime/invokedynamic/MathLinker.java#L237

it matched 9.2.8.0 so maybe, somehow, you ended up (still) picking up 9.2.8.0?
https://github.com/jruby/jruby/blob/9.2.8.0/core/src/main/java/org/jruby/runtime/invokedynamic/MathLinker.java#L237

[jsvd]

right we need to sort that out. I've cloned master locally and ran:

./gradlew clean installDefaultGems -Pcustom.jruby.path="~/projects/jruby"

% bin/logstash -e ""
WARNING: Illegal reflective access by com.headius.backport9.modules.Modules (file:/Users/joaoduarte/elastic/logstash/logstash-core/lib/jars/jruby-complete-9.2.9.0-SNAPSHOT.jar) to method sun.nio.ch.NativeThread.signal(long)
[2019-10-25T12:49:07,648][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"8.0.0"}
[2019-10-25T12:49:07,673][FATAL][logstash.runner          ] An unexpected error occurred! {:error=>java.lang.NullPointerException, :backtrace=>["org.jruby.runtime.invokedynamic.MathLinker.floatOperator(MathLinker.java:353)", "Users.joaoduarte.elastic.logstash.logstash_minus_core.lib.logstash.agent.RUBY$method$initialize$0(/Users/joaoduarte/elastic/logstash/logstash-core/lib/logstash/agent.rb:70)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:84)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:70)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:332)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:86)", "org.jruby.RubyClass.newInstance(RubyClass.java:915)", "org.jruby.RubyClass$INVOKER$i$newInstance.call(RubyClass$INVOKER$i$newInstance.gen)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:183)", "Users.joaoduarte.elastic.logstash.logstash_minus_core.lib.logstash.runner.RUBY$method$create_agent$0(/Users/joaoduarte/elastic/logstash/logstash-core/lib/logstash/runner.rb:450)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:84)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:120)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:175)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:208)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:396)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:205)", "org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:325)", "org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:86)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:73)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:183)", "Users.joaoduarte.elastic.logstash.vendor.bundle.jruby.$2_dot_5_dot_0.gems.clamp_minus_0_dot_6_dot_5.lib.clamp.command.RUBY$method$run$0(/Users/joaoduarte/elastic/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-0.6.5/lib/clamp/command.rb:67)", "Users.joaoduarte.elastic.logstash.vendor.bundle.jruby.$2_dot_5_dot_0.gems.clamp_minus_0_dot_6_dot_5.lib.clamp.command.RUBY$method$run$0$__VARARGS__(/Users/joaoduarte/elastic/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-0.6.5/lib/clamp/command.rb)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:84)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:70)", "org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuper(IRRuntimeHelpers.java:1169)", "org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuperSplatArgs(IRRuntimeHelpers.java:1156)", "org.jruby.ir.targets.InstanceSuperInvokeSite.invoke(InstanceSuperInvokeSite.java:39)", "Users.joaoduarte.elastic.logstash.logstash_minus_core.lib.logstash.runner.RUBY$method$run$0(/Users/joaoduarte/elastic/logstash/logstash-core/lib/logstash/runner.rb:242)", "Users.joaoduarte.elastic.logstash.logstash_minus_core.lib.logstash.runner.RUBY$method$run$0$__VARARGS__(/Users/joaoduarte/elastic/logstash/logstash-core/lib/logstash/runner.rb)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:84)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:70)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:183)", "Users.joaoduarte.elastic.logstash.vendor.bundle.jruby.$2_dot_5_dot_0.gems.clamp_minus_0_dot_6_dot_5.lib.clamp.command.RUBY$method$run$0(/Users/joaoduarte/elastic/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-0.6.5/lib/clamp/command.rb:132)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:84)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:70)", "org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:183)", "Users.joaoduarte.elastic.logstash.lib.bootstrap.environment.RUBY$script(/Users/joaoduarte/elastic/logstash/lib/bootstrap/environment.rb:73)", "java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:710)", "org.jruby.ir.Compiler$1.load(Compiler.java:89)", "org.jruby.Ruby.runScript(Ruby.java:857)", "org.jruby.Ruby.runNormally(Ruby.java:780)", "org.jruby.Ruby.runNormally(Ruby.java:798)", "org.jruby.Ruby.runFromMain(Ruby.java:610)", "org.logstash.Logstash.run(Logstash.java:113)", "org.logstash.Logstash.main(Logstash.java:47)"]}
[2019-10-25T12:49:07,685][ERROR][org.logstash.Logstash    ] java.lang.IllegalStateException: Logstash stopped processing because of an error: (SystemExit) exit

[headius]

I believe an additional fix that @kares made in jruby/jruby@ec1443a6098787a40f6bb882540cabffcf326df0 will probably fix the final NPE that @jsvd reported. Please retest with JRuby master. We will be releasing 9.2.9 next week.

[jsvd]

I've just tested the scenario I described in https://github.com/elastic/logstash/issues/11196#issuecomment-546323059 with https://github.com/jruby/jruby/commit/21a664268b and it all works fine now, many thanks @kares and @headius :)

[d18c7db]

Oops I seem to have oppened an issue in https://github.com/logstash-plugins/logstash-input-udp/issues/47 which is exactly the problem you guys are discussing here.

[colinsurprenant]

Great stuff! I also confirm that the latest master fixes the above repro script with the logstash netflow & Bindata Header class.
Thanks @kares!!

[JasonEverling]

So is this fixed in the 7.5 release? I didn't see any reference in release notes.

[colinsurprenant]

@JasonEverling unfortunately no, this will be fixed when JRuby is updated to 9.2.9.0 in logstash which is currently updated in the 7.x branch so will be out in the 7.6 release.

[willemdh]

Is this issue solved in 7.6?

[fracmak]

I'm no longer seeing the error in 7.6