Refine your search:

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

asked 25 Apr '12, 11:31

hiteshkanchan's gravatar image

hiteshkanchan
38238
accept rate: 25%

edited 27 Apr '12, 00:57

kristian.kolb's gravatar image

kristian.kolb ♦
19.4k1820


2 Answers:

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

link

answered 25 Apr '12, 13:32

kristian.kolb's gravatar image

kristian.kolb ♦
19.4k1820
accept rate: 36%

edited 27 Apr '12, 00:46

Thanks. The query has been answered. Do I need to mark it as answered anywhere?

(02 May '12, 11:45) hiteshkanchan

I believe you could just click the check-mark next to the answer, underneath the up/down arrows. Thanks, /k

(02 May '12, 12:30) kristian.kolb ♦

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/

(03 May '12, 04:17) hiteshkanchan

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
link

answered 25 Apr '12, 23:10

hiteshkanchan's gravatar image

hiteshkanchan
38238
accept rate: 25%

edited 26 Apr '12, 00:30

kristian.kolb's gravatar image

kristian.kolb ♦
19.4k1820

see update above

/k

(25 Apr '12, 23:35) kristian.kolb ♦

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

(26 Apr '12, 00:04) hiteshkanchan

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.

(26 Apr '12, 00:38) kristian.kolb ♦

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?

(26 Apr '12, 01:53) hiteshkanchan

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.

(26 Apr '12, 01:58) kristian.kolb ♦

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.

(26 Apr '12, 02:34) hiteshkanchan

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.

(26 Apr '12, 02:45) kristian.kolb ♦

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

(26 Apr '12, 03:06) hiteshkanchan

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)?

(26 Apr '12, 03:40) hiteshkanchan

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?

(26 Apr '12, 06:33) hiteshkanchan

yes that is correct.

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

(26 Apr '12, 06:50) kristian.kolb ♦

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?

(26 Apr '12, 23:05) hiteshkanchan

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

(27 Apr '12, 00:39) kristian.kolb ♦

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.

(27 Apr '12, 02:07) hiteshkanchan

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.

(27 Apr '12, 04:57) hiteshkanchan

I get the same results for both approaches. /k

(27 Apr '12, 05:17) kristian.kolb ♦

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

(27 Apr '12, 05:57) hiteshkanchan
Post your answer
toggle preview

Follow this question

Log In to enable email subscriptions

RSS:

Answers

Answers + Comments

Markdown Basics

  • *italic* or _italic_
  • **bold** or __bold__
  • link:[text](http://url.com/ "Title")
  • image?![alt text](/path/img.jpg "Title")
  • numbered list: 1. Foo 2. Bar
  • to add a line break simply add two spaces to where you would like the new line to be.
  • basic HTML tags are also supported

Tags:

×665
×50

Asked: 25 Apr '12, 11:31

Seen: 4,420 times

Last updated: 03 May '12, 04:17

Copyright © 2005-2014 Splunk Inc. All rights reserved.