Dateparsefailure while replacing @timestamp

pratheek_k · May 31, 2017, 5:45pm

Problem:
Logs not ordered in when viewing through kibana.

Goal:
Replace timestamp with the time in the log messaage. So that i can order my logs in kibana

Error: dataparsefailure. I dont see any other error message in the logs

Conf:
input {
beats {
port => 5044
}
}
filter {
date {
locale => "en"
match => ["message", "YYYY-MM-dd HH:mm:ss,SSS"]
timezone => "America/Chicago"
}
}

output {
elasticsearch {
hosts => "localhost:9200"
manage_template => false
index => "%{[metadata][beat]}-%{+YYYY.MM.dd}"
document_type => "%{[metadata][type]}"
}
}

Logs:
output received {"event"=>{"@timestamp"=>2017-05-31T17:18:46.639Z, "offset"=>43069, "@version"=>"1", "input_type"=>"log", "beat"=>{"hostname"=>"rsappd123", "name"=>"rsappd123", "version"=>"5.4.0"}, "host"=>"rsappd111", "source"=>"/apps/logs/abc/abc.log", "message"=>"2017-05-31 12:18:39,817 02035935ec ABBXYZZ c.a.e.r.s.hotelExchangeImpl:hotelExchange:250 [INFO] - Total transaction response time: 877", "type"=>"log", "tags"=>["beats_input_codec_plain_applied", "_dateparsefailure"]}}

Log after starting logstash:

[2017-05-31T12:14:04,821][DEBUG][logstash.plugins.registry] On demand adding plugin to the registry {:name=>"date", :type=>"filter", :class=>LogStash::Filters::Date}
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/locale = "en"
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/match = ["message", "YYYY-MM-dd HH:mm:ss,SSS"]
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/@timezone = "America/Chicago"
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/id = "7b4c32e1f7fd8ae4047cf2f25b3977a62e3e48ef-2"
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/enable_metric = true
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/add_tag = []
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/remove_tag = []
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/add_field = {}
[2017-05-31T12:14:04,823][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/remove_field = []
[2017-05-31T12:14:04,824][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/periodic_flush = false
[2017-05-31T12:14:04,824][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/target = "@timestamp"
[2017-05-31T12:14:04,824][DEBUG][logstash.filters.date ] config LogStash::Filters::Date/tag_on_failure = ["_dateparsefailure"]
[2017-05-31T12:14:04,836][DEBUG][org.logstash.filters.DateFilter] Date filter with format=YYYY-MM-dd HH:mm:ss,SSS, locale=en, timezone=America/Chicago built as org.logstash.filters.parser.JodaParser

Please help!!!

Jaxon_Kochel · May 31, 2017, 6:00pm

I'll give you an example of me doing this in my conf file and hopefully it'll help you.

 if [path] =~ "deployment"{   
      mutate { replace => { "type" => "DeployLog" } }             #Deployment Log

    grok{                                                         #Matches the format of the log and breaks it into named fields
      match => { "message" => "(?m)%{DATESTAMP:timestamp}  ?%{NOTSPACE:severity}  ?\[%{NOTSPACE:package}\]  ?%{GREEDYDATA:message}" }
      overwrite => ["message"]                                    #Replaces the entire message from above with just the value of the GREEDYDATA:message
    } 
  }

 date {
    match => [ "timestamp" , "yy-MM-dd HH:mm:ss,SSS", "yy-MM-dd HH:mm:ss.SSS"]
    target => "@timestamp"
  }

So i match my entire message in my grok section, then the date section only takes the timestamp matches it to a format and the the target tells it to go into @timestamp. It does not look like you are using a grok section to filter out all the different properties in your file. Therefore, it has no idea what your date is.

pratheek_k · May 31, 2017, 6:47pm

Thanks for your response. May i know the log message you are parsing using the grok pattern.

Jaxon_Kochel · May 31, 2017, 6:57pm

So that pattern matches something like this in my own log files

2016-01-08 00:35:00,984 INFO [org.apache.shiro.session.mgt.AbstractValidatingSessionManager] Finished session validation. No sessions were stopped.

so its able to break it down into

timestamp: 2016-01-08 00:35:00,984
loglevel: INFO
package: org.apache.shiro.session.mgt.AbstractValidatingSessionManager
message: Finished session validation. No sessions were stopped.

So when it gets to the date section it already knows that my timestamp is "2016-01-08 00:35:00,984" and that will successfully match "yy-MM-dd HH:mm:ss,SSS" so that succeeds and my @timestamp is overridden with that timestamp

pratheek_k · May 31, 2017, 7:49pm

@timestamp is not getting replaced.
Here is the output of logstash:
output received {"event"=>{"@timestamp"=>0017-05-31T20:28:21.639Z, "offset"=>228617, "@version"=>"1", "input_type"=>"log", "beat"=>{"hostname"=>"rsappd111", "name"=>"rsappd111", "version"=>"5.4.0"}, "host"=>"rsappd111", "source"=>"/apps/logs/rtkts/rtkts.log", "message"=>"02035935ec MKMEOD c.a.e.r.s.RebookExchangeImpl:rebookExchange:250 [INFO] - Total rebookExchange response time: 509", "type"=>"log", "tags"=>["beats_input_codec_plain_applied"], "timestamp"=>"17-05-31 14:37:45,639"}}

Jaxon_Kochel · May 31, 2017, 7:57pm

Can you provide a sample log entry for me to test with?

pratheek_k · May 31, 2017, 7:59pm

Sample Entry- 17-05-31 14:37:45,639 02035935ec MKMEOD c.a.e.r.s.RebookExchangeImpl:rebookExchange:250 [INFO] - Total rebookExchange response time: 509
Conf:
input {
beats {
port => 5044
}
}
filter {

grok{
  match => { "message" => "(?m)%{DATESTAMP:timestamp} ?%{GREEDYDATA:message}" }
  overwrite => ["message"]
}
date {
    locale => "en"
    match => ["timestamp", "yyyy-MM-dd HH:mm:ss,SSS"]
    target => "@timestamp"
    timezone => "America/Chicago"
}

}

output {
elasticsearch {
hosts => "localhost:9200"
manage_template => false
index => "%{[@metadata][beat]}-%{+YYYY.MM.dd}"
document_type => "%{[@metadata][type]}"
}
}

Jaxon_Kochel · May 31, 2017, 8:22pm

it seems to be working for me, except its adding a few extra hours into @timestamp compared to the regular timestamp. so if thats the issue youre having youll just have to pick a different timezone untill it matches. Also use match => ["timestamp", "yy-MM-dd HH:mm:ss,SSS"] instead of match => ["timestamp", "yyyy-MM-dd HH:mm:ss,SSS"], itll come out with 2017 in your @timestamp instead of 0017

When i use this conf file

input {
	stdin{}
}

    filter {

    	grok{
    	  match => { "message" => "%{DATESTAMP:timestamp} ?%{GREEDYDATA:message}" }
    	  overwrite => ["message"]
    	}
    	date {
    	    locale => "en"
    	    match => ["timestamp", "yy-MM-dd HH:mm:ss,SSS"]
    	    target => "@timestamp"
    	    timezone => "UTC"
    	}
    }

    output {
    	 stdout { codec => rubydebug }
    }

I'm able to get this correct output

{
    "@timestamp" => 2017-05-22T14:37:45.639Z,
      "@version" => "1",
          "host" => "MROSENBERGER342",
       "message" => "02035935ec MKMEOD c.a.e.r.s.RebookExchangeImpl:rebookExchange:250 [INFO] - Total rebookExchange response time: 509\r",
     "timestamp" => "17-05-22 14:37:45,639"
}

I also changed your date, just so it was easier for me to see that it was working that doesnt matter

pratheek_k · May 31, 2017, 10:25pm

Appreciate you help. So now as I am able to parse the time and override @timestamp. I don't want timestamp field. Do you know how can i do that

Jaxon_Kochel · May 31, 2017, 10:45pm

In filter section.

mutate{
remove_field => ["timestamp"]
}

magnusbaeck · June 1, 2017, 5:20am

it seems to be working for me, except its adding a few extra hours into @timestamp compared to the regular timestamp. so if thats the issue youre having youll just have to pick a different timezone untill it matches.

No, don't do that unless the timestamp in your log is in UTC. @timestamp is always UTC and not local time.

pratheek_k · June 1, 2017, 2:53pm

@magnusbaeck @Jaxon_Kochel
Yes, @timestamp value is UTC by default, i found that after more research. Currently i am able to order logs upto milli second level. I need more precision as the logs are not in order, if event has same milli second timestamp. I know there is a workaround to capture nano second value as another field but my original log does not have nano second value. I dont want to change it. Is there any other workaround.

Thanks

magnusbaeck · June 1, 2017, 8:10pm

Doesn't Logstash and/or Filebeat store the file offset from which the event was read? That can be used for sorting along with the timestamp.

pratheek_k · June 1, 2017, 10:25pm

Thanks. That works but i dont want users to see offset as a column. can i hide that?

magnusbaeck · June 2, 2017, 5:07am

Not if you want to use it for sorting.

pratheek_k · June 13, 2017, 7:51pm

@magnusbaeck I would like to combine below events.
June 1st 2017, 11:51:26.992 12345ab AAAAA ClassName:methodName:99 [DEBUG] - Received request:
June 1st 2017, 11:51:26.993 12345ab AAAAA ClassName:methodName:100 [DEBUG] - request:
June 1st 2017, 11:51:26.993 12345ab AAAAA ClassName:methodName:100 [DEBUG] - Id: abbababcajdfbjasndflsdlf
June 1st 2017, 11:51:26.993 12345ab AAAAA ClassName:methodName:100 [DEBUG] - unique id: AAAAA

Now,all the events having AAAAA in it should be combined into one event. How can i configure this.

But if filebeat ships these events disorderly when i combine them it will be disordered. How can use offset in order the events in logstash and combine them into one event.

magnusbaeck · June 13, 2017, 8:10pm

I don't have an out of the box solution for that. Maybe an aggregate filter can help. How would Logstash know when an event is "done", i.e. when the last line of an event has arrived?

I'd actually question the premise of what you want to do. If AAAAA is a unique identifier, why not just extract it to a field and use it for filtering/grouping? Then you'd also capture that related events can have different timestamps and line numbers (for example).

pratheek_k · June 13, 2017, 8:41pm

@magnusbaeck I am fine with parsing out the unique id as separate field which i already did. Now, how can i group all the events with this unique id into one event and order them based on timestamp and offset in logstash. Or, Can i do this at filebeat?

magnusbaeck · June 14, 2017, 5:34am

Now, how can i group all the events with this unique id into one event and order them based on timestamp and offset in logstash.

You're asking the same question again and my answer is still the same.

Or, Can i do this at filebeat?

No.

system · July 12, 2017, 5:35am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.