logstash-filter-translate-3.2.0 doesn't work with ELK stack 6.4.0

[madkoala]

I'm running elasticflow-3.1.0 on 4 ubuntu 16.04 cluster.
I've upgraded ELK stack from 6.3.2 to 6.4.0 via aptitude.

After upgrade, I've run /usr/share/logstash/bin/logstash-plugin update logstash-filter-translate and it updated translate filter from 3.1.0 to 3.2.0.
After that, elastiflow failed to parse netflow events.
So, after few hours of investigation, I've found that the pipeline had been blocked processing "elastiflow_public_dst_rep_label" or "elastiflow_public_src_rep_label" which are defined in the "20_filter_90_post_process.logstash.conf".

My workaround was:

1. Remove logstash-filter-translate 3.2.0
2. Install logstash-filter-translate 3.1.0 using "logstash-plugin install --version=3.1.0 logstash-filter-translate"

Thank you for your great effort.
Hope this issue helps.

[robcowart]

Interesting. Were there any errors in the logs that you could share?

[madkoala]

There's no log shown when the netflow events are not processed. It may be blocked.
But when stopping logstash, I can see the following logs.

[2018-08-25T00:56:22,163][WARN ][logstash.runner ] SIGTERM received. Shutting down.
[2018-08-25T00:56:29,442][WARN ][org.logstash.execution.ShutdownWatcherExt] {"inflight_count"=>0, "stalling_threads_info"=>{["LogStash::Filters::Translate", {"dictionary_path"=>"${ELASTIFLOW_DICT_PATH:/etc/logstash/elastiflow/dictionaries}/ip_rep_basic.yml", "destination"=>"[@metadata][dst_rep_label]", "id"=>"elastiflow_public_dst_rep_label", "field"=>"[flow][dst_addr]"}]=>[{"thread_id"=>96, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in []'"}, {"thread_id"=>97, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in []'"}, {"thread_id"=>98, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in match'"}, {"thread_id"=>99, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in match'"}, {"thread_id"=>100, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in match'"}, {"thread_id"=>102, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in []'"}], ["LogStash::Filters::Translate", {"dictionary_path"=>"${ELASTIFLOW_DICT_PATH:/etc/logstash/elastiflow/dictionaries}/ip_rep_basic.yml", "destination"=>"[@metadata][src_rep_label]", "id"=>"elastiflow_public_src_rep_label", "field"=>"[flow][src_addr]"}]=>[{"thread_id"=>101, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:-1:in block in fetch'"}, {"thread_id"=>103, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:-1:in block in fetch'"}]}}
[2018-08-25T00:56:29,500][ERROR][org.logstash.execution.ShutdownWatcherExt] The shutdown process appears to be stalled due to busy or blocked plugins. Check the logs for more information.
[2018-08-25T00:56:35,175][WARN ][org.logstash.execution.ShutdownWatcherExt] {"inflight_count"=>0, "stalling_threads_info"=>{["LogStash::Filters::Translate", {"dictionary_path"=>"${ELASTIFLOW_DICT_PATH:/etc/logstash/elastiflow/dictionaries}/ip_rep_basic.yml", "destination"=>"[@metadata][src_rep_label]", "id"=>"elastiflow_public_src_rep_label", "field"=>"[flow][src_addr]"}]=>[{"thread_id"=>96, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in []'"}, {"thread_id"=>100, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in match'"}, {"thread_id"=>102, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in match'"}, {"thread_id"=>103, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:-1:in block in fetch'"}], ["LogStash::Filters::Translate", {"dictionary_path"=>"${ELASTIFLOW_DICT_PATH:/etc/logstash/elastiflow/dictionaries}/ip_rep_basic.yml", "destination"=>"[@metadata][dst_rep_label]", "id"=>"elastiflow_public_dst_rep_label", "field"=>"[flow][dst_addr]"}]=>[{"thread_id"=>97, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in []'"}, {"thread_id"=>98, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in keys'"}, {"thread_id"=>99, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in match'"}, {"thread_id"=>101, "name"=>nil, "current_call"=>"[...]/vendor/bundle/jruby/2.3.0/gems/logstash-filter-translate-3.2.0/lib/logstash/filters/fetch_strategy/file.rb:45:in []'"}]}}

[robcowart]

Please add you comments to... logstash-plugins/logstash-filter-translate#69

It looks like there are others (not ElastiFlow users) having issues with version 3.2.0 of the translate filter.

[guyboertje]

@robcowart

The dictionary path "${ELASTIFLOW_DICT_PATH:/etc/logstash/elastiflow/dictionaries}/ip_rep_basic.yml" looks very unusual to me.

I presume this works in 3.1.0 but I can't see how.
v 3.1.0

  def load_yaml(raise_exception=false)
    if !File.exists?(@dictionary_path)
      @logger.warn("dictionary file read failure, continuing with old dictionary", :path => @dictionary_path)
      return
    end
    refresh_dictionary!(YAML.load_file(@dictionary_path))
  end

where YAML.load_file does:

File.open(filename, 'r:bom|utf-8') { |f| self.load f, filename }

The new code does IO.read(dictionary_path)

[robcowart]

@guyboertje what is so unusual? The path is a concatenation of the value of the environment variable ELASTIFLOW_DICT_PATH, or /etc/logstash/elastiflow/dictionaries if not set, and /ip_rep_basic.yml. So it wil be something like: /etc/logstash/elastiflow/dictionaries/ip_rep_basic.yml

I have been using environment variables like this for nearly two years. It is pretty standard and documented.

[guyboertje]

@robcowart

I'm not saying it is wrong or to blame for the translate filter problems and I understand the intent.

EDITED

I did not understand where/how in the LS code base the environment variable is resolved, I do now.

I see now that it is part of the config parsing where plugin params are deep_replaced via the LogStash::Util::SubstitutionVariables class.

[guyboertje]

BTW,
logstash-plugins/logstash-filter-translate#69 is specifically about LS 2.4.1 not working with 3.2.0 of translate (fix in progress).
logstash-plugins/logstash-filter-translate#70 has been triaged to be relevant only when using the CSV filter and a CSV dictionary in 3.2.0 of translate (fixed locally PR tomorrow).
elastic/logstash#9936 seems to be related to JSON parsing. We switched to using Logstash::Json to parse the file instead of the ruby JSON gem. Jackson (the Java JSON) parser doesn't seem to like that users JSON data - need more reports on this one to verify a more general problem). EDITED. There is a bug that effectively makes regex => true and creates Regex instances from the json keys - this this case the json keys contained unescaped regex square brackets.