How do I set conditions for calculating the duration of an event such that the end time is based on the way a user ends their session?

[gertverhoog]

Hi all,

I am trying to extract usage duration patterns for our web app, from login to either logout, or when the user stops sending requests to the server. I can get the session duration with a transaction that starts with the login event, and ends with either a logout or a session expiry event, but sessions only expire some time after the last user activity. I don't want to capture this "idle time".

Our web app logs what users are doing with the app, from login to either logout or session purge. It looks somewhat like this:

2017-09-28 12:55:36,595 event_id="auth:login:success" email="johndoe@example.com" [....]
2017-09-28 12:56:00,010 event_id="app:web:request" email="johndoe@example.com" [....]
2017-09-28 12:56:01,243 event_id="app:web:request" email="johndoe@example.com" [....]

[...]

2017-09-28 12:57:12,243 event_id="auth:logout:success" email="johndoe@example.com" [....]

Of course, quite often, users won't explicitly logout. They just close the browser window and let the session expire. In that case, the logs look somewhat like this:

2017-09-28 12:55:36,595 event_id="auth:login:success" email="johndoe@example.com" [....]
2017-09-28 12:56:00,010 event_id="app:web:request" email="johndoe@example.com" [....]
2017-09-28 12:56:01,243 event_id="app:web:request" email="johndoe@example.com" [....]

[...]

2017-09-28 13:26:01,243 event_id="auth:session-purge:success" email="johndoe@example.com" [....]

I have the following search that shows how long people's sessions were, but when users don't explicitly logout, it counts all the idle time before a session expires.

[...] email!="" (event_id="auth:*" OR event_id="app:web:request")
| transaction email
    startswith=(event_id="auth:login:success")
    endswith=(event_id="auth:session-purge:success" OR event_id="auth:logout:success")
| eval end_time_s=_time+duration
| eval start_time=strftime(_time,"%m/%d/%y %H:%M:%S")
| eval end_time=strftime(end_time_s,"%m/%d/%y %H:%M:%S")
| eval dur_time=tostring(duration,"duration")
| sort by -start_time
| table start_time,end_time,dur_time,email

This works, but when a user gets logged out because their session expires, I get all the idle time as well, even if the user did nothing after their first request.

What I would like to express in search is the following:

if the transaction ends with event_id="auth:session-purge:success", then use _time of the last log entry within the transaction where event_id="app:web:request" to calculate the duration. Otherwise, use the time of the logout event.

How would I do this?

[cpetterborg]

There is a simple way to do your transaction that will probably meet your requirements (if I understand them correctly). Since you have a timeout interval for the session, you can use that to make sure that you don't include that timeout in your transaction using the maxpause parameter. If you set the maxpause parameter to one second less than your timeout period, then the timeout will come after the transaction must end. Then the duration of the transaction should be the value that you want. Try something like:

| transaction email
     startswith=(event_id="auth:login:success")
     endswith=(event_id="auth:logout:success")
     maxpause=599s

if 600 seconds is your session timeout period. Please set it according to you situation. This is only a change to your transaction command in your search. Use the rest of your search as is, or modify as needed for your intended purpose.

[gertverhoog]

Clever! I'll give it a try — although I'd like to avoid hard-coding the session timeout in case this changes.

[DalJeanis]

Try something like this...

...your search... which leaves records  in reverse time order...

| rename COMMENT as "Mark records that were timeouts and copy the mark backward in time 1 event." 
| rename COMMENT as "Then kill the timeout records themselves." 
| eval timeout=case(event_id="auth:session-purge:success",1)
| streamstats current=f last(timeout) as endoftrans window=1 by email
| where isnull(timeout)

| rename COMMENT as "Flag either kind of logout, then build the transaction." 
| eval endoftrans=if(event_id="auth:logout:success",1,endoftrans)
| transaction email
      startswith=(event_id="auth:login:success")
      endswith=(endoftrans=1)

...the remainder of your processing...

[gertverhoog]

Interesting, thanks for that! I haven't quite got it working yet, but I like your approach. I'll do some more experimenting.

[DalJeanis]

@gertverhoog - great! Let us know if we can help further.

[Sukisen1981]

hi,
2017-09-28 12:55:36,595 event_id="auth:login:success" email="johndoe@example.com" [....]
2. 2017-09-28 12:56:00,010 event_id="app:web:request" email="johndoe@example.com" [....]
3. 2017-09-28 12:56:01,243 event_id="app:web:request" email="johndoe@example.com" [....]

7. 2017-09-28 13:26:01,243 event_id="auth:session-purge:success" email="johndoe@example.com" [....]

what should duration be in this case, assuming only 3 events in this case?
2017-09-28 13:26:01,243 - 2017-09-28 12:55:36,595
OR
2017-09-28 13:26:01,243 - 2017-09-28 12:56:01,243

[gertverhoog]

The duration should be 2017-09-28 12:56:01,243 – 2017-09-28 12:55:36,595 in that case, so not counting the session purge event.