Getting Data In

Calculate Time difference between 2 events

Communicator

I need to calculate the time difference between 2 different events as shown below(Event1 and Event2). It gives the time required for a particular host to login.

These Events are going to be repeated over time. So I need to calculate the time for each of the Event pairs( so that I can calculate the average login time at the end)

Event1: 2:45:57.000 PM

04/24/2012 02:45:57 PM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4624
EventType=0
Type=Information 
host=host1

Several other events with differnt EventCode or host info

Event2: 2:45:59.000 PM

04/24/2012 02:45:59 PM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4648
EventType=0
Type=Information 
host=host1

I am trying the following command but it does not seem to give the desired output.

source="WMI:WinEventLog:Security" EventCode="4648" OR EventCode="4624" | transaction EventCode "beginswith=4648 endswith=4624" | EVAL Outage(Minutes)=duration/60 | TABLE EventCode Outage(Minutes) _time

I need to do it for similar host(time for host=host1, time for host=host2 etc). Can you suggest if the above command would be useful or can you suggest a different command.

The exact log looks something like this

04/25/2012 07:00:16 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4624
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=170971

04/25/2012 07:00:12 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4648
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=170971

04/25/2012 07:00:08 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4624
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=170971

04/25/2012 07:00:00 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4648
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=170971
1 Solution

Ultra Champion

If I understand your question correctly (seems to be some editing required), you're making a mistake in the transactions command. You're doing the transaction over the wrong field. The point of having a transaction over a field, is that the value of the field is the same for all events considered to be part of the transaction. Think of a JSESSIONID or a client IP in a web server log, and you'll get the idea.

In your case, I think this search would work the way you want;

source=WMI:WinEventLog:Security EventCode="4648" OR EventCode="4624" 
| transaction host startswith=4648 endswith=4624 maxevents=2
| table host duration _time

The result should look something like

_time                 host        duration
2012-04-25 12:23:34   server-A    3
2012-04-21 15:31:22   server-B    4

UPDATE:

Since there seems to be no true sessionID to go by, we'll make a transaction over a combination of fields. First however, we must make a rename of some fields, since there are some inconsistencies in Redmond naming standards.

source=WMI:WinEventLog:Security EventCode="4648" OR EventCode="4624"
| rename Source_Network_Address AS Network_Address Source_Port AS Port 
| transaction Port Network_Address Account_Name startswith=4648 endswith=4624 maxevents=2
| search eventcount = 2
| table host duration _time Account_Name

Hope this helps,

Kristian

View solution in original post

Communicator

I think the question was not very clear.

The output that I get by running this command is

_time                Host            Outage_Minutes
2012-04-25 12:23:34  server-A        6097.4833

What this command gives is the difference between the first Event-4648 time and the last Event-4624 time. But in the log there are several such combination of events ( 4648 and 4624 pairs )

What I actually want is the time difference between each 4648 and 4624 combinations separately (which gives me the time required for a user to login to a VM).

The output needs to be something like this.

_time                   Host        Outage_Seconds
2012-04-25 12:23:34     server-A    10 
2012-04-25 08:15:24     server-A    20 
2012-04-22 12:21:32     server-A     8 
2012-04-22 12:02:32     server-B    15

which tells that Server-A took 10 seconds to login at time 12:23:34

and 20 Seconds at time 08:15:24

Pasting the log below for clarity

04/25/2012 12:23:34 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4624
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=171050


04/25/2012 12:23:34 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4624
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=171049

04/25/2012 12:23:24 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4648
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=171048


04/25/2012 08:15:24 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4624
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=171046


04/25/2012 08:15:24 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4624
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=171045


04/25/2012 08:15:04 AM
LogName=Security
SourceName=Microsoft Windows security auditing.
EventCode=4648
EventType=0
Type=Information
ComputerName=Devserver2.mswpc.com
TaskCategory=Logon
OpCode=Info
RecordNumber=171044
0 Karma

Communicator

Actually my log data have slightly changed with the Event codes and the associated common parameters between the Event codes. This had to be done because we were not getting proper logging information with the earlier events.

So we wrote some Event through the VB Script which gets logged when the VM starts (and it is having EventCode=0).
The common field b/n these events is only the host,

host="*.mswpc.com" EventCode="0" OR EventCode="4624" | transaction host startswith=(EventCode="4624") endswith=(EventCode="0") maxevents=2 | search eventcount=2 | table duration, host, _time, Account_Name

0 Karma

Ultra Champion

I get the same results for both approaches. /k

0 Karma

Communicator

I tried "where eventcount=2" as well instead of "search eventcount=2". Even that does not seem to work. It still logs in some time even if only one of the events is present.

0 Karma

Communicator

Yeah right. You are right on the use case. Its still giving me some high value if one of the events is not present. Need to check this.

0 Karma

Ultra Champion

So you mean that you happen to run the search in the middle of a login attempt, so the login process has started but not completed? Or the opposite, where you catch the end of a login, but beginning of the transaction was outside/before the time range of the search?

The answer to either is the same, and I've updated the search above.

/k

0 Karma

Communicator

One problem that I see running this command is, when the Eventcode=4624 is existing and the other EventCode=4648 is not existing, it still calculates some value for duration (=136)which is not correct. Can we avoid this?

0 Karma

Ultra Champion

yes that is correct.

please mark the question as answered if it worked out for you.

0 Karma

Communicator

I validated your command on a proper set of data. It seems to be working fine. Thanks a lot.

As i can see the transaction command lists the multiple combination of event pairs separately.
Is that correct?

0 Karma

Communicator

I am seeing some higher values in the duration field like 1252, 1400 etc. normally login time will be in 5-10 seconds. Can I see the time for both 4624 and 4648(for a specific user) and then the difference, so that it will be easier for me to validate. When you execute the command does it calculate the time difference between the adjacent 4624 and 4648 for a specific user (and ignores the 4624 and 4624 combination)?

0 Karma

Communicator

Yes the ComputerName is the machine thats been logged into. I am trying to validate the result.

Before that Is transaction not used for
calculating the time difference between the first occurence and the last occurence and not adjacent occurences. Is it correct?

Thats why I was trying somethg like this.

host="DEVSERVER7" (EventCode=4624 OR EventCode=4648) |sort _time| delta _time AS timeDelta p=1 | eval timeDeltaS=abs(timeDelta) | eval AVGtime=tostring(timeDelta,"duration")|search AVGtime!="00:00:00" OR EventCode=4648 | table _time,Account_Name,Source_Network_Address,EventCode,AVGtime

0 Karma

Ultra Champion

Is there nothing like a session-id in windows logs? I think I've seen it, but perhaps not for these eventcodes.

The ComputerName would be the machine that's being logged into, right?

See above for updated info.

0 Karma

Communicator

We are actually logging into a VM. Other than the ComputerName there is Username and IP_Address field which gives information of which User (with IP_address) is trying to log in.

0 Karma

Ultra Champion

Is it the ComputerName only? If 2 people log on to the machine, will there not be 2 events of each 4624 and 4648? How do you tell the sessions apart?

I don't think you'll be needing delta.

0 Karma

Communicator

Its actually the ComputerName(I think I specified this as host in my earlier enquiry) which signifies that the 4648 is connected to 4624. There will be several other host/ComputerName like that. I am trying to use a combination of delta and transaction. Is that the right way to go?

0 Karma

Ultra Champion

Hi, could you please tell me what piece of information in the events signify that a particular 4648 is connected to a particular 4624?

Is it the Account_Name, ComputerName, IP address or something else (or a combination of several). I'm not a Windows admin, and the LogonGUID, Logon_ID seem confusing.

0 Karma

Communicator

Hi Kristian, Is it not very clear still. Do you want me to give some more explanation.

0 Karma

Ultra Champion

see update above

/k

0 Karma

Ultra Champion

If I understand your question correctly (seems to be some editing required), you're making a mistake in the transactions command. You're doing the transaction over the wrong field. The point of having a transaction over a field, is that the value of the field is the same for all events considered to be part of the transaction. Think of a JSESSIONID or a client IP in a web server log, and you'll get the idea.

In your case, I think this search would work the way you want;

source=WMI:WinEventLog:Security EventCode="4648" OR EventCode="4624" 
| transaction host startswith=4648 endswith=4624 maxevents=2
| table host duration _time

The result should look something like

_time                 host        duration
2012-04-25 12:23:34   server-A    3
2012-04-21 15:31:22   server-B    4

UPDATE:

Since there seems to be no true sessionID to go by, we'll make a transaction over a combination of fields. First however, we must make a rename of some fields, since there are some inconsistencies in Redmond naming standards.

source=WMI:WinEventLog:Security EventCode="4648" OR EventCode="4624"
| rename Source_Network_Address AS Network_Address Source_Port AS Port 
| transaction Port Network_Address Account_Name startswith=4648 endswith=4624 maxevents=2
| search eventcount = 2
| table host duration _time Account_Name

Hope this helps,

Kristian

View solution in original post

Communicator

Sure will do that. Kristian, do you have any idea about using REST API's. I am getting error("401 Unauthorized") in Step 3, when I run example given in the below link.
http://blogs.splunk.com/2011/08/02/splunk-rest-api-is-easy-to-use/

0 Karma
State of Splunk Careers

Access the Splunk Careers Report to see real data that shows how Splunk mastery increases your value and job satisfaction.

Find out what your skills are worth!