logstash 7.16.* recently fails to start when using this plugin!

[richard-mauri]

Please run these steps (works on mac os with Docker desktop) Note I also tried to specify a locked down version with --version 2.1.3 but it doesn't help.

printf "FROM docker.elastic.co/logstash/logstash:7.16.2\nUSER logstash\nRUN bin/logstash-plugin install logstash-input-s3-sns-sqs" > Dockerfile

docker build -t lsbug --no-cache .
docker run --rm --name=lsbug lsbug

You will see:

$ docker run --rm --name=lsbug lsbug
Using bundled JDK: /usr/share/logstash/jdk
OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
Sending Logstash logs to /usr/share/logstash/logs which is now configured via log4j2.properties
[2022-02-16T15:57:07,545][INFO ][logstash.runner          ] Log4j configuration path used is: /usr/share/logstash/config/log4j2.properties
[2022-02-16T15:57:07,554][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"7.16.2", "jruby.version"=>"jruby 9.2.20.1 (2.5.8) 2021-11-30 2a2962fbd1 OpenJDK 64-Bit Server VM 11.0.13+8 on 11.0.13+8 +indy +jit [linux-x86_64]"}
[2022-02-16T15:57:07,589][INFO ][logstash.settings        ] Creating directory {:setting=>"path.queue", :path=>"/usr/share/logstash/data/queue"}
[2022-02-16T15:57:07,602][INFO ][logstash.settings        ] Creating directory {:setting=>"path.dead_letter_queue", :path=>"/usr/share/logstash/data/dead_letter_queue"}
[2022-02-16T15:57:07,939][INFO ][logstash.agent           ] No persistent UUID file found. Generating new UUID {:uuid=>"3e81ba1d-ad81-4ae4-90c1-2a2d57615f7c", :path=>"/usr/share/logstash/data/uuid"}
[2022-02-16T15:57:07,983][FATAL][logstash.runner          ] An unexpected error occurred! {:error=>#<ArgumentError: wrong number of arguments (given 3, expected 1..2)>, :backtrace=>["/usr/share/logstash/logstash-core/lib/logstash/api/modules/base.rb:43:in `initialize'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sinatra-2.2.0/lib/sinatra/base.rb:1537:in `new'", "/usr/share/logstash/logstash-core/lib/logstash/api/rack_app.rb:113:in `block in app'", "org/jruby/RubyBasicObject.java:2622:in `instance_eval'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rack-2.2.3/lib/rack/builder.rb:125:in `initialize'", "/usr/share/logstash/logstash-core/lib/logstash/api/rack_app.rb:101:in `app'", "/usr/share/logstash/logstash-core/lib/logstash/webserver.rb:123:in `initialize'", "/usr/share/logstash/logstash-core/lib/logstash/webserver.rb:74:in `from_settings'", "/usr/share/logstash/logstash-core/lib/logstash/agent.rb:76:in `initialize'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:533:in `create_agent'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:424:in `execute'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-1.0.1/lib/clamp/command.rb:68:in `run'", "/usr/share/logstash/logstash-core/lib/logstash/runner.rb:291:in `run'", "/usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/clamp-1.0.1/lib/clamp/command.rb:133:in `run'", "/usr/share/logstash/lib/bootstrap/environment.rb:93:in `<main>'"]}
[2022-02-16T15:57:07,987][FATAL][org.logstash.Logstash    ] Logstash stopped processing because of an error: (SystemExit) exit
org.jruby.exceptions.SystemExit: (SystemExit) exit
	at org.jruby.RubyKernel.exit(org/jruby/RubyKernel.java:747) ~[jruby-complete-9.2.20.1.jar:?]
	at org.jruby.RubyKernel.exit(org/jruby/RubyKernel.java:710) ~[jruby-complete-9.2.20.1.jar:?]
	at usr.share.logstash.lib.bootstrap.environment.<main>(/usr/share/logstash/lib/bootstrap/environment.rb:94) ~[?:?]

[cherweg]

Looks like an configuration issue. Could you please provide your pipeline Config?

regards Christian

[richard-mauri]

@cherweg Did you try the reproduction steps?

Do you not notice that the Dockerfile encapsulated default configs and the only addition is adding this plugin?

If you want you can docker exec -it into the container and view the default configs.

[richard-mauri]

I STRONGLY advise using docker build --no-cache (as a docker build will not rebuild the layer installing the plugin) I had local vs jenkins diffs caused by local docker cache picking up "old" layers. Once I docker pruned then local results matched jenkins results (logstash cannot start!)

[cherweg]

I‘ll reproduce and analyze … maybe today evening.

regards

[richard-mauri]

Elastic support shared this: https://github.com/elastic/logstash/issues/13777#issuecomment-1041558020

[richard-mauri]

My take is that ALL versions of logstash that use plugins (not just this one) are broken.

Does elastic.co even test?

Here's a reply from elastic support:

Got response from dev and it turns out a known issue, invoking the plugin manager to install any plugin is pulling in an updated Sinatra that cannot start on Jruby. 
We have pinned the offending Sinatra library on the 7.17, 8.0, and 8.1 branches, which means that the upcoming releases 7.17.1, 8.0.1, and 8.1.0 will all include a version of Sinatra that doesn't have this problem.
The Comment in https://github.com/elastic/logstash/issues/13777#issuecomment-1041558020 showed how to restore LS into a working state .

[houserx-dan]

I have the same issue, i believe this started with the new logstash-mixin-aws release. I have a working AMI that is running logstash-mixin-aws 5.0.0 and logstash-input-s3-sns-sqs 2.1.3, but if I run logstash-plugin update or install it immediately breaks with the same error show above.

[Park-minkyu]

we have exactly same issue, are we expecting new patches coming up?

[richard-mauri]

Am I the only one that thinks Elasrtic is unclear what semantic versioning means? We are using logstash 7.16.2 and they will not provide a patch except for 7.17.x and 8.x They changed the Dockerfile FROM to Ubuntu in 7.17.0, so in order to get the upcoming fix I have to port to Ubuntu. The releaes notes for 7.17.0 mention the change to Ubuntu; To me that is a breaking major change that should be in 8.x. (but is a moot point now)

Also, I wonder what other dependencies are not locked down in logstash core. They will lock down the Sinatra dependency, but what other landmines are there?

[yaauie]

The Logstash plugin manager uses Bundler to modify the Logstash installation itself in order to build and install a dependency graph that satisfies all of the transitive dependencies of itself and its plugins. This is a fundamentally grey area, as bundler cannot know at Logstash release time what the dependency graph for plugins will look like at a later date. We pin things somewhat optimistically, and review changes as part of the release process before locking in what ships with each Logstash release. Clearly, this can have problems when third-parties release artifacts of things we depend on after we release. I have filed an issue on Logstash core to chase down being less optimistic about unrelated dependencies when installing plugins (https://github.com/elastic/logstash/issues/13789).

As to why this particular issue happened: by installing this (or any other) plugin, your Logstash installation picked up a minor bump of Sinatra from the 2.x version that was tested (such as 2.1.0 with Logstash 7.16.2) to 2.2.0 that was released yesterday. Unfortunately, while Sinatra does commit to semantic versioning, and this change was semantically a minor change for Sinatra, it surfaced a bug that fundamentally broke it when running in the JRuby runtime. We have reported the bug upstream to both Sinatra (https://github.com/sinatra/sinatra/issues/1749) and JRuby (https://github.com/jruby/jruby/issues/7102), and reduced the optimism with which we pin Sinatra until it is resolved.

Additionally, the following patch can be applied to an installation that has been modified to include the offending Sinatra 2.2.0, to include a proposed fix for upstream Sinatra (https://github.com/sinatra/sinatra/pull/1750):

diff --git a/vendor/bundle/jruby/2.5.0/gems/sinatra-2.2.0/lib/sinatra/base.rb b/vendor/bundle/jruby/2.5.0/gems/sinatra-2.2.0/lib/sinatra/base.rb
index 6ced0a6..986fe45 100644
--- a/vendor/bundle/jruby/2.5.0/gems/sinatra-2.2.0/lib/sinatra/base.rb
+++ b/vendor/bundle/jruby/2.5.0/gems/sinatra-2.2.0/lib/sinatra/base.rb
@@ -1533,10 +1533,11 @@ module Sinatra
       # Create a new instance of the class fronted by its middleware
       # pipeline. The object is guaranteed to respond to #call but may not be
       # an instance of the class new was called on.
-      def new(*args, **kwargs, &bk)
-        instance = new!(*args, **kwargs, &bk)
+      def new(*args, &bk)
+        instance = new!(*args, &bk)
         Wrapper.new(build(instance).to_app, instance)
       end
+      ruby2_keywords :new if respond_to?(:ruby2_keywords, true)
 
       # Creates a Rack::Builder instance with all the middleware set up and
       # the given +app+ as end point.

[richard-mauri]

Thank you @yaauie for this comprehensive analysis and resolution initiative.

I still have an unsettled concern, that may be shared by other elastic logstash customers using/relying on "immutable infrastructure" and want to reduce risk and disruption.

In my case, this bug surfaced quickly, because our CI/CD system operates many times a day and the docker build of our logstash image happens regardless of the nature of the change that triggered the build.

This frequent and simplistic image building is not strictly necessary when the change is, for example, adding client logstash test case. I certainly can eliminate the image building in that scenario.

However, there are other scenarios that do demand an image rebuild and I think there are two categories of these where one is build with the intention to simply change like a logstash pipeline config file, and the other is like to add a new plugin or other large change.

I want to essentially reuse, a prior qualified by me, dependency graph when I assert it is safe to do so.

Ideally, a build directive to help control the dependency graph analysis would be provided. It would be great if the dependecy graph metadata could be captured by the core and surfaced and later provided, in subsequent builds so as to reduce the risk of unwanted changes disrupting the enterprise.

Could this be considered?

[christianherweg0807]

Hey everyone, in my opinion optimistic version locking is the correct way to deploy needed changes in the lib supply chain fast. (--> see aws-sdk in logstash mixin) I´ve tested a quick fix, wich locks down the sinatra version. @@ -23,6 +23,7 @@ Gem::Specification.new do |s|

   s.add_runtime_dependency 'logstash-mixin-aws', '>= 4.3'
+  s.add_runtime_dependency 'sinatra', '>= 2.0.0', '< 2.2.0'

It works only if you have a fresh version of logstash without installed dependencys, but breaks if there is sinatra 2.2.0 already installed.

[christianherweg0807]

But as you can see elastic fixed it by pinning sinatra, too: https://github.com/elastic/logstash/commit/07068ae0481516c1e322a7ade951bd131651e53a

to "repair" your dependecy to sinatra you could do something like:

cd logstash-7.16.2  
perl -i -pe 's/(sinatra.*)\x27~>\s+2\x27/$1 \x27~> 2.1.0\x27/g' $(find . -type f -name "logstash-core.gemspec")  
rm Gemfile.lock  
./bin/ruby $(./bin/ruby -S gem env gemdir 2>&1 | grep /vendor/bundle)/bin/bundle update  
./bin/ruby $(./bin/ruby -S gem env gemdir 2>&1 | grep /vendor/bundle)/bin/bundle

regards christian

[yaauie]

optimistic version locking is the correct way to deploy needed changes in the lib supply chain fast -- @christianherweg0807

I absolutely agree. As a plugin mantainer you also shouldn't need to pin dependencies of things that aren't actually dependencies of your plugin.

But the Logstash plugin manager doesn't need to optimistically update unrelated dependencies by default. It would be best if our community could rely on the Logstash team to ship artifacts whose dependency graph has been extensively tested, and for that graph to not be modified unnecessarily by the plugin manager. We have filed elastic/logstash#13789 to chase that down, and have a PR in flight to make the behaviour configurable.

I have also personally validated a fix from upstream Sinatra, with a patch available here to in-place "repair" Sinatra 2.2.0 after it has been installed: https://github.com/sinatra/sinatra/pull/1750#issuecomment-1042535369

---

@richard-mauri it is perhaps worth taking your concerns over to elastic/logstash#13789 were we discuss how optimistic we are willing to be about unrelated dependencies when the plugin manager is invoking bundler to install plugins by name; alternately, feel free to rope me in on a separate issue on Logstash core. I agree that this isn't currently an experience that is easy for a user to reason about, and that is a bug.

If immutable infrastructure is your goal, Logstash also supports offline plugin packs which (a) contain only the explicitly-named plugins and their dependencies and (b) fail to install if those dependencies don't mesh with the dependency graph of what is already installed. That way you can validate the plugin's behaviour with a specific set of versioned dependencies, distribute that set, and not rely on dependency resolution at container launch-time.

As to the separately-listed concerns about the base image being changed out, we certainly hear you and we didn't make the decision lightly. With CentOS changing positions from being a stable downstream build of RHEL to effectively its "experimental upstream", along-side the RHEL/CentOS End-of-Life policies, we needed to ensure that we can continue to produce our artifacts with CVE's in the underlying OS addressed in a timely manner for the duration of our 7.x maintenance window. If there are things we can do to make that transition less painful for you, please let us know on Logstash core.