Getting Data In

Substituting _time with an extracted time field changing behavior unexpectedly

aholzer
Motivator

Details:

  • The data is coming in from syslog and the time that I want to base my searches off of is in fact the "localtime" contained inside the message (the actual time the event occurred on the se rver) rather than the timestamp of the syslog message itself
  • My end goal is to catch events that occur within 1second of each other as long as the "channel" is the same and the sourcetypes differ.
  • I test that my logic works for two events that I've identified as matching (the two sample events provided), but when I expand my timerange, then my results are drastically changed and I don't get expected results such as the transaction of the two events I've identified.

I have the following 2 sample events:

sourcetype A
2014-04-11T04:00:15.270885-04:00 -  Alert - string1 - severity[Alert] source[string3] ip[-] description[description1] details[] reason[EventSet] localtime[2014/04/11 04:00:02.0 EDT] time[2014/04/11 08:00:02.0 UTC] count[1] value[x] 
sourcetype B
2014-04-11T04:00:03.312903-04:00 -  Alert Clear - string2 - severity[Alert] source[string3] ip[-] description[description2] details[] reason[EventReset] localtime[2014/04/11 04:00:03.0 EDT] time[2014/04/11 08:00:03.0 UTC] count[1] value[x] 

The important information is the "localtime", which is being extracted into a field of the same name, and the "source", which is being extracted into a field named channel. So I can abbreviate the data as follows:

event1: _time="2014-04-11T04:00:15.270885-04:00", sourcetype=A, channel=mysource1, localtime="2014/04/11 04:00:02.0 EDT"
event2: _time="2014-04-11T04:00:03.312903-04:00", sourcetype=B, channel=mysource1, localtime="2014/04/11 04:00:03.0 EDT"

If I run the below search I get the 2 results listed above:

index=myindex earliest=@d+4h latest=@d+4h+1m ((sourcetype=A "string1") OR ((sourcetype=B OR sourcetype=C) "string2")) (channel="string3" OR channel=string4) | eval localtime=strptime(localtime, "%Y/%m/%d %H:%M:%S.0 %Z") 

But if I add the below eval statement, I only get event1 in my results, even though the values in _time still fall within the earliest-latest range:

index=myindex earliest=@d+4h latest=@d+4h+1m ((sourcetype=A "string1") OR ((sourcetype=B OR sourcetype=C) "string2")) (channel="string3" OR channel=string4) | eval localtime=strptime(localtime, "%Y/%m/%d %H:%M:%S.0 %Z") | eval _time = localtime

Something that makes this even odder is that if I run the above search with a transaction in it, both events get caught as I'd expect in my transaction:

index=myindex earliest=@d+4h latest=@d+4h+1m ((sourcetype=A "string1") OR ((sourcetype=B OR sourcetype=C) "string2")) (channel="string3" OR channel="string4") | eval localtime=strptime(localtime, "%Y/%m/%d %H:%M:%S.0 %Z") | eval _time = localtime | transaction channel maxpause=2s

This is the behavior I'm looking for in the end, but sadly the story doesn't end here. If I now use the above search, and increase latest to @d+4h+10m, then the transaction is lost...

index=remyindex earliest=@d+4h latest=@d+4h+10m ((sourcetype=A "string1") OR ((sourcetype=B OR sourcetype=C) "string2")) (channel="string3" OR channel="string4") | eval localtime=strptime(localtime, "%Y/%m/%d %H:%M:%S.0 %Z") | eval _time = localtime | transaction channel maxpause=2s

Any help would be greatly appreciated.

0 Karma
1 Solution

marcoscala
Builder

Aholzer,
if the real timestam of the event you get is stored in the 'localtime' field, my suggestion is to customize timestamp recognition and set _time to that timestamp instead of the syslog timestamp.

You can do it setting the correct TIME_PREFIX and TIME_FORMAT
TIME_PREFIX=localtime[

Marco

View solution in original post

0 Karma

somesoni2
Revered Legend

Try instead of eval, use rename. (|rename localtime as _time)

0 Karma

marcoscala
Builder

Aholzer,
if the real timestam of the event you get is stored in the 'localtime' field, my suggestion is to customize timestamp recognition and set _time to that timestamp instead of the syslog timestamp.

You can do it setting the correct TIME_PREFIX and TIME_FORMAT
TIME_PREFIX=localtime[

Marco

View solution in original post

0 Karma

marcoscala
Builder

Glad it worked! Please don't forget to mark the question answered!

And happy Splunking!
Marco

0 Karma

aholzer
Motivator

Marco,

From preliminary testing it would seem that this did the trick. I found a couple of events that I should be catching under my logic (after the time change), I've tested with a short and a wide timerange, and in both cases the events come up in a transaction.

Thanks!

0 Karma

aholzer
Motivator

I appreciate it. Doing what you suggest is a good idea and will eliminate at least one point of failure. The server is restarting now, I'll need to wait to get some data before I can test if it's been fixed or not. Again, thanks for your input

0 Karma

marcoscala
Builder

to be honest I'm quite busy and couldn't check carefully your searches if there's some other mistakes. Sometimes, bwt, _time field gives problem with substitutions or other operation. That's why I suggested a cleaner approach from the beginning, with the correct time extraction.

Let me know!

Marco

0 Karma

aholzer
Motivator

Let me test that. I don't think that it will solve everything though. I'll report back after I make the change.

0 Karma
Did you miss .conf21 Virtual?

Good news! The event's keynotes and many of its breakout sessions are now available online, and still totally FREE!