Getting Data In
Highlighted

How do I find timestamp recognition discrepancies in my events?

Super Champion

I seem to have some events that were where not given the correct timestamp. I'm trying to track down how/why this is happening, but it doesn't happen all the time.

It's a pain to track down all the timestamp discrepancies manually. This is splunk, isn't there an easier way?


For the purpose of an example, here's a type of event that sometimes has the wrong timestamp:

524|20101013080932|MY.APP|system|3|INFO|Thread[Thread-16,5,jboss] UploadMonitor: The file upload monitor is functioning normally

The file is "|" delimited, and the second field is the timestamp, which represents 2010-10-13 08:09:32 AM.

Here's my props.conf entry:

[my_sourcetype]
TIME_FORMAT = %Y%m%d%H%M%S
TIME_PREFIX = ^\d+\|
EXTRACT-fields = ^(?P<msgid>\d+)\|\d+\|(?P<component>[^|]+)\|[^|]+\|\d+\|(?P<log_level>[A-Z]+)\|Thread\[(?P<thread>[^\]|]+)\] (?P<message>.*)
Highlighted

Re: How do I find timestamp recognition discrepancies in my events?

Motivator

If the timestamps are in a consistent format, you could use rex to extract the time into a new field at search time, then pipe to convert mktime() to get epoch time, and where or eval to see if it matches the value in _time.

0 Karma
Highlighted

Re: How do I find timestamp recognition discrepancies in my events?

Super Champion

There are several steps I would recommend when tracking down timestamp recognition problems.

  1. In Splunk 4 and later, Splunk records the start and end positions of where the timestamp was found for each event. This info is in the timestartpos and timeendpos fields.

    So for just getting started, it's helpful to simply see what text splunk used to extract the timestamp. This should point out if splunk is looking at any numbers before/after your actual timestamp, or if part of your timestamp is being cut off.

    sourcetype=my_sourcetype | eval raw_timestamp=substr(_raw, timestartpos+1, timeendpos-timestartpos) | table _time, raw_timestamp
    

    NOTE: There are some places where this may not work properly. For example, if the event's _raw field is modified by a transformer or SEDCMD, then the start and end index would represent the locations based on your original event, and not the final even. This is because timestamp recognition happens before any custom transformations. But as long as your modifications to _raw didn't move any text around before your timestamp, you should be okay.

  2. Another approach is to compare the timestamp text from the event with the value stored in _time, the internal timestamp field. To do this we must first extract the raw timestamp text from the raw event, which can be done using approach used in #1, or by extracting it yourself using a rex command. Then we convert _time to a timestamp string using strftime() using the same format that the event uses (this should match the TIME_FORMAT in your props.conf entry.) Keep in mind that you have to run this search for only one type of timestamp format at a time.

    sourcetype=my_sourcetype | eval raw_timestamp=ifnull(substr(_raw, timestartpos+1, timeendpos-timestartpos),"unknown") | eval time=strftime(_time, "%Y%m%d%H%M%S") | table _time, raw_timestamp, time
    

    If you see just the discrepancies, then you can tack this on the end: | where raw_timestamp!=time

    NOTE: This works better for some timestamps than it does for others. For example, some timestamps have optional leading 0s, sometimes you see "AM" and other times it could be "am". There are ways to compensate for many of these using eval and possibly a rex command (using mode=sed).

  3. Another option is very similar to option 2, except that it does the check in reverse. Instead of taking _time and covering it to a human readable timestamp, we convert the extracted timestamp text and convert it to a unix epoch value using the strptime() function. This approach should avoid any of the timestamp quarks that you can run into with option #2 (optional 0s and case changes), but downside of this approach is that you are really just redoing what splunk already did at index time. (So if there really is a bug in splunk's strptime() code, then it may go unnoticed here.)

    In this example I'm using a regex to extract the timestamp instead of relying on timestartpos and timeendpos, which are not always available. Extracting the timestamp is very simple in the example case, and this serves as an extra check to see if splunk is looking in the right place for the timestamp.

    sourcetype=my_sourcetype | rex "^\d+\|(?<timestamp_raw>\d{14})\|" | eval time=_time | eval my_time=ifnull(strptime(timestamp_raw, "%Y%m%d%H%M%S"),"error") | where time!=my_time | table _time, timestamp_raw, time, my_time
    

    NOTE: If my_time has the value "error", then you should verify that your regex is correct and that your timestamp format string is valid.


Additional notes:

1.) Keep in mind that I haven't tested this across different timezone configurations. So It's possible that you would have to modify some of the examples given above base on timezone differences between your evens and the indexer. This can be done by adding/subtracting seconds to any epoch field, like _time, or can be done with something like relative_time(_time, "+5h") eval expression if your running Splunk 4.1 or later.

2.) I'm not sure if how close the strptime() eval-function is when compared to splunk's internal timestamp parsing functions used at index time. So you could run into issues with timeformats with sub-seconds, or other non-standard strfptime() formats that splunk supports at index time.

3.) I've come across some events on my system that don't have the standard time-related indexed fields for some unknown reason. For these events, all of the date_* fields were missing, along with the timestartpos and timeendpos). So for events like this, you can't rely on extracting the timestamp using the substr() method shown in #1, you'll have to use the regex-based extraction. (Update: I've added some ifnull() expressions to the examples above to help catch this kind of situation. Without this, the search simply ignores these situations because the field would contain a NULL and therefore not match.)

If someone has additional any of these points, I'd be happy to update this answer accordingly.