Logstash Fatal Error after updating logstash plugin

[jgough]

I don't know what has happened but in the past two weeks I've been unable to run logstash filter verifier with Logstash 6 after updating plugins.

A full Dockerfile to repro is provided below, but the steps are:

1. Install logstash 6 (verified fails with 6.7.0, 6.8.2 & 6.8.10)
2. Run logstash-filter-verifier => This works as expected
3. Update any plugin, eg run logstash-plugin update logstash-input-tcp
4. Run logstash-filter-verifier => Logstash exits with the error:

   [2020-07-16T09:34:07,690][FATAL][logstash.runner          ] An unexpected error occurred! {:error=>#<NameError: uninitialized constant LibC::FFI>, :backtrace=>["org/jruby/RubyModule.java:3536:in `const_missing'", "/usr/share/logstash/logstash-core/lib/logstash/util/prctl.rb:4:in `<module:LibC>'", "/usr/share/logstash/logstash-core/lib/logstash/util/prctl.rb:2:in `<main>'", "org/jruby/RubyKernel.java:984:in `require'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/polyglot-0.3.5/lib/polyglot.rb:65:in `require'", "/usr/share/logstash/logstash-core/lib/logstash/util.rb:21:in `set_thread_name'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:306:in `execute'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-0.6.5/lib/clamp/command.rb:67:in `run'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:237:in `run'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-0.6.5/lib/clamp/command.rb:132:in `run'", "/opt/logstash/lib/bootstrap/environment.rb:73:in `<main>'"]}

Notes:

• the pipeline works correctly when run directly in logstash, the above error only occurs when running through logstash-filter-verifier.
• I'm not sure that this is necessarily an issue with the filter verifier itself - but something along the chain isn't working
• I've tried with logstash 7.6.0 which works fine, but logstash 6 fails.
• This suddenly stopped working at some point in the past 2 weeks. I can't figure out why!
• I have tried this with logstash filter verifier v1.6.0 and v1.6.1 and both fail.

Here is a Dockerfile to repro this:

FROM docker.elastic.co/logstash/logstash:6.8.10

# Install Logstash Filter Verifier
ENV LOGSTASH_FILTER_VERIFIER_VERSION 1.6.1
USER root
ADD https://github.com/magnusbaeck/logstash-filter-verifier/releases/download/${LOGSTASH_FILTER_VERIFIER_VERSION}/logstash-filter-verifier_${LOGSTASH_FILTER_VERIFIER_VERSION}_linux_386.tar.gz /opt/
RUN tar xvzf /opt/logstash-filter-verifier_${LOGSTASH_FILTER_VERIFIER_VERSION}_linux_386.tar.gz -C /opt \
    && mv /opt/logstash-filter-verifier /usr/bin/

USER logstash

# Set up some test files
RUN echo 'input { generator { lines => ["line 1"] count => 1 } } output { stdout { codec => rubydebug } }' > ./logstash.conf
RUN echo '{}' > ./test.json

# Run logstash, then run the filter verifier
#### BOTH OF THESE WORK CORRECTLY ####
RUN bin/logstash -f ./logstash.conf
RUN logstash-filter-verifier ./test.json ./logstash.conf

# Doesn't really matter what gets updated here, just update something
RUN logstash-plugin update logstash-input-tcp 

# This works
RUN bin/logstash -f ./logstash.conf

#### This DOES NOT work and returns an error ####
RUN logstash-filter-verifier ./test.json ./logstash.conf

Here is the raw output to building this:

$ docker build .
Sending build context to Docker daemon  3.072kB
Step 1/13 : FROM docker.elastic.co/logstash/logstash:6.8.10
 ---> 526c0151af45
Step 2/13 : ENV LOGSTASH_FILTER_VERIFIER_VERSION 1.6.1
 ---> Running in 54319a414193
Removing intermediate container 54319a414193
 ---> 944be0e5153a
Step 3/13 : USER root
 ---> Running in 98b44a9cafda
Removing intermediate container 98b44a9cafda
 ---> 0b67aaa3a9c0
Step 4/13 : ADD https://github.com/magnusbaeck/logstash-filter-verifier/releases/download/${LOGSTASH_FILTER_VERIFIER_VERSION}/logstash-filter-verifier_${LOGSTASH_FILTER_VERIFIER_VERSION}_linux_386.tar.gz /opt/
Downloading [==================================================>]  3.458MB/3.458MB
 ---> 681afbbfda72
Step 5/13 : RUN tar xvzf /opt/logstash-filter-verifier_${LOGSTASH_FILTER_VERIFIER_VERSION}_linux_386.tar.gz -C /opt     && mv /opt/logstash-filter-verifier /usr/bin/
 ---> Running in f07d57a3f577
./
./CHANGELOG.md
./logstash-filter-verifier
./LICENSE
./README.md
Removing intermediate container f07d57a3f577
 ---> 0a3bf5d0df6a
Step 6/13 : USER logstash
 ---> Running in 3bc895ba96b8
Removing intermediate container 3bc895ba96b8
 ---> b2569056a8cb
Step 7/13 : RUN echo 'input { generator { lines => ["line 1"] count => 1 } } output { stdout { codec => rubydebug } }' > ./logstash.conf
 ---> Running in a00782768ad5
Removing intermediate container a00782768ad5
 ---> 14eb0a6acb8b
Step 8/13 : RUN echo '{}' > ./test.json
 ---> Running in f42a249e33d9
Removing intermediate container f42a249e33d9
 ---> 9c721690c76a
Step 9/13 : RUN bin/logstash -f ./logstash.conf
 ---> Running in 135e3e174b08
Sending Logstash logs to /usr/share/logstash/logs which is now configured via log4j2.properties
[2020-07-16T09:48:41,587][INFO ][logstash.setting.writabledirectory] Creating directory {:setting=>"path.queue", :path=>"/usr/share/logstash/data/queue"}
[2020-07-16T09:48:41,604][INFO ][logstash.setting.writabledirectory] Creating directory {:setting=>"path.dead_letter_queue", :path=>"/usr/share/logstash/data/dead_letter_queue"}
[2020-07-16T09:48:41,938][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2020-07-16T09:48:41,950][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"6.8.10"}
[2020-07-16T09:48:41,980][INFO ][logstash.agent           ] No persistent UUID file found. Generating new UUID {:uuid=>"b0b3284a-3d82-490f-a7d6-5b69a2b8ae06", :path=>"/usr/share/logstash/data/uuid"}
[2020-07-16T09:48:42,496][WARN ][logstash.monitoringextension.pipelineregisterhook] xpack.monitoring.enabled has not been defined, but found elasticsearch configuration. Please explicitly set `xpack.monitoring.enabled: true` in logstash.yml
[2020-07-16T09:48:43,339][INFO ][logstash.licensechecker.licensereader] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://elasticsearch:9200/]}}
[2020-07-16T09:48:43,505][WARN ][logstash.licensechecker.licensereader] Attempted to resurrect connection to dead ES instance, but got an error. {:url=>"http://elasticsearch:9200/", :error_type=>LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError, :error=>"Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch: Name or service not known"}
[2020-07-16T09:48:43,558][WARN ][logstash.licensechecker.licensereader] Marking url as dead. Last error: [LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError] Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch {:url=>http://elasticsearch:9200/, :error_message=>"Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch", :error_class=>"LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError"}
[2020-07-16T09:48:43,566][ERROR][logstash.licensechecker.licensereader] Unable to retrieve license information from license server {:message=>"Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch"}
[2020-07-16T09:48:43,606][ERROR][logstash.monitoring.internalpipelinesource] Failed to fetch X-Pack information from Elasticsearch. This is likely due to failure to reach a live Elasticsearch cluster.
[2020-07-16T09:48:48,682][INFO ][logstash.pipeline        ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>16, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2020-07-16T09:48:48,789][INFO ][logstash.pipeline        ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x2c018b90 sleep>"}
[2020-07-16T09:48:48,854][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/awesome_print-1.7.0/lib/awesome_print/formatters/base_formatter.rb:31: warning: constant ::Fixnum is deprecated
{
      "@version" => "1",
    "@timestamp" => 2020-07-16T09:48:48.820Z,
          "host" => "135e3e174b08",
       "message" => "line 1",
      "sequence" => 0
}
[2020-07-16T09:48:49,274][INFO ][logstash.pipeline        ] Pipeline has terminated {:pipeline_id=>"main", :thread=>"#<Thread:0x2c018b90 run>"}
[2020-07-16T09:48:49,281][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
[2020-07-16T09:48:49,475][INFO ][logstash.runner          ] Logstash shut down.
Removing intermediate container 135e3e174b08
 ---> 35340e02a58c
Step 10/13 : RUN logstash-filter-verifier ./test.json ./logstash.conf
 ---> Running in d05763a98b87
Running tests in test.json...
☑ Compare actual event with expected event from test.json

Summary: ☑ All tests: 1/1
         ☑ test.json: 1/1
Removing intermediate container d05763a98b87
 ---> 111e8ffe1f81
Step 11/13 : RUN logstash-plugin update logstash-input-tcp
 ---> Running in 68b2abff8a7d
Updating logstash-input-tcp
Updated logstash-input-tcp 5.2.3 to 6.0.6
Removing intermediate container 68b2abff8a7d
 ---> cdd9a3e7ec62
Step 12/13 : RUN bin/logstash -f ./logstash.conf
 ---> Running in 2910b4ba6690
Sending Logstash logs to /usr/share/logstash/logs which is now configured via log4j2.properties
[2020-07-16T09:49:52,057][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2020-07-16T09:49:52,071][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"6.8.10"}
[2020-07-16T09:49:52,588][WARN ][logstash.monitoringextension.pipelineregisterhook] xpack.monitoring.enabled has not been defined, but found elasticsearch configuration. Please explicitly set `xpack.monitoring.enabled: true` in logstash.yml
[2020-07-16T09:49:53,450][INFO ][logstash.licensechecker.licensereader] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://elasticsearch:9200/]}}
[2020-07-16T09:49:53,611][WARN ][logstash.licensechecker.licensereader] Attempted to resurrect connection to dead ES instance, but got an error. {:url=>"http://elasticsearch:9200/", :error_type=>LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError, :error=>"Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch: Name or service not known"}
[2020-07-16T09:49:53,652][WARN ][logstash.licensechecker.licensereader] Marking url as dead. Last error: [LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError] Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch {:url=>http://elasticsearch:9200/, :error_message=>"Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch", :error_class=>"LogStash::Outputs::ElasticSearch::HttpClient::Pool::HostUnreachableError"}
[2020-07-16T09:49:53,660][ERROR][logstash.licensechecker.licensereader] Unable to retrieve license information from license server {:message=>"Elasticsearch Unreachable: [http://elasticsearch:9200/][Manticore::ResolutionFailure] elasticsearch"}
[2020-07-16T09:49:53,697][ERROR][logstash.monitoring.internalpipelinesource] Failed to fetch X-Pack information from Elasticsearch. This is likely due to failure to reach a live Elasticsearch cluster.
[2020-07-16T09:49:58,946][INFO ][logstash.pipeline        ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>16, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2020-07-16T09:49:59,049][INFO ][logstash.pipeline        ] Pipeline started successfully {:pipeline_id=>"main", :thread=>"#<Thread:0x6f73e06d run>"}
[2020-07-16T09:49:59,111][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/awesome_print-1.7.0/lib/awesome_print/formatters/base_formatter.rb:31: warning: constant ::Fixnum is deprecated
{
      "@version" => "1",
      "sequence" => 0,
    "@timestamp" => 2020-07-16T09:49:59.109Z,
       "message" => "line 1",
          "host" => "2910b4ba6690"
}
[2020-07-16T09:49:59,549][INFO ][logstash.pipeline        ] Pipeline has terminated {:pipeline_id=>"main", :thread=>"#<Thread:0x6f73e06d run>"}
[2020-07-16T09:49:59,552][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
[2020-07-16T09:49:59,750][INFO ][logstash.runner          ] Logstash shut down.
Removing intermediate container 2910b4ba6690
 ---> 6c5c60f88325
Step 13/13 : RUN logstash-filter-verifier ./test.json ./logstash.conf
 ---> Running in 2bf0def813e2
Running tests in test.json...
Error running Logstash: exit status 1.
Process output:
Sending Logstash logs to /tmp/080761604/log which is now configured via log4j2.properties
[2020-07-16T09:50:15,856][DEBUG][logstash.modules.scaffold] Found module {:module_name=>"fb_apache", :directory=>"/opt/logstash/modules/fb_apache/configuration"}
[2020-07-16T09:50:15,860][DEBUG][logstash.plugins.registry] Adding plugin to the registry {:name=>"fb_apache", :type=>:modules, :class=>#<LogStash::Modules::Scaffold:0x4fdf83bb @directory="/opt/logstash/modules/fb_apache/configuration", @module_name="fb_apache", @kibana_version_parts=["6", "0", "0"]>}
[2020-07-16T09:50:15,862][DEBUG][logstash.modules.scaffold] Found module {:module_name=>"netflow", :directory=>"/opt/logstash/modules/netflow/configuration"}
[2020-07-16T09:50:15,862][DEBUG][logstash.plugins.registry] Adding plugin to the registry {:name=>"netflow", :type=>:modules, :class=>#<LogStash::Modules::Scaffold:0x63c57bde @directory="/opt/logstash/modules/netflow/configuration", @module_name="netflow", @kibana_version_parts=["6", "0", "0"]>}
[2020-07-16T09:50:15,908][INFO ][logstash.setting.writabledirectory] Creating directory {:setting=>"path.queue", :path=>"/tmp/080761604/data/queue"}
[2020-07-16T09:50:15,915][INFO ][logstash.setting.writabledirectory] Creating directory {:setting=>"path.dead_letter_queue", :path=>"/tmp/080761604/data/dead_letter_queue"}
[2020-07-16T09:50:15,980][FATAL][logstash.runner          ] An unexpected error occurred! {:error=>#<NameError: uninitialized constant LibC::FFI>, :backtrace=>["org/jruby/RubyModule.java:3742:in `const_missing'", "/usr/share/logstash/logstash-core/lib/logstash/util/prctl.rb:4:in `<module:LibC>'", "/usr/share/logstash/logstash-core/lib/logstash/util/prctl.rb:2:in `<main>'", "org/jruby/RubyKernel.java:987:in `require'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/polyglot-0.3.5/lib/polyglot.rb:65:in `require'", "/usr/share/logstash/logstash-core/lib/logstash/util.rb:21:in `set_thread_name'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:306:in `execute'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-0.6.5/lib/clamp/command.rb:67:in `run'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:237:in `run'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-0.6.5/lib/clamp/command.rb:132:in `run'", "/opt/logstash/lib/bootstrap/environment.rb:73:in `<main>'"]}
[2020-07-16T09:50:15,986][ERROR][org.logstash.Logstash    ] java.lang.IllegalStateException: Logstash stopped processing because of an error: (SystemExit) exit

The process wrote nothing to its logfile.
The command '/bin/sh -c logstash-filter-verifier ./test.json ./logstash.conf' returned a non-zero code: 1

Any thoughts on why this might be happening? I'm baffled. Let me know if I can provide more info. Thanks!

[magnusbaeck]

Very odd indeed. I don't have anything clever to offer OTOH but I can at least see if I can reproduce it. Given the dockerfile (thanks for that!) it should reproduce, but I've seen weirder stuff.

[cdenneen]

I downloaded 6.8.12 and just trying to run that i'm getting this error... Did anyone figure out what was causing this issue? Maybe it's not plugin related?

[jgough]

I never managed to get it to work myself, I had to upgrade to v7 to get around this.

[magnusbaeck]

Since it works on Logstash 7 I say we close the issue. If the problem pops on in a current release we can reopen.