How to calculate the average time between two different events?

[lakromani]

We have a Hotspot server where we like to get the average time from when a user requests an SMS to the time the user logs in.

Data looks like this:

Sep 30 10:28:32 172.30.112.1 AAA: 172.30.54.61 logged in with username 45550203
Sep 30 10:26:12 172.30.112.1 AAA: 172.30.52.157 logged in with username 97540358
Sep 30 10:25:04 172.30.112.1 PORTAL: SMS sent to 97072419.
Sep 30 10:24:59 172.30.112.1 PORTAL: SMS sent to 41400012.
Sep 30 10:24:53 172.30.112.1 PORTAL: Login failed for 172.30.58.145 - invalid password for username 97390754
Sep 30 10:24:51 172.30.112.1 PORTAL: Login failed for 172.30.60.126 - invalid password for username 97072419
Sep 30 10:24:26 172.30.112.1 AAA: 172.30.54.61 logged in with username 45550203
Sep 30 10:24:24 172.30.112.1 AAA: 172.30.12.230 logged in with username 41655923
Sep 30 10:24:16 172.30.112.1 PORTAL: Login failed for 172.30.59.209 - invalid username.
Sep 30 10:23:48 172.30.112.1 PORTAL: SMS sent to 97540358.
Sep 30 10:23:36 172.30.112.1 PORTAL: SMS sent to 45550203.

Where the field username contains the username like 45550203
And eventtype contains status like User_logged_in and SMS_sendt

A user may log in later, so we need only the first hits.
A user may not log in at all, discard data.

User 45550203 gets an SMS 10:23:36 and logs inn 10:24:26. That would give 50 seconds.
User 97540358 gets an SMS 10:23:48 and logs inn 10:26:12. That would give 144 seconds

I have looked at other posts here, but do not get it all together.
If anyone could help, I would be happy.

[tom_frotscher · Accepted solution]

Hi,

the simplest way to achieve this, should be the transaction command. I indexed your sample data in my main index and used a simple regex to get the username as a field. This is the resulting search:

index=main sourcetype="answer300915" | rex "(?<username>[0-9]{8})" | transaction username startswith="SMS sent to" endswith="logged in with username"

The transaction command automatically creates a field called duration, wich is the duration between the first and last event of a transaction. In your case, this is the field you want, and for me it also shows the correct 144 and 50 seconds.

Of course you need to adjust the regex for the username, because this one i used is not restrictive enough, but i dont know exactly how your usernames can look like.

Usually a solution that uses stats is faster than the transaction command, therefore you could also use something like this:

index=main sourcetype="answer300915" "logged in with username" OR "SMS sent to" | rex "(?<username>[0-9]{8})" | stats earliest(_time) as first latest(_time) as last by username | eval duration = last - first

But there is a problem in your sample data: The username "45550203" got one "SMS sent" event and two "logged in" events. Which one do you want to use? You need to decide this and then adjust the search to recognize the right event as the "closing" event. For example by using dedup or similar commands to filter out later "logged in" events.

Greetings

Tom

[lakromani]

This seems to solve it. Thanks.

I will always use the first login.
A user may request one SMS, log in, then the system logs the user out of the system.
If the user tries to use a web browser, he will be asked for his username/password, or he can save it.
So one user can have many logins, but for me, the first is the one to get.