Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

It is possible for plugin alias support to emit NPE #13666

Closed
yaauie opened this issue Jan 20, 2022 · 4 comments
Closed

It is possible for plugin alias support to emit NPE #13666

yaauie opened this issue Jan 20, 2022 · 4 comments

Comments

@yaauie
Copy link
Member

yaauie commented Jan 20, 2022

Encountered this in a CI run of integration tests:

11:20:06     Failures:
11:20:06 
11:20:06       1) Read configuration from elasticsearch should immediately register a new pipeline state document when the pipeline is reloaded
11:20:06          Failure/Error:
11:20:06            @logstash_service = logstash("bin/logstash -w 1", {
11:20:06              :settings => {
11:20:06                "xpack.management.enabled" => true,
11:20:06                "xpack.management.pipeline.id" => @pipelines.keys + ["*"],
11:20:06                "xpack.management.logstash.poll_interval" => "1s",
11:20:06                "xpack.management.elasticsearch.hosts" => ["http://localhost:9200"],
11:20:06                "xpack.management.elasticsearch.username" => "elastic",
11:20:06                "xpack.management.elasticsearch.password" => elastic_password,
11:20:06                "xpack.monitoring.elasticsearch.username" => "elastic",
11:20:06                "xpack.monitoring.elasticsearch.password" => elastic_password
11:20:06          
11:20:06          Belzebuth::ExecutionTimeout:
11:20:06            `bin/logstash -w 1 --path.settings /tmp/studtmp-eedf4dd539497bb909e5fac346c34d5bbbb14b191a179ccf2012882df3fd --path.data /tmp/studtmp-5acf882511e3316848b0bbd4d7aaa25576e382dd9afa16f82f941e39e107` took too much time to execute (timeout: 300) Reponse: 
11:20:06            stdout:
11:20:06            [2022-01-20T19:06:49,739][WARN ][logstash.configmanagement.elasticsearchsource] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>8}
11:20:06          
11:20:06            [2022-01-20T19:06:51,023][INFO ][org.reflections.Reflections] Reflections took 171 ms to scan 1 urls, producing 119 keys and 416 values 
11:20:06          
11:20:06            [2022-01-20T19:06:51,029][ERROR][logstash.agent           ] Failed to execute action {:action=>LogStash::PipelineAction::Create/pipeline_id:.monitoring-logstash, :exception=>"Java::JavaLang::NullPointerException", :message=>"Inflater has been closed", :backtrace=>["java.base/java.util.zip.Inflater.ensureOpen(Inflater.java:740)", "java.base/java.util.zip.Inflater.inflate(Inflater.java:377)", "java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:153)", "java.base/java.io.FilterInputStream.read(FilterInputStream.java:133)", "java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)", "java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)", "java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)", "java.base/java.io.InputStreamReader.read(InputStreamReader.java:181)", "java.base/java.io.Reader.read(Reader.java:189)", "java.base/java.util.Scanner.readInput(Scanner.java:882)", "java.base/java.util.Scanner.findWithinHorizon(Scanner.java:1796)", "java.base/java.util.Scanner.nextLine(Scanner.java:1649)", "org.logstash.plugins.AliasRegistry$YamlWithChecksum.load(AliasRegistry.java:69)", "org.logstash.plugins.AliasRegistry$YamlWithChecksum.access$100(AliasRegistry.java:64)", "org.logstash.plugins.AliasRegistry$AliasYamlLoader.loadAliasesDefinitionsFromInputStream(AliasRegistry.java:134)", "org.logstash.plugins.AliasRegistry$AliasYamlLoader.loadAliasesDefinitions(AliasRegistry.java:130)", "org.logstash.plugins.AliasRegistry.<init>(AliasRegistry.java:179)", "org.logstash.plugins.factory.PluginFactoryExt.<init>(PluginFactoryExt.java:86)", "org.logstash.execution.JavaBasePipelineExt.initialize(JavaBasePipelineExt.java:73)", "org.logstash.execution.JavaBasePipelineExt$INVOKER$i$1$0$initialize.call(JavaBasePipelineExt$INVOKER$i$1$0$initialize.gen)", "org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:837)", "org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuper(IRRuntimeHelpers.java:1169)", "org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuperSplatArgs(IRRuntimeHelpers.java:1156)", "org.jruby.ir.targets.InstanceSuperInvokeSite.invoke(InstanceSuperInvokeSite.java:39)", "opt.logstash.logstash_minus_core.lib.logstash.java_pipeline.RUBY$method$initialize$0(/opt/logstash/logstash-core/lib/logstash/java_pipeline.rb:47)", "org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:80)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:70)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:333)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:87)", "org.jruby.RubyClass.newInstance(RubyClass.java:939)", "org.jruby.RubyClass$INVOKER$i$newInstance.call(RubyClass$INVOKER$i$newInstance.gen)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:333)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:87)", "org.jruby.ir.instructions.CallBase.interpret(CallBase.java:549)", "org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:361)", "org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)", "org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:92)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:191)", "org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:178)", "org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:208)", "opt.logstash.logstash_minus_core.lib.logstash.agent.RUBY$block$converge_state$2(/opt/logstash/logstash-core/lib/logstash/agent.rb:376)", "org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:138)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:58)", "org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:52)", "org.jruby.runtime.Block.call(Block.java:139)", "org.jruby.RubyProc.call(RubyProc.java:318)", "org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)", "java.base/java.lang.Thread.run(Thread.java:829)"]}
11:20:06          
11:20:06            [2022-01-20T19:06:51,044][ERROR][logstash.agent           ] An exception happened when converging configuration {:exception=>LogStash::Error, :message=>"Don't know how to handle `Java::JavaLang::NullPointerException` for `PipelineAction::Create<.monitoring-logstash>`"}
11:20:06          
11:20:06            [2022-01-20T19:06:52,321][FATAL][logstash.runner          ] An unexpected error occurred! {:error=>#<LogStash::Error: Don't know how to handle `Java::JavaLang::NullPointerException` for `PipelineAction::Create<.monitoring-logstash>`>, :backtrace=>["org/logstash/execution/ConvergeResultExt.java:135:in `create'", "org/logstash/execution/ConvergeResultExt.java:60:in `add'", "/opt/logstash/logstash-core/lib/logstash/agent.rb:389:in `block in converge_state'"]}
11:20:06          
11:20:06            [2022-01-20T19:06:52,364][FATAL][org.logstash.Logstash    ] Logstash stopped processing because of an error: (SystemExit) exit
11:20:06          
11:20:06            org.jruby.exceptions.SystemExit: (SystemExit) exit
11:20:06          
11:20:06            	at org.jruby.RubyKernel.exit(org/jruby/RubyKernel.java:747) ~[jruby-complete-9.2.20.1.jar:?]
11:20:06          
11:20:06            	at org.jruby.RubyKernel.exit(org/jruby/RubyKernel.java:710) ~[jruby-complete-9.2.20.1.jar:?]
11:20:06          
11:20:06            	at opt.logstash.lib.bootstrap.environment.<main>(/opt/logstash/lib/bootstrap/environment.rb:94) ~[?:?]
11:20:06          
11:20:06            stderr
11:20:06            OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
11:20:06          
11:20:06            warning: thread "Converge PipelineAction::Create<.monitoring-logstash>" terminated with exception (report_on_exception is true):
11:20:06          
11:20:06            LogStash::Error: Don't know how to handle `Java::JavaLang::NullPointerException` for `PipelineAction::Create<.monitoring-logstash>`
11:20:06          
11:20:06                      create at org/logstash/execution/ConvergeResultExt.java:135
11:20:06          
11:20:06                         add at org/logstash/execution/ConvergeResultExt.java:60
11:20:06          
11:20:06              converge_state at /opt/logstash/logstash-core/lib/logstash/agent.rb:389
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/belzebuth-0.2.3/lib/belzebuth/process.rb:63:in `block in run'
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/bundler-2.3.5/lib/bundler.rb:394:in `block in with_clean_env'
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/bundler-2.3.5/lib/bundler.rb:698:in `with_env'
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/bundler-2.3.5/lib/bundler.rb:394:in `with_clean_env'
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/belzebuth-0.2.3/lib/belzebuth/process.rb:47:in `run'
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/belzebuth-0.2.3/lib/belzebuth/process.rb:30:in `run'
11:20:06          # ./qa/integration/support/helpers.rb:165:in `logstash_with_empty_default'
11:20:06          # ./qa/integration/support/helpers.rb:150:in `logstash'
11:20:06          # ./qa/integration/management/multiple_pipelines_spec.rb:28:in `block in <main>'
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/rspec-wait-0.0.9/lib/rspec/wait.rb:46:in `block in <main>'
11:20:06          # /opt/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-devutils-2.3.0-java/lib/logstash/devutils/rspec/spec_helper.rb:61:in `block in <main>'
11:20:06          # /opt/logstash/lib/bootstrap/rspec.rb:31:in `<main>'
11:20:06 
@andsel
Copy link
Contributor

andsel commented Mar 28, 2022

Looking at the stack trace

java.base/java.util.zip.Inflater.ensureOpen(Inflater.java:740)
java.base/java.util.zip.Inflater.inflate(Inflater.java:377)
java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:153)
java.base/java.io.FilterInputStream.read(FilterInputStream.java:133)
java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
java.base/java.io.InputStreamReader.read(InputStreamReader.java:181)
java.base/java.io.Reader.read(Reader.java:189)
java.base/java.util.Scanner.readInput(Scanner.java:882)
java.base/java.util.Scanner.findWithinHorizon(Scanner.java:1796)
java.base/java.util.Scanner.nextLine(Scanner.java:1649)
org.logstash.plugins.AliasRegistry$YamlWithChecksum.load(AliasRegistry.java:69)
org.logstash.plugins.AliasRegistry$YamlWithChecksum.access$100(AliasRegistry.java:64)
org.logstash.plugins.AliasRegistry$AliasYamlLoader.loadAliasesDefinitionsFromInputStream(AliasRegistry.java:134)
org.logstash.plugins.AliasRegistry$AliasYamlLoader.loadAliasesDefinitions(AliasRegistry.java:130)
org.logstash.plugins.AliasRegistry.<init>(AliasRegistry.java:179)
org.logstash.plugins.factory.PluginFactoryExt.<init>(PluginFactoryExt.java:86)
org.logstash.execution.JavaBasePipelineExt.initialize(JavaBasePipelineExt.java:73)
org.logstash.execution.JavaBasePipelineExt$INVOKER$i$1$0$initialize.call(JavaBasePipelineExt$INVOKER$i$1$0$initialize.gen)
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:837)
org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuper(IRRuntimeHelpers.java:1169)
org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuperSplatArgs(IRRuntimeHelpers.java:1156)
org.jruby.ir.targets.InstanceSuperInvokeSite.invoke(InstanceSuperInvokeSite.java:39)
opt.logstash.logstash_minus_core.lib.logstash.java_pipeline.RUBY$method$initialize$0(/opt/logstash/logstash-core/lib/logstash/java_pipeline.rb:47)
org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:80)
org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:70)
org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:333)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:87)
org.jruby.RubyClass.newInstance(RubyClass.java:939)
org.jruby.RubyClass$INVOKER$i$newInstance.call(RubyClass$INVOKER$i$newInstance.gen)
org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:333)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:87)
org.jruby.ir.instructions.CallBase.interpret(CallBase.java:549)
org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:361)
org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:72)
org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:92)
org.jruby.internal.runtime.methods.MixedModeIRMethod.INTERPRET_METHOD(MixedModeIRMethod.java:191)
org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:178)
org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:208)
opt.logstash.logstash_minus_core.lib.logstash.agent.RUBY$block$converge_state$2(/opt/logstash/logstash-core/lib/logstash/agent.rb:376)
org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:138)
org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:58)
org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:52)
org.jruby.runtime.Block.call(Block.java:139)
org.jruby.RubyProc.call(RubyProc.java:318)
org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)
java.base/java.lang.Thread.run(Thread.java:829)

the alias loader encounter the problem when it tries to load the yaml file (YamlWithChecksum.load) from the class path, the file is located in the resource org/logstash/plugins/plugin_aliases.yml.
The opening of the resource happens at

final String filePath = "org/logstash/plugins/plugin_aliases.yml";
final InputStream in = AliasYamlLoader.class.getClassLoader().getResourceAsStream(filePath);
if (in == null) {
LOGGER.warn("Malformed yaml file in yml definition file in jar resources: {}", filePath);
return Collections.emptyMap();
}
return loadAliasesDefinitionsFromInputStream(in);
.

So it meas that the jar file containing the resource file is closed after the alias loader got a reference to it but before it started to read.
WDYT?

@andsel andsel self-assigned this Mar 28, 2022
robbavey added a commit to robbavey/logstash that referenced this issue Apr 19, 2022
The current implementation of AliasRegistry will create an instance of the Alias Registry for each
pipeline, which appears to potentially result in situations, such as in elastic#13996, where multiple pipelines
are simultaneously loading an alias registry from a yaml file in the jar file using getResourceAsStream, with
the potential of the first thread closing the jar file underneath subsequent threads, leading to errors when
reading the yaml file as the JarFile has been closed after the initial thread completed accessing.

This commit changes the AliasRegistry to be a singleton, as is the PluginRegistry.

Relates: elastic#13996, elastic#13666
robbavey added a commit to robbavey/logstash that referenced this issue Apr 19, 2022
The current implementation of AliasRegistry will create an instance of the Alias Registry for each
pipeline, which appears to potentially result in situations, such as in elastic#13996, where multiple pipelines
are simultaneously loading an alias registry from a yaml file in the jar file using getResourceAsStream, with
the potential of the first thread closing the jar file underneath subsequent threads, leading to errors when
reading the yaml file as the JarFile has been closed after the initial thread completed accessing.

This commit changes the AliasRegistry to be a singleton, as is the PluginRegistry.

Relates: elastic#13996, elastic#13666
robbavey added a commit to robbavey/logstash that referenced this issue Apr 19, 2022
The current implementation of AliasRegistry will create an instance of the Alias Registry for each
pipeline, which appears to potentially result in situations, such as in elastic#13996, where multiple pipelines
are simultaneously loading an alias registry from a yaml file in the jar file using getResourceAsStream, with
the potential of the first thread closing the jar file underneath subsequent threads, leading to errors when
reading the yaml file as the JarFile has been closed after the initial thread completed accessing.

This commit changes the AliasRegistry to be a singleton, as is the PluginRegistry.

Relates: elastic#13996, elastic#13666
robbavey added a commit to robbavey/logstash that referenced this issue Apr 19, 2022
The current implementation of AliasRegistry will create an instance of the Alias Registry for each
pipeline, which appears to potentially result in situations, such as in elastic#13996, where multiple pipelines
are simultaneously loading an alias registry from a yaml file in the jar file using getResourceAsStream, with
the potential of the first thread closing the jar file underneath subsequent threads, leading to errors when
reading the yaml file as the JarFile has been closed after the initial thread completed accessing.

This commit changes the AliasRegistry to be a singleton, as is the PluginRegistry.

Relates: elastic#13996, elastic#13666
@andsel
Copy link
Contributor

andsel commented Apr 20, 2022

Looking around for this I discovered:

The suspect is that loading the aliases definitions from multiple threads could be the problem of concurrent closes of the zipped input stream.

Possible solution are:

  • synchronize the access to AliasYamlLoader methods
  • transform AliasRegistry in a singleton, with the instantiation wrapped by a syncronize (this is part of standard singleton implementation)
  • use an URLConnection to access the yaml resource file but disabling cache with connection.setUseCaches(false);

I think the best is the second one, but before a multithreaded unit test has to be create to proof it's a concurrency problem related to the close of the resource.

robbavey added a commit that referenced this issue Apr 26, 2022
* Make AliasRegistry a singleton

The current implementation of AliasRegistry will create an instance of the Alias Registry for each
pipeline, which appears to potentially result in situations, such as in #13996, where multiple pipelines
are simultaneously loading an alias registry from a yaml file in the jar file using getResourceAsStream, with
the potential of the first thread closing the jar file underneath subsequent threads, leading to errors when
reading the yaml file as the JarFile has been closed after the initial thread completed accessing.

This commit changes the AliasRegistry to be a singleton, as is the PluginRegistry.

Relates: #13996, #13666

* Update reflections library to 0.9.12 to avoid multi threading bug

Earlier versions of the reflections library used in the plugin registry would
use caches on JarUrlConnection, which when closed would also close the jar file
for other resources using it, such as the AliasRegistry. This, combined with the
fact that the AliasRegistry could be created simultaneously by many threads/pipelines
could cause issues during AliasRegistry creation leading to failure to create a
pipeline.

* Avoid use of URLConnection caching when getting alias yaml resource
* Use idiomatic ruby when accessing Java getInstance method

Co-authored-by: Andrea Selva <selva.andre@gmail.com>
github-actions bot pushed a commit that referenced this issue Apr 26, 2022
* Make AliasRegistry a singleton

The current implementation of AliasRegistry will create an instance of the Alias Registry for each
pipeline, which appears to potentially result in situations, such as in #13996, where multiple pipelines
are simultaneously loading an alias registry from a yaml file in the jar file using getResourceAsStream, with
the potential of the first thread closing the jar file underneath subsequent threads, leading to errors when
reading the yaml file as the JarFile has been closed after the initial thread completed accessing.

This commit changes the AliasRegistry to be a singleton, as is the PluginRegistry.

Relates: #13996, #13666

* Update reflections library to 0.9.12 to avoid multi threading bug

Earlier versions of the reflections library used in the plugin registry would
use caches on JarUrlConnection, which when closed would also close the jar file
for other resources using it, such as the AliasRegistry. This, combined with the
fact that the AliasRegistry could be created simultaneously by many threads/pipelines
could cause issues during AliasRegistry creation leading to failure to create a
pipeline.

* Avoid use of URLConnection caching when getting alias yaml resource
* Use idiomatic ruby when accessing Java getInstance method

Co-authored-by: Andrea Selva <selva.andre@gmail.com>
(cherry picked from commit 4e77f1b)
@andsel
Copy link
Contributor

andsel commented Apr 27, 2022

@robbavey with landing of #14002 I think we can close this, WDYT?

@robbavey
Copy link
Member

Yes, I agree. Closing

robbavey added a commit that referenced this issue May 6, 2022
* Make AliasRegistry a singleton

The current implementation of AliasRegistry will create an instance of the Alias Registry for each
pipeline, which appears to potentially result in situations, such as in #13996, where multiple pipelines
are simultaneously loading an alias registry from a yaml file in the jar file using getResourceAsStream, with
the potential of the first thread closing the jar file underneath subsequent threads, leading to errors when
reading the yaml file as the JarFile has been closed after the initial thread completed accessing.

This commit changes the AliasRegistry to be a singleton, as is the PluginRegistry.

Relates: #13996, #13666

* Update reflections library to 0.9.12 to avoid multi threading bug

Earlier versions of the reflections library used in the plugin registry would
use caches on JarUrlConnection, which when closed would also close the jar file
for other resources using it, such as the AliasRegistry. This, combined with the
fact that the AliasRegistry could be created simultaneously by many threads/pipelines
could cause issues during AliasRegistry creation leading to failure to create a
pipeline.

* Avoid use of URLConnection caching when getting alias yaml resource
* Use idiomatic ruby when accessing Java getInstance method

Co-authored-by: Andrea Selva <selva.andre@gmail.com>
(cherry picked from commit 4e77f1b)

Co-authored-by: Rob Bavey <rob.bavey@elastic.co>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants