elastic / logstash

Logstash - transport and process your logs, events, or other data
https://www.elastic.co/products/logstash
Other
106 stars 3.51k forks source link

NullPointerException upon inequality operators on inexistant fields #11917

Open colinsurprenant opened 4 years ago

colinsurprenant commented 4 years ago

This is a reboot of #10706

Reproduction

$ bin/logstash -e 'filter{if [a] >= 0 { mutate { add_tag => ["foo"]}}}'
[2020-05-22T10:30:18,188][ERROR][org.logstash.execution.WorkerLoop][main] Exception in pipelineworker, the pipeline stopped processing new events, please check your filter configuration and restart Logstash.
java.lang.NullPointerException: null
    at org.logstash.config.ir.compiler.EventCondition$Compiler$UnexpectedTypeException.<init>(EventCondition.java:679) ~[logstash-core.jar:?]
    at org.logstash.config.ir.compiler.EventCondition$Compiler.compare(EventCondition.java:453) ~[logstash-core.jar:?]
    at org.logstash.config.ir.compiler.EventCondition$Compiler.lambda$compareFieldToConstant$11(EventCondition.java:444) ~[logstash-core.jar:?]
    at org.logstash.config.ir.compiler.Utils.filterEvents(Utils.java:47) ~[logstash-core.jar:?]
    at org.logstash.generated.CompiledDataset0.compute(Unknown Source) ~[?:?]
    at org.logstash.generated.CompiledDataset1.compute(Unknown Source) ~[?:?]
    at org.logstash.generated.CompiledDataset2.compute(Unknown Source) ~[?:?]
    at org.logstash.config.ir.CompiledPipeline$CompiledUnorderedExecution.compute(CompiledPipeline.java:339) ~[logstash-core.jar:?]
    at org.logstash.config.ir.CompiledPipeline$CompiledUnorderedExecution.compute(CompiledPipeline.java:333) ~[logstash-core.jar:?]
    at org.logstash.execution.WorkerLoop.run(WorkerLoop.java:83) [logstash-core.jar:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(JavaMethod.java:426) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.javasupport.JavaMethod.invokeDirect(JavaMethod.java:293) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.java.invokers.InstanceMethodInvoker.call(InstanceMethodInvoker.java:24) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.java.invokers.InstanceMethodInvoker.call(InstanceMethodInvoker.java:86) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:207) [jruby-complete-9.2.11.1.jar:?]
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.RUBY$block$start_workers$5(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:278) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:138) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:58) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:52) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.runtime.Block.call(Block.java:139) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.RubyProc.call(RubyProc.java:318) [jruby-complete-9.2.11.1.jar:?]
    at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105) [jruby-complete-9.2.11.1.jar:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
warning: thread "[main]>worker0" terminated with exception (report_on_exception is true):
java.lang.IllegalStateException: java.lang.NullPointerException
    at org.logstash.execution.WorkerLoop.run(org/logstash/execution/WorkerLoop.java:105)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(jdk/internal/reflect/NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(jdk/internal/reflect/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:566)
    at org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:426)
    at org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:293)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.start_workers(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:278)
    at org.jruby.RubyProc.call(org/jruby/RubyProc.java:318)
    at java.lang.Thread.run(java/lang/Thread.java:834)
Caused by: java.lang.NullPointerException
    at org.logstash.config.ir.compiler.EventCondition$Compiler$UnexpectedTypeException.<init>(EventCondition.java:679)
    at org.logstash.config.ir.compiler.EventCondition$Compiler.compare(EventCondition.java:453)
    at org.logstash.config.ir.compiler.EventCondition$Compiler.lambda$compareFieldToConstant$11(EventCondition.java:444)
    at org.logstash.config.ir.compiler.Utils.filterEvents(Utils.java:47)
    at org.logstash.generated.CompiledDataset0.compute(Unknown Source)
    at org.logstash.generated.CompiledDataset1.compute(Unknown Source)
    at org.logstash.generated.CompiledDataset2.compute(Unknown Source)
    at org.logstash.config.ir.CompiledPipeline$CompiledUnorderedExecution.compute(CompiledPipeline.java:339)
    at org.logstash.config.ir.CompiledPipeline$CompiledUnorderedExecution.compute(CompiledPipeline.java:333)
    at org.logstash.execution.WorkerLoop.run(WorkerLoop.java:83)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(JavaMethod.java:426)
    at org.jruby.javasupport.JavaMethod.invokeDirect(JavaMethod.java:293)
    at org.jruby.java.invokers.InstanceMethodInvoker.call(InstanceMethodInvoker.java:24)
    at org.jruby.java.invokers.InstanceMethodInvoker.call(InstanceMethodInvoker.java:86)
    at org.jruby.ir.targets.InvokeSite.invoke(InvokeSite.java:207)
    at Users.colin.dev.src.elasticsearch.logstash.logstash_minus_core.lib.logstash.java_pipeline.RUBY$block$start_workers$5(/Users/colin/dev/src/elasticsearch/logstash/logstash-core/lib/logstash/java_pipeline.rb:278)
    at org.jruby.runtime.CompiledIRBlockBody.callDirect(CompiledIRBlockBody.java:138)
    at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:58)
    at org.jruby.runtime.IRBlockBody.call(IRBlockBody.java:52)
    at org.jruby.runtime.Block.call(Block.java:139)
    at org.jruby.RubyProc.call(RubyProc.java:318)
    at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:105)
    at java.base/java.lang.Thread.run(Thread.java:834)

Proposal

IMO simply crashing the pipeline is the worst case scenario and is not acceptable. We already support that a[inexistent field] == value is always false and [inexistent field] != value is always true and by that we have accepted to give meaning to an inexistent field.

In that same logic I suggest we always return false for <, <=, >, >= operators against an inexistent field. This behaviour could be controlled with a flag but when disabled I suggest we raise a ConditionalException we could trap higher up and tag the event and/or log the conditional failure and move on.

Workaround

Avoid performing unguarded comparisons by checking to ensure a value exists before comparing it.

Instead of if [somefield] > 1 { ... }, do if [somefield] and [somefield] > 1 { ... }

predogma commented 4 years ago

Is there any update on when this may be corrected? It has been reported in the 7.9 version as well.

colinsurprenant commented 3 years ago

@jsvd WDYT?

jsvd commented 3 years ago

In that same logic I suggest we always return false for <, <=, >, >= operators against an inexistent field. This behaviour could be controlled with a flag but when disabled I suggest we raise a ConditionalException we could trap higher up and tag the event and/or log the conditional failure and move on.

Conditional expressions such as missing_field != 0 or missing_field not in [tags] are useful because you can rely on them make sense even in the absence of the fields. For example:

if [deployment_environment] == "prod" {
  elasticsearch { }
}

In this case we're confident about the data being sent to production: we only write to ES if the field is there and has the expected value. If the value is different, or nonexistent, then the conditional is false.

While in the case of greater/less than operators, we can make bad judgements by defaulting to false:

# log warn(4) info(3) debug (2) and trace(1) to file
if [log_level] <= 4 {
  file { path => /tmp/log }
} else { # send error(5) to production
  pagerduty {}
}

In this case if the field is missing we hit the else clause and flood pagerduty with potential garbage.

Avoid performing unguarded comparisons by checking to ensure a value exists before comparing it. Instead of if [somefield] > 1 { ... }, do if [somefield] and [somefield] > 1 { ... }

An added note is that if you're writing if [somefield] > 1 { } else { }, then the safe workaround needs to be:

if [somefield] {
  if [somefield] > 1 {
     ...
  } else {
     ...
  }
}

Until we can ship data that can't be evaluated correctly to the DLQ, I wonder if we can find other user experiences instead of evaluating the conditional to false. One alternative would be to skip that conditional altogether, adding the event instead to the batch that exits the conditional, with an extra tag or metadata added to it. Any other ideas?

RubieV commented 3 years ago

@jsvd I'm replying here as I do agree @colinsurprenant has the stronger argument: crashing the application for a single event is the worst case scenario.

Alternatives are:

The motto for the community is: If a newbie has a bad time, it's a bug.. This makes it easy to make a decision.

bakennedy commented 2 years ago

Having just hit this bug by crashing our staging logstash, as a newbie logging the missing field would be much appreciated 🙏 Even just logging that this error was the cause and crashing would be a substantial improvement.

pskopnik commented 2 years ago

We also hit this problem and found it rather disturbing that such a situation triggers a full crash of the Logstash instance, leading to the log line going missing and Logstash potentially being down for some time during restarts. In addition, the exception message reveals nothing about the cause.

if [log_level] <= 4 {
  file { path => /tmp/log }
} else { # send error(5) to production
  pagerduty {}
}

IMO, evaluating such a comparison to false while also skipping all else (and else-if) blocks and adding a special tag is the best approach to the situation. However, I find it difficult to argue that this is definitely more clear than evaluating the comparison to false. And there may be a bigger chunk of implementation work required, as skipping conditionals is not how if-else-if-else blocks usually work.