Logstash: Bivalue error when trying to parse logs

[suyograo]

I get this un-actionable error when I try to parse the sample log with the below configuration. Can we catch such error messages and present a better user-facing one?

org.logstash.bivalues.StringBiValue cannot be cast to java.lang.String

Exception in thread "[main]>worker4" java.lang.ClassCastException: org.logstash.bivalues.StringBiValue cannot be cast to java.lang.String
    at org.logstash.Event.toString(Event.java:312)
    at org.logstash.ext.JrubyEventExtLibrary$RubyEvent.ruby_to_s(JrubyEventExtLibrary.java:209)
    at org.logstash.ext.JrubyEventExtLibrary$RubyEvent$INVOKER$i$0$0$ruby_to_s.call(JrubyEventExtLibrary$RubyEvent$INVOKER$i$0$0$ruby_to_s.gen)
    at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:306)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:136)
    at org.jruby.ast.CallNoArgNode.interpret(CallNoArgNode.java:60)
    at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
    at org.jruby.ast.CallTwoArgNode.interpret(CallTwoArgNode.java:59)
    at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
    at org.jruby.ast.IfNode.interpret(IfNode.java:118)
    at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
    at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
    at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:182)
    at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:203)
    at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
    at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
    at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
    at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
    at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
    at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:157)
    at org.jruby.runtime.Block.yield(Block.java:142)
    at org.jruby.RubyArray.eachCommon(RubyArray.java:1606)
    at org.jruby.RubyArray.each(RubyArray.java:1613)
    at org.jruby.RubyArray$INVOKER$i$0$0$e

Log line:

192.168.33.1 - - [26/Dec/2016:16:22:00 +0000] "GET / HTTP/1.1" 200 484 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.98 Safari/537.36"

Config:

input {
  stdin {}
}
filter {
   grok {
      match => { "message" => ["%{IPORHOST:apache2.access.remote_ip} - %{DATA:apache2.access.user_name} \\[%{HTTPDATE:apache2.access.time}\\] \"%{WORD:apache2.access.method} %{DATA:apache2.access.url} HTTP/%{NUMBER:apache2.access.http_version}\" %{NUMBER:apache2.access.response_code} %{NUMBER:apache2.access.body_sent.bytes}( \"%{DATA:apache2.access.referrer}\")?( \"%{DATA:apache2.access.agent}\")?", 
        "%{IPORHOST:apache2.access.remote_ip} - %{DATA:apache2.access.user_name} \\[%{HTTPDATE:apache2.access.time}\\] \"-\" %{NUMBER:apache2.access.response_code} -" ] }
      remove_field => "message"
   }
   mutate {
      rename => { "@timestamp" => "read_timestamp" }
   }
   date {
      match => [ "apache2.access.time", "dd/MMM/YYYY:H:m:s Z" ]
      remove_field => "apache2.access.time"
   }
   useragent {
      source => "apache2.access.agent"
      target => "apache2.access.user_agent"
      remove_field => "apache2.access.agent"
   }
   geoip {
      source => "apache2.access.remote_ip"
      target => "apache2.access.geoip"
   }
}
output {
  stdout {}
}

[colinsurprenant]

For some reason this did not show on my radar. Will look into this.

[colinsurprenant]

same issue reported in #7377 by @logstashbugreporter

[colinsurprenant]

So looking at this, it looks like the Event.toString() method has not been updated to use the getField() method or otherwise use the BiValue/Javafier to correctly convert Bivalue to String.
Same problem in 5.4.1 and master https://github.com/elastic/logstash/blob/0f648858ef48c2d0b912d71fa2fda9122062440f/logstash-core/src/main/java/org/logstash/Event.java#L271

[jsvd]

just a simple scenario that triggers this:

1.9 :016 > e = LogStash::Event.new("what" => "hey"); e.remove("@timestamp"); e.to_s
 => "%{host} %{message}" 
1.9 :017 > e = LogStash::Event.new("message" => "hey"); e.remove("@timestamp"); e.to_s
Java::JavaLang::ClassCastException: org.logstash.bivalues.StringBiValue cannot be cast to 

[rdsubhas]

This randomly gets triggered with some data, gets queued, and then logstash buffers everything after this but cannot read anything out of the queue, and the whole queue has to be moved away and gets lost. A pipeline blocker bug...

[DeoLeung]

Encounter the same problem, any quick workaround to avoid this? It's completely blocking

[rdsubhas]

@DeoLeung if you can add your experience to https://discuss.elastic.co/t/logstash-5-4-repeated-deserialization-errors-and-losing-data-with-persistent-queues/91503/9 maybe we can try to see how it matches...

[colinsurprenant]

Reproduced the problem in #7604 - fix incoming.

[colinsurprenant]

manual repro one-liner:

bin/logstash -e 'filter{mutate{rename => {"@timestamp" => "foo"}}} output{stdout{}}'

[colinsurprenant]

Fix is now in #7604 awaiting review, ping @suyograo @guyboertje

[colinsurprenant]

@rdsubhas while similar this is not the same issue as the discuss thread https://discuss.elastic.co/t/logstash-5-4-repeated-deserialization-errors-and-losing-data-with-persistent-queues/91503/9

@DeoLeung could you share the details of your problem to make sure it is related and will be addressed by #7604 ?

[colinsurprenant]

fixed in #7604, will be part of upcoming 5.5.1 release.

[jstoja]

hey @colinsurprenant, I'm a very similar error like this:

[2017-11-29T14:13:09,683][ERROR][logstash.pipeline        ] Exception in pipelineworker, the pipeline stopped processing new events, please check your filter configuration and restart Logstash.
...
Exception in thread "[main]>worker0" java.lang.ClassCastException: org.logstash.bivalues.StringBiValue cannot be cast to org.logstash.ConvertedList
at org.logstash.Accessors.setChild(Accessors.java:109)
at org.logstash.Accessors.set(Accessors.java:18)
at org.logstash.Event.setField(Event.java:161)                                                                                                                                                                                                                at org.logstash.ext.JrubyEventExtLibrary$RubyEvent.ruby_set_field(JrubyEventExtLibrary.java:132)
at org.logstash.ext.JrubyEventExtLibrary$RubyEvent$INVOKER$i$2$0$ruby_set_field.call(JrubyEventExtibrary$RubyEvent$INVOKER$i$2$0$ruby_set_field.gen)

I assume that the logs and filters won't help you since it's just a cast issue.
(I can open a new ticket if needed)

[colinsurprenant]

@jstoja thanks for the report - which version of LS are you using? Also, would it be possible for you to create a reproduction scenario? Thanks!

[jstoja]

Thanks for your quick answer!
I'm using Logstash 6.0.0. I think I found the source of the "error".
It seems to occur when I mutate => rename a child field when the parent field is a string.
For example: In my example below I want to rename "source" => "[log][file]" but log is a string... Hence the casting error.
I don't know if it's how it should be handled, but I assume that crashing the workers is not a desired behavior.

You have here the necessary files to reproduce https://gist.github.com/jstoja/c7a74038d8cfa34c87b565b17f7eb18f
(Sorry that it uses docker and filebeat, but that what I came down to).

[colinsurprenant]

@jstoja I moved your reported issue into https://github.com/elastic/logstash/issues/8777 - feel free to followup there.
Thanks again for your report.