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
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
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
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
I get the same results for both approaches. /k
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.
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.
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
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?
yes that is correct.
please mark the question as answered if it worked out for you.
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?
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)?
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
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.
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.
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.
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?
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.
Hi Kristian, Is it not very clear still. Do you want me to give some more explanation.
see update above
/k
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
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/