topic Re: How to use transaction command to show Windows time difference between two EventCodes? in Getting Data In

How to use transaction command to show Windows time difference between two EventCodes?

M2016G0216 — Tue, 29 Sep 2020 16:22:01 GMT

I want to capture EventCode=1100 , but I also want to know if EventCode=4608 is created in one minute after EventCode=1100, If EventCode is created by itself and is not followed by EventCode=4608, I want to know that. Here's the search syntax I have, but the results are not what I really want. I don't know if what I have captures the gist of what I'm trying to do.

[10:19]
index=wineventlog source="WinEventLog:Security" host=* ((EventCode=1100 body="The event logging service has shut down.") OR (EventCode=4608 ) )
| transaction EventCode maxspan=1m
| table _time, EventCode, host,body
| sort -_time

[10:20]
The results are something like this:

[10:20]
2017-10-16 01:03:29 4608 Windows is starting up.
2017-10-15 23:01:51 4608 Windows is starting up.
2017-10-15 23:01:21 1100 The event logging service has shut down.
2017-10-15 20:02:59 4608 Windows is starting up.
2017-10-15 01:15:31 4608 Windows is starting up.

Re: How to use transaction command to show Windows time difference between two EventCodes?

elliotproebstel — Fri, 20 Oct 2017 21:12:46 GMT

Right now, you are telling transaction to consider a group of events a single transaction if they share the same EventCode, but I think you want to consider two events part of the same transaction if they are marked by a starting EventCode=1100 and an ending EventCode=4608. In that case, you'll want to use the arguments startswith and endswith, as documented:
https://docs.splunk.com/Documentation/SplunkCloud/6.6.3/SearchReference/Transaction

So I think you'll want something like this:
index=wineventlog source="WinEventLog:Security" host=* ((EventCode=1100 body="The event logging service has shut down.") OR (EventCode=4608 ) ) | transaction maxspan=1m startswith=eval(EventCode=1100) endswith=eval(EventCode=4608) keeporphans=true | where _txn_orphan=1

Splunk will consider starting events (EventCode=1100) that don't have a corresponding ending event (EventCode=4608) within the maxspan window to be orphans. Hence the need to include keeporphans=true and then finally filter to display only the orphans.

Re: How to use transaction command to show Windows time difference between two EventCodes?

DalJeanis — Mon, 23 Oct 2017 02:35:03 GMT

@elliotproebstel - Good start. Your answer is an improvement for the OP, but there is more improvement there to be had.

Transaction is a real resource hog, so here's a challenge for you: see if you can refactor this query to meet the need using a streamstats command instead of transaction.

Come up with good code for that, tag me on the reply here and I'll upvote it.

Re: How to use transaction command to show Windows time difference between two EventCodes?

elliotproebstel — Mon, 23 Oct 2017 14:06:02 GMT

Thanks for the challenge @DalJeanis! You're right; although the OP specifically requested guidance on how to use the transaction command to complete this task, I should have at least mentioned that transaction is resource-intensive and rarely the most efficient way to solve a problem.

I'm pretty sure this should achieve the same goal:
index=wineventlog source="WinEventLog:Security" (1100 EventCode=1100) OR (4608 EventCode=4608) | streamstats count reset_after=(EventCode=1100) time_window=1m | search EventCode=1100 count=1

In this approach, the streamstats command will walk through events in the order returned from the original search (which, by default, is reverse-chronological) and apply a field called count. The value of count will reset every time either of these two conditions is met:
1. The time between two events is greater than the specified time_window value of 1 minute; OR
2. The search encounters an event where EventCode=1100.

In the case of #1, the count will reset before it is applied to the next event. In the case of #2, the count will reset after it is applied to the event with EventCode=1100. Thus, every event with EventCode=1100 where count>1 is guaranteed to be followed by an event with EventCode=4608 within 1 min.

One thing that wasn't specified in the original post but is likely needed: OP, if your Windows logs are coming from multiple hosts, you might be wanting to narrow your search to look for events with EventCode=1100 followed by events with EventCode=4608 within the same minute from the same host. If this is the case, you should add the clause BY host like this:
index=wineventlog source="WinEventLog:Security" (1100 EventCode=1100) OR (4608 EventCode=4608) | streamstats count BY host reset_after=(EventCode=1100) time_window=1m | search EventCode=1100 count=1

Re: How to use transaction command to show Windows time difference between two EventCodes?

M2016G0216 — Tue, 29 Sep 2020 16:27:28 GMT

If do the following search for the past four days and deliberately leave out "| where _txn_orphan=1" to see the total number of EventCode=1100, I get 5 results for EventCode=1100:

index=wineventlog source="WinEventLog:Security" host=workstation1 ((EventCode=1100 body="The event logging service has shut down.") OR (EventCode=4608 ) )
| transaction startswith=eval(EventCode=1100) endswith=eval(EventCode=4608) maxspan=1m keeporphans=true
| eval Time=strftime(_time, "%b %d %H:%M:%S")
| table Time, EventCode, host,body,action
| rename body to "Event Message", action to "Final Action", host to "Host Name", Time to "Time of Event"

The following results of the above search show EventCode=1100 as an "orphan" five times:
Time of Event
EventCode
Host Name
Event Message
Final Action

Oct 22 23:02:07 1100
4608 WORKSTATION1 The event logging service has shut down.
Windows is starting up. This event is logged when LSASS.EXE starts and the auditing subsystem is initialized. stopped
success
Oct 22 23:02:07 1100
4608 WORKSTATION1 The event logging service has shut down.
Windows is starting up. This event is logged when LSASS.EXE starts and the auditing subsystem is initialized. stopped
success
Oct 22 23:02:07 1100 WORKSTATION1 The event logging service has shut down. stopped
Oct 22 23:02:07 1100 WORKSTATION1 The event logging service has shut down. stopped
Oct 22 23:02:07 1100 WORKSTATION1 The event logging service has shut down. stopped
Oct 22 01:14:47 1100
4608 WORKSTATION1 The event logging service has shut down.
Windows is starting up. This event is logged when LSASS.EXE starts and the auditing subsystem is initialized. stopped
success
Oct 22 01:14:47 1100 WORKSTATION1 The event logging service has shut down. stopped
Oct 21 01:14:37 1100
4608 WORKSTATION1 The event logging service has shut down.
Windows is starting up. This event is logged when LSASS.EXE starts and the auditing subsystem is initialized. stopped
success
Oct 21 01:14:37 1100 WORKSTATION1 The event logging service has shut down. stopped

And, if I do the streamstats version of the search below, I get 7 results for EventCode=1100.

index=wineventlog source="WinEventLog:Security" host=workstation1 ((EventCode=1100 body="The event logging service has shut down.") OR (EventCode=4608 ) )
| streamstats count BY host reset_after=(EventCode=1100) time_window=1m
| search EventCode=1100 count=1
| eval Time=strftime(_time, "%b %d %H:%M:%S")
| table Time, EventCode, host,body,action
| rename body to "Event Message", action to "Final Action", host to "Host Name", Time to "Time of Event"

I'm doing the search for the same time. Why are the results of the search different as far as the number of EventCode=1100 is concerned?

Re: How to use transaction command to show Windows time difference between two EventCodes?

M2016G0216 — Tue, 24 Oct 2017 15:07:16 GMT

To be clear, the original answer provided by @elliotproebstel does work.

Re: How to use transaction command to show Windows time difference between two EventCodes?

M2016G0216 — Tue, 24 Oct 2017 16:15:55 GMT

The interesting thing is that these "orphans" are taking place within the time frame of EventCode=1100 being followed by EventCode=4608. Is there a way to search for "orphans" outside that time range only?

Re: How to use transaction command to show Windows time difference between two EventCodes?

elliotproebstel — Tue, 24 Oct 2017 16:40:44 GMT

Hmm...looking at the events you've posted here, I'm realizing that I made some assumptions about the data that aren't true at all. My code assumed there would be non-duplicative log entries marking the start and end of a "transaction". Seeing three events with EventCode=1100 in a row with the same timestamp violates that assumption.

Not knowing exactly what your end purpose is with the data, I need to ask a couple clarifying questions. First, just to understand - is this entry an event with EventCode=4608?

Oct 22 23:02:07 1100 4608 WORKSTATION1 The event logging service has shut down. Windows is starting up. This event is logged when LSASS.EXE starts and the auditing subsystem is initialized. stopped success ??
What is the 1100 after the timestamp? The rest of my answer will assume that this event is an event of type 4608.

Given the entries that are all timestamped 23:02:07 - I see three EventCode=1100 events followed by two EventCode=4608 events. Do you want to consider all three 1100 events effectively closed out by the 4608 events, or are you looking to identify two of the 1100 events as unmatched?

Re: How to use transaction command to show Windows time difference between two EventCodes?

M2016G0216 — Tue, 24 Oct 2017 19:48:45 GMT

The host reboots once a week and these EventCodes are generated as a consequence. EventCode=1100 is generated when the event logging service has shut down. This is anticipated since the workstation is shutting down. Upon the system booting back up, EventCode=4608 is generated. What I want to do is capture EventCode=1100 outside that reboot window. For some reason the EventCode=1100 and EventCode=4608 are not one to one, but there seems to be more EventCode=1100 than EventCode=4608 produced during the reboot process. EventCode=1100 happening outside that window would be suspicious as someone would have disabled event logging. That's when I want to be able to catch it and make the alert an actionable alert.

Re: How to use transaction command to show Windows time difference between two EventCodes?

elliotproebstel — Tue, 24 Oct 2017 20:50:33 GMT

Got it. So you want to find any events with EventCode=1100 where there are no subsequent events with EventCode=4608 on the same host within 1 minute. But you don't need to worry about whether they are 1:1, so those three events with EventCode=1100 followed by two events with EventCode=4608 in the above data should not generate an alert. In fact, if I'm understanding correctly, none of the events in the above data should generate an alert, correct?

I'll have to think about it more carefully, but I think the streamstats approach should work if you replace reset_after(EventCode=1100) with reset_before(EventCode=4608).

Re: How to use transaction command to show Windows time difference between two EventCodes?

M2016G0216 — Wed, 25 Oct 2017 14:07:21 GMT

That's correct. Thank you for your help. I made the change per your recommendation and I think I'm set. You did a great job answering my questions and explaining in detail the correct search syntax.

Re: How to use transaction command to show Windows time difference between two EventCodes?

elliotproebstel — Thu, 26 Oct 2017 12:52:43 GMT

Thanks. I'm glad to help! I enjoy SPL challenges.