nil fields can cause crash of the pipeline

[joemiller]

Please post all product and debugging questions on our forum. Your questions will reach our wider community members there, and if we confirm that there is a bug, then we can open a new issue here.

For all general issues, please provide the following details for fast resolution:

• Version: 2.3.2 and 2.3.3
• Operating System: linux (fedora-22)

We have run into a case where fields with a nil name are entering the pipeline. In this case these are coming from the use of the kv filter to parse on =. The prune filter should probably be more defensive about this.

Here is the exception and stack trace:

Jun 21 16:34:24 foo logstash_server[20795]: {:timestamp=>"2016-06-21T16:34:24.344000+0000", :message=>"Exception in pipelineworker, the pipeline stopped processing new events, please check your filter con
figuration and restart Logstash.", "exception"=>#<NoMethodError: undefined method `match' for nil:NilClass>, "backtrace"=>["/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-prune-2.0.5/lib/logstash/filters/prune.rb:97:in `filter
'", "org/jruby/RubyHash.java:1403:in `each_key'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-prune-2.0.5/lib/logstash/filters/prune.rb:93:in `filter'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/
lib/logstash/filters/base.rb:151:in `multi_filter'", "org/jruby/RubyArray.java:1613:in `each'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/filters/base.rb:148:in `multi_filter'", "(eval):13472:in `co
nd_func_711'", "org/jruby/RubyArray.java:1613:in `each'", "(eval):13467:in `cond_func_711'", "(eval):3008:in `filter_func'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:267:in `filter_batc
h'", "org/jruby/RubyArray.java:1613:in `each'", "org/jruby/RubyEnumerable.java:852:in `inject'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:265:in `filter_batch'", "/opt/logstash/vendor/b
undle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:223:in `worker_loop'", "/opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:201:in `start_workers'"], :level=>:error}
Jun 21 16:34:24 foo logstash_server[20795]: NoMethodError: undefined method `match' for nil:NilClass
Jun 21 16:34:24 foo logstash_server[20795]: filter at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-prune-2.0.5/lib/logstash/filters/prune.rb:97
Jun 21 16:34:24 foo logstash_server[20795]: each_key at org/jruby/RubyHash.java:1403
Jun 21 16:34:24 foo logstash_server[20795]: filter at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-filter-prune-2.0.5/lib/logstash/filters/prune.rb:93
Jun 21 16:34:24 foo logstash_server[20795]: multi_filter at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/filters/base.rb:151
Jun 21 16:34:24 foo logstash_server[20795]: each at org/jruby/RubyArray.java:1613
Jun 21 16:34:24 foo logstash_server[20795]: multi_filter at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/filters/base.rb:148
Jun 21 16:34:24 foo logstash_server[20795]: cond_func_711 at (eval):13472
Jun 21 16:34:24 foo logstash_server[20795]: each at org/jruby/RubyArray.java:1613
Jun 21 16:34:24 foo logstash_server[20795]: cond_func_711 at (eval):13467
Jun 21 16:34:24 foo logstash_server[20795]: filter_func at (eval):3008
Jun 21 16:34:24 foo logstash_server[20795]: filter_batch at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:267
Jun 21 16:34:24 foo logstash_server[20795]: each at org/jruby/RubyArray.java:1613
Jun 21 16:34:24 foo logstash_server[20795]: inject at org/jruby/RubyEnumerable.java:852
Jun 21 16:34:24 foo logstash_server[20795]: filter_batch at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:265
Jun 21 16:34:24 foo logstash_server[20795]: worker_loop at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:223
Jun 21 16:34:24 foo logstash_server[20795]: start_workers at /opt/logstash/vendor/bundle/jruby/1.9/gems/logstash-core-2.3.2-java/lib/logstash/pipeline.rb:201

Here is an example (event.to_hash()) of the bad data that t

{"@timestamp"=>"2016-06-21T16:32:38.000Z", "@version"=>1, "message"=>"==> /var/log/nginx/nginx_hermes-error.log <==", "host"=>"1.1.2.3", "port"=>36896, "sslsubject"=>"/C=US/ST=California/L=San Francisco/O=Pantheon Systems, Inc./OU=endpoint/CN=7cb65900-a703-4a37-9f9e-0d9a34e6a201", "tags"=>["systemd_journal_json"], "priority"=>"6", "syslog_
facility"=>"3", "syslog_identifier"=>"tail", "boot_id"=>"ddd", "cap_effective"=>"0", "cmdline"=>"/bin/tail -F /var/log/nginx/nginx_hermes-access.log -F /var/log/nginx/nginx_hermes-error.log", "comm"=>"tail", "
exe"=>"/usr/bin/tail", "gid"=>"0", "hostname"=>"hermes7cb", "machine_id"=>"dddd", "pid"=>"385", "systemd_cgroup"=>"/system.slice/hermes_logs.service", "systemd_slice"=>"system.slice", "syste
md_unit"=>"hermes_logs.service", "transport"=>"stdout", "uid"=>"0", "cursor"=>"s=f8a663617c914503b1f5ec9c1cc69d3e;i=492e360;b=cba0e871f39a40a1ad64c55230f70c41;m=3c3fd8648b7;t=535cc5e84a03a;x=4747f4c7c780d926", "monotonic_timestamp"=>"4140
306942135", nil=>"="}

Notice the bad data is the last field which has key nil and value =.

The prune filter could be more defensive on line 94 and 105 by next if field.nil?.