Multiline filter and dateparse issue in production

Elastic Stack Logstash
1

Hi
I am using logstash-1.5.3 as indexer

my configuration is

filter{


   multiline {
     pattern => "^%{TIMESTAMP_ISO8601}"
    # negate => true
     what => previous
   }

    multiline {
     pattern => "^\s"
    # negate => true
     what => previous
   }

   grok {
         match => { "message" => "%{TIMESTAMP_ISO8601:eventLogTime}" }
   }
   date {
        match => [ "eventLogTime", "YYYY-MM-dd'T'HH:mm:ss", "YYYY-MM-dd HH:mm:ss","HH:mm:ss MMM dd yyyy","YYYY-MM-dd HH:mm:ss,SSS","yyyy-MM-dd'T'HH:mm:ss.SSSZ","yyyy-MM-dd'T'HH:mm:ss.SSSZ+0300", "yyyy-MM-dd'T'HH:mm:ss.SSSSSS+0200", "yyyy-MM-dd'T'HH:mm:ss.SSSSSZ+0200", "YYYY-MM-dd'T'HH:mm:ssZ","YYYY-MM-dd'T'HH:mm:ss.sssZ"]
        target => "eventLogTime"
   }

}

Still its showing below error continuously in logs. its debug level set for logs.

{:timestamp=>"2016-03-20T11:37:59.744000+0200", :message=>"Flushing", :plugin=><LogStash::Filters::Multiline pattern=>"^%{TIMESTAMP_ISO8601}", negate=>true, what=>"previous", periodic_flush=>true, source=>"message", allow_duplicates=>true, stream_identity=>"%{host}.%{path}.%{type}", max_age=>5>, :level=>:debug, :file=>"(eval)", :line=>"16", :method=>"initialize"}

Again it throws multiline filter error

"tags"=>["multiline", "_dateparsefailure"]}, @metadata_accessors=#<LogStash::Util::Accessors:0x40dafa2f @store={"retry_count"=>0}, @lut={}>, @cancelled=false>]]}, :batch_timeout=>1, :force=>nil, :final=>nil, :level=>:debug, :file=>"stud/buffer.rb", :line=>"207", :method=>"buffer_flush"}

Also there are errors for "\tat" pattern in logs.
please help.

thanks
Sunil

2

Why have you commented out negate => true? I'm pretty sure you need that. If that doesn't help then provide an example of the kind of log messages you want to handle.

3

Hi Magnus,
I have un-commented that part and its restarted now.
However I am getting below errros. I dont know whether negate => true reall solved that issue or still its there.

Application"=>"AppName", "Sub-System"=>"bo", "type"=>"error", "eventLogTime"=>"2016-03-21T05:28:00.341Z", "tags"=>["_dateparsefailure", "multiline"]}, @metadata_accessors=#<LogStash::Util::Accessors:0x5efcbeeb @store={}, @lut={}>, @cancelled=false>, :level=>:debug, :file=>"logstash/filters/grok.rb", :line=>"283", :method=>"filter"}
{:timestamp=>"2016-03-21T07:28:03.180000+0200", :message=>"Regexp match object", :names=>["TIMESTAMP_ISO8601:eventLogTime"], :captures=>["2016-03-21 07:28:00,341"], :level=>:debug, :file=>"grok-pure.rb", :line=>"179", :method=>"match_and_capture"}
{:timestamp=>"2016-03-21T07:28:03.181000+0200", :message=>"Event now: ", :event=>#<LogStash::Event:0x65897de7 @metadata={}, @accessors=#<LogStash::Util::Accessors:0x6ecd7609 @store={"message"=>"2016-03-21 07:28:00,341 [http-bio-8443-exec-51] [lainevi 200E9A0917FB3FC010BF5A9D502CBE99] ERROR com.tieto.its.sc.restclient.ExceptionHandlingClientFilter - Error occurred on RestClient call. Response status: 404, ReasonPhrase : 'Not Found'.\n2016-03-21 07:28:00,360 [http-bio-8443-exec-51] [lainevi 200E9A0917FB3FC010BF5A9D502CBE99] ERROR com.tieto.its.sb.service.AbstractApplicationService - Exception Trace :: ", "@version"=>"1", "@timestamp"=>"2016-03-21T05:28:03.128Z", "file"=>"/var/log/xxx/xxxERROR.log", "host"=>"hosiName", "offset"=>["48952", "49194"], "Application"=>"sales", "Sub-System"=>"bo", "type"=>"error", "eventLogTime"=>"2016-03-21T05:28:00.341Z", "tags"=>["_dateparsefailure", "multiline"]}, @lut={"message"=>[{"message"=>"2016-03-21 07:28:00,341 [http-bio-8443-exec-51] [lainevi 200E9A0917FB3FC010BF5A9D502CBE99] ERROR  

{:timestamp=>"2016-03-21T07:28:03.182000+0200", :message=>"Date filter: received event", :type=>"error", :level=>:debug, :file=>"logstash/filters/date.rb", :line=>"206", :method=>"filter"}
{:timestamp=>"2016-03-21T07:28:03.183000+0200", :message=>"Date filter looking for field", :type=>"error", :field=>"eventLogTime", :level=>:debug, :file=>"logstash/filters/date.rb", :line=>"209", :method=>"filter"}
{:timestamp=>"2016-03-21T07:28:03.187000+0200", :message=>"Failed parsing date from field", :field=>"eventLogTime", :value=>"2016-03-21T05:28:00.341Z", :exception=>"cannot convert instance of class org.jruby.RubyObject to class java.lang.String", :config_parsers=>"YYYY-MM-dd'T'HH:mm:ss,YYYY-MM-dd HH:mm:ss,HH:mm:ss MMM dd yyyy,YYYY-MM-dd HH:mm:ss,SSS,yyyy-MM-dd'T'HH:mm:ss.SSSZ,yyyy-MM-dd'T'HH:mm:ss.SSSZ+0300,yyyy-MM-dd'T'HH:mm:ss.SSSSSS+0200,yyyy-MM-dd'T'HH:mm:ss.SSSSSZ+0200,YYYY-MM-dd'T'HH:mm:ssZ,YYYY-MM-dd'T'HH:mm:ss.sssZ", :config_locale=>"default=en_US", :level=>:warn, :file=>"logstash/filters/date.rb", :line=>"242", :method=>"filter"}


{:timestamp=>"2016-03-21T07:28:03.193000+0200", :message=>"\tat $Proxy231.getServiceProviderById(Unknown Source)", :pattern=>"^%{TIMESTAMP_ISO8601}", :match=>true, :negate=>true, :level=>:debug, :file=>"logstash/filters/multiline.rb", :line=>"173", :method=>"filter"}
{:timestamp=>"2016-03-21T07:28:03.194000+0200", :message=>"filter received", :event=>{"message"=>"\tat com.mycompany.its.sb.service.impl.ProviderApplicationService.getServiceProviderById(ProviderApplicationService.java:95)", "@version"=>"1", "@timestamp"=>"2016-03-21T05:28:03.129Z", "file"=>"/filePath/salesERROR.log", "host"=>"AppName", "offset"=>"49984", "Application"=>"sales", "Sub-System"=>"bo", "type"=>"error"}, :level=>:debug, :file=>"(eval)", :line=>"657", :method=>"filter_func"}
{:timestamp=>"2016-03-21T07:28:03.195000+0200", :message=>"\tat com.myCompany.its.sb.service.impl.ProviderApplicationService.getServiceProviderById(ProviderApplicationService.java:95)", :pattern=>"^%{TIMESTAMP_ISO8601}", :match=>true, :negate=>true, :level=>:debug, :file=>"logstash/filters/multiline.rb", :line=>"173", :method=>"filter"}
{:timestamp=>"2016-03-21T07:28:03.197000+0200", :message=>"filter received", :event=>{"message"=>"\tat sun.reflect.GeneratedMethodAccessor1044.invoke(Unknown Source)", "@version"=>"1", "@timestamp"=>"2016-03-21T05:28:03.129Z", "file"=>"/filePath/salesERROR.log", "host"=>"AppName", "offset"=>"50104", "Application"=>"sales", "Sub-System"=>"bo", "type"=>"error"}, :level=>:debug, :file=>"(eval)", :line=>"657", :method=>"filter_func"}

Please check errors.

thanks
Sunil

4

Most of those are debug-level diagnostic messages and not errors. Here's what you should focus on:

{:timestamp=>"2016-03-21T07:28:03.187000+0200", :message=>"Failed parsing date from field", :field=>"eventLogTime", :value=>"2016-03-21T05:28:00.341Z", :exception=>"cannot convert instance of class org.jruby.RubyObject to class java.lang.String", :config_parsers=>"YYYY-MM-dd'T'HH:mm:ss,YYYY-MM-dd HH:mm:ss,HH:mm:ss MMM dd yyyy,YYYY-MM-dd HH:mm:ss,SSS,yyyy-MM-dd'T'HH:mm:ss.SSSZ,yyyy-MM-dd'T'HH:mm:ss.SSSZ+0300,yyyy-MM-dd'T'HH:mm:ss.SSSSSS+0200,yyyy-MM-dd'T'HH:mm:ss.SSSSSZ+0200,YYYY-MM-dd'T'HH:mm:ssZ,YYYY-MM-dd'T'HH:mm:ss.sssZ", :config_locale=>"default=en_US", :level=>:warn, :file=>"logstash/filters/date.rb", :line=>"242", :method=>"filter"}

I'm not sure what's up here. Try simplifying your configuration to narrow down where the error might be. You don't by any chance have two date filters trying to parse the same field twice?

5

Hi,
Thanks for the clue. I will get back after checking actual logs.
I have reduced log level to debug and now there are very few logs.

However, I have one more error as below. is that serious one or its just info or warn?

{:timestamp=>"2016-03-21T09:29:33.450000+0200", :message=>"Switched current elasticsearch client to #0 at <ip-address>", :level=>:debug, :file=>"logstash/outputs/elasticsearch.rb", :line=>"600", :method=>"shift_client"}
{:timestamp=>"2016-03-21T09:29:33.457000+0200", :message=>"Shifting current elasticsearch client", :level=>:debug, :file=>"logstash/outputs/elasticsearch.rb", :line=>"549", :method=>"flush"}
{:timestamp=>"2016-03-21T09:29:33.458000+0200", :message=>"Switched current elasticsearch client to #0 at <ip-address>", :level=>:debug, :file=>"logstash/outputs/elasticsearch.rb", :line=>"600", :method=>"shift_client"}
{:timestamp=>"2016-03-21T09:29:34.044000+0200", :message=>"Flushing", :plugin=><LogStash::Filters::Multiline pattern=>"^%{TIMESTAMP_ISO8601}", negate=>true, what=>"previous", periodic_flush=>true, source=>"message", allow_duplicates=>true, stream_identity=>"%{host}.%{path}.%{type}", max_age=>5>, :level=>:debug, :file=>"(eval)", :line=>"16", :method=>"initialize"}

{:timestamp=>"2016-03-21T09:29:34.045000+0200", :message=>"Flushing", :plugin=><LogStash::Filters::Multiline pattern=>"^%{TIMESTAMP_ISO8601}" negate=>true, what=>"previous", periodic_flush=>true, source=>"message", allow_duplicates=>true, stream_identity=>"%{host}.%{path}.%{type}",max_age=>5>, :level=>:debug, :file=>"(eval)", :line=>"189", :method=>"initialize"}
{:timestamp=>"2016-03-21T09:29:34.046000+0200", :message=>"Flushing", :plugin=><LogStash::Filters::Multiline pattern=>"^%{TIMESTAMP_ISO8601}" negate=>true, what=>"previous", periodic_flush=>true, source=>"message", allow_duplicates=>true, stream_identity=>"%{host}.%{path}.%{type}",max_age=>5>, :level=>:debug, :file=>"(eval)", :line=>"344", :method=>"initialize"}

br,
Sunil

6

All of those are debug-level messages as you can see from the :level=>:debug annotation.

7

Thanks a ton Magnus,
I appreciate you and all those who are always there to help in critical times. :slight_smile:

br,
Sunil

8

Hi Magnus,
I have below error about date parsing.
But I think, I have provided sufficient formats in date filter.

{:timestamp=>"2016-03-21T10:06:17.912000+0200", :message=>"Failed parsing date from field", :field=>"eventLogTime", :value=>"2016-03-21T08:06:15.156Z", :exception=>"cannot convert instance of class org.jruby.RubyObject to class java.lang.String", :config_parsers=>"YYYY-MM-dd'T'HH:mm:ss,YYYY-MM-dd HH:mm:ss,HH:mm:ss MMM dd yyyy,YYYY-MM-dd HH:mm:ss,SSS,yyyy-MM-dd'T'HH:mm:ss.SSSZ,yyyy-MM-dd'T'HH:mm:ss.SSSZ+0300,yyyy-MM-dd'T'HH:mm:ss.SSSSSS+0200,yyyy-MM-dd'T'HH:mm:ss.SSSSSZ+0200,YYYY-MM-dd'T'HH:mm:ssZ,YYYY-MM-dd'T'HH:mm:ss.sssZ", :config_locale=>"default=en_US", :level=>:warn}

config Below:

date {
        match => [ "eventLogTime", "YYYY-MM-dd'T'HH:mm:ss", "YYYY-MM-dd HH:mm:ss","HH:mm:ss MMM dd yyyy","YYYY-MM-dd HH:mm:ss,SSS","yyyy-MM-dd'T'HH:mm:ss.SSSZ","yyyy-MM-dd'T'HH:mm:ss.SSSZ+0300", "yyyy-MM-dd'T'HH:mm:ss.SSSSSS+0200", "yyyy-MM-dd'T'HH:mm:ss.SSSSSZ+0200", "YYYY-MM-dd'T'HH:mm:ssZ","YYYY-MM-dd'T'HH:mm:ss.sssZ"]
        target => "eventLogTime"
   }
9

The error message indicates that the eventLogTime field is a Ruby object rather than a string. How come? Continue to simplify your setup until the problem disappears.

10

Hi,
I can see form kibana setting, its date field.

11

I can see form kibana setting, its date field.

That's not relevant.

12

Try converting it to a string first before using the date filter

 mutate {
     convert => [ "eventLogTime", "string" ]
 }