Exception in inputworker - Value for year must be in range

[pgastinger]

Hi,

I recently upgraded my IPFIX-ELK-installation to version 6.3.2 on "Ubuntu 16.04.5 LTS" and I get
following logstash error message:

[2018-08-23T06:40:52,762][ERROR][logstash.inputs.udp      ] Exception in inputworker {"exception"=>#<RangeError: Value -292275055 for year must be in the range [-292275054,292278993]>, "backtrace"=>["org/jruby/RubyTime.java:1166:in `at'", "org/logstash/ext/JrubyTimestampExtLibrary.java:188:in `at'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:379:in `block in decode_ipfix'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/struct.rb:169:in `block in each_pair'", "org/jruby/RubyArray.java:1734:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/struct.rb:168:in `each_pair'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:372:in `block in decode_ipfix'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `block in each'", "org/jruby/RubyArray.java:1734:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:358:in `decode_ipfix'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:131:in `block in decode'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `block in each'", "org/jruby/RubyArray.java:1734:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:130:in `decode'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-udp-3.3.3/lib/logstash/inputs/udp.rb:142:in `inputworker'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-udp-3.3.3/lib/logstash/inputs/udp.rb:111:in `block in udp_listener'"]}
[2018-08-23T06:40:52,781][ERROR][logstash.inputs.udp      ] Exception in inputworker {"exception"=>#<RangeError: Value -292275055 for year must be in the range [-292275054,292278993]>, "backtrace"=>["org/jruby/RubyTime.java:1166:in `at'", "org/logstash/ext/JrubyTimestampExtLibrary.java:188:in `at'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:379:in `block in decode_ipfix'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/struct.rb:169:in `block in each_pair'", "org/jruby/RubyArray.java:1734:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/struct.rb:168:in `each_pair'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:372:in `block in decode_ipfix'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `block in each'", "org/jruby/RubyArray.java:1734:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:358:in `decode_ipfix'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:131:in `block in decode'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `block in each'", "org/jruby/RubyArray.java:1734:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/bindata-2.4.3/lib/bindata/array.rb:208:in `each'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb:130:in `decode'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-udp-3.3.3/lib/logstash/inputs/udp.rb:142:in `inputworker'", "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-input-udp-3.3.3/lib/logstash/inputs/udp.rb:111:in `block in udp_listener'"]}

After this message, I have to restart the logstash process, otherwise it won't insert any new data into elasticsearch anymore. I can't even restart the process the standard way, I have to kill it:

[2018-08-23T07:26:57,482][ERROR][logstash.shutdownwatcher ] The shutdown process appears to be stalled due to busy or blocked plugins. Check the logs for more information.

Does anybody have any ideas how to fix this? Thanks!

regards,
Peter

[jorritfolmer]

Can you provide a pcap file with the IPFIX traffic that causes this crash?

[pgastinger]

Unfortunately, the pcap trace is rather large and confidential. If it would help, I can share it privately (approx 100MB)

I added a couple of debug outputs to this file:
/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/logstash-codec-netflow-3.14.1/lib/logstash/codecs/netflow.rb

              begin
                  event[@target][k.to_s] = LogStash::Timestamp.at(v.snapshot.to_f / 1_000).to_iso8601
              rescue
                  @logger.error("ERROR - START")
                  @logger.error(LogStash::Event)
                  @logger.error("ERROR - END")
                  event[@target][k.to_s] = ""

This dirty hack catches the exception and it does not crash anymore. But it looks like the Logstash::Event is empty for some requests:

[2018-08-27T11:51:02,093][ERROR][logstash.codecs.netflow  ] ERROR - START
[2018-08-27T11:51:02,093][ERROR][logstash.codecs.netflow  ] {}
[2018-08-27T11:51:02,093][ERROR][logstash.codecs.netflow  ] ERROR - END

[jorritfolmer]

Sure share it privately, email in my profile.

[jorritfolmer]

I haven't been able to reproduce the crash by replaying your pcap.
Replaying templates + data 256 and 512 from 1 exporter and 1 observation domain also decode fine.
All dates are 2018-08. This looks fine too.

Looking at your pcap it seems you point multiple exporters to your logstash instance. Which could work, however the codec cannot differentiate based on src ip of the exporter, because it's a codec not an input plugin.

This means that most likely a template sent by exporter A is used to decode a data packet by exporter B. This could work if exporter A and B are using the exact same firmware and the exact same exporter settings.

We've seen with Cisco devices this leads to similar issues, so most likely too with Juniper stuff.
See for example #9 and #21