How to troubleshoot why TIME_FORMAT is not being applied events at index time?

[asleeis]

I've looked through many posts about TIME_FORMAT being ignored. None seemed to quite apply to me. This is a single instance (so the issue of forwarder/indexer doesn't apply).

Here's the issue:

This is the sourcetype definition:

[crashplan_service_log]
BREAK_ONLY_BEFORE = \[\d+\.\d+\.\d+ \d+:\d+:\d+\.\d+
DATETIME_CONFIG =
MAX_TIMESTAMP_LOOKAHEAD = 43
NO_BINARY_CHECK = true
TIME_FORMAT = %m.%d.%y %H:%M:%S.%3Q
category = Custom
description = Format for CrashPlan service.log
pulldown_type = true

Here are some sample logs:

[12.13.16 14:55:09.918 WARN  inot-hand-1  ode42.jna.inotify.InotifyManager] Unable to remove watch for path /opt/splunk/var/run/splunk/dispatch/1481669072.863/remote_events, errno: 22
[12.13.16 14:55:09.917 WARN  inot-hand-1  ode42.jna.inotify.InotifyManager] Unable to remove watch for path /opt/splunk/var/run/splunk/dispatch/1481669072.863/buckets, errno: 22
[12.13.16 14:55:09.767 WARN  inot-hand-1  ode42.jna.inotify.InotifyManager] Unable to remove watch for path /opt/splunk/var/run/splunk/dispatch/1481669072.863/events, errno: 22
[12.13.16 14:55:06.218 INFO  099_SFQ-CW-1 42.backup.path.BackupSetsManager] BSM:: Backup set is out of schedule! Stopping...

When setting up the input, Splunk by default was trying to match %y.%m.%d for the date portion. It is actually %m.%d.%y. So, I tried to override that by specifying the DATE_FORMAT. However, it seems to just ignore what I specified and still use the %y.%m.%d of the date string. It gets the time right either way.

Now, if I perform a query (All Time), and then override the _time variable with strptime(), it works just fine. But I'd like this to work when ingested, not at query time... not to mention querying All Time when I only need the last few hours is wasteful. This query adjusts the datetime correctly when it imported it incorrectly:

source=/usr/local/crashplan/log/service.log.0 | rex field=_raw "^\[(?<dts>\d+\.\d+\.\d+ \d+:\d+:\d+\.\d+) " | eval _time=strptime(dts, "%m.%d.%y %H:%M:%S.%3Q") | eval evt=case(match(_raw, "Unable to remove watch for path"), "watch_error", 1=1, "other") | timechart span=1h count by evt

Anyone see what I'm missing here?

Thanks in advance for any assistance.

[amallik]

Try following, I was able to ingest Crashplan service log successfully.

[crashplan_service]
MAX_TIMESTAMP_LOOKAHEAD = 21
NO_BINARY_CHECK = true
SHOULD_LINEMERGE = false
TIME_FORMAT = %m.%d.%y %H:%M:%S.%3N
TIME_PREFIX = ^\[
category = Custom
description = crashplan_service
disabled = false
pulldown_type = true

[coltwanger · Accepted solution]

Have you tried specifying a TIME_PREFIX? I was having issues ingesting this through the wizard until I added a prefix:

TIME_PREFIX = \[

[asleeis]

Oh crap! Actually, I tried it with just "[" and not escaping it. I just retried when I realized that, and it seems to recognize that correctly.

So solution is to add in the prefix of: \[

Thank you! Such a simple issue, and yet so brain racking. Kinda like a missing ; in one's code back in the day. 🙂

[ppablo]

Don't forget to upvote the answer by @coltwanger for helping you out!

[coltwanger]

Glad it's resolved! I run into these issues from time to time because I mostly edit them in the CONFs themselves. Running it through a the Add Data UI sometimes helps to catch errors you wouldn't normally see. In this case Splunk whined about a regex issue with TIME_PREFIX when I just tried [ 🙂

[mattymo]

+1 to the the 'add data' wizard . It's a great place to test out these settings on sample data!!
j

[asleeis]

I have. Didn't help.