1046236 - Log call success/termination for metrics

Status: RESOLVED FIXED

(Hello (Loop) :: Server, defect)

Description

[Katie Parlante]

For mvp metrics, we want to log the result of the call setup. The format should be very similar to the request.summary log, json with the fields:

- "time" : <UTC timestamp, same> 
- "op" : "call.setup" (or something similar)
- "hostname" : <same>
- "v" : <same>

And then information for each side of the connection:
- "caller_id"
- "caller_agent"
- "caller_lang"
- "callee_id"
- "callee_lang" 
- "callee_agent"

That assumes you have user agent & lang information for both caller and callee -- the user agent is helpful in particular because we're very interested in device vs desktop segmentations. If that's not possible, we'll get at that by segmenting `POST /calls`, but its then harder to associate with connection/termination.

And a success/error code. I recommend:
- "errno" (0 == success, with error codes for each of the termination reasons listed in the table: reject, busy, timeout, etc.)  

I'm open to an alternative scheme, such as:
- "result" : "connected", "reject", "busy", "timeout", etc.

You may also want to log all state transitions, if you think having that data on production will help you, but only the result is needed for the metrics.

Comment 1

[Katie Parlante]

:tarek, we should probably get this assigned/prioritized/scheduled -- we need it for the total & recurring user counts. Let me know if I need to do anything differently to make that happen...

Comment 2

[Tarek Ziadé (:tarek)]

This bug is scheduled in our current cycle, and will probably be addressed this week - you can follow our work at https://trello.com/b/c28T0Sl8/da-french-team

Comment 3

[Wesley Dawson [:whd]]

I'm wondering if we can have a call setup generate two "call.setup" log messages for ease of parsing/filtering. Right now we've got https://mana.mozilla.org/wiki/display/CLOUDSERVICES/Logging+Standard which our json decoder parses, including normalizing the user agent. My idea is that if we generate two "call.setup" logs for each call setup, setting "context" to "caller" or "callee" as appropriate, and then use "rid" to correlate the two messages (if necessary), we can use the standard fields for everything and it makes writing the filters easier.

With the proposed schema in order to parse this data for filtering I'll have to either parameterize the json decoder for user agent field(s) or perform the user agent tranformation/pii scrubbing specially on the aggregator. This is totally doable (and is in fact mostly done), but if we can avoid it I'd like to.

Katie, what do you think of this approach?

Comment 4

[Alexis Metaireau (:alexis)]

The websockets only knows when the call starts, but doesn't have any information about when it stops.

Similarly, because the clients connects with websockets, we don't have the information you're requesting, about lang and user agent. One way to get it would be to store it in the call-info database and then match the records via the websocket token that's being sent in the protocol.

Comment 5

[Rémy Hubscher (:natim)]

But we now if a call setup when to the end or not.

Comment 6

[Katie Parlante]

(In reply to Alexis Metaireau (:alexis) from comment #4)
> The websockets only knows when the call starts, but doesn't have any
> information about when it stops.

Ok, the meaning of the event that is being logged is then "successful call setup". We still want this event logged -- we have both caller_id and callee_id, and we'll use those for the recurring user counts. Its not perfect, but it sounds like that is as close as we can get from loop server.

> Similarly, because the clients connects with websockets, we don't have the
> information you're requesting, about lang and user agent. One way to get it
> would be to store it in the call-info database and then match the records
> via the websocket token that's being sent in the protocol.

Ok, if we don't have the info, lets leave it out then. We can get the segmentations from the http endpoints.

Comment 7

[Katie Parlante]

(In reply to Wesley Dawson [:whd] from comment #3)
> I'm wondering if we can have a call setup generate two "call.setup" log
> messages for ease of parsing/filtering. Right now we've got
> https://mana.mozilla.org/wiki/display/CLOUDSERVICES/Logging+Standard which
> our json decoder parses, including normalizing the user agent. My idea is
> that if we generate two "call.setup" logs for each call setup, setting
> "context" to "caller" or "callee" as appropriate, and then use "rid" to
> correlate the two messages (if necessary), we can use the standard fields
> for everything and it makes writing the filters easier.
> 
> With the proposed schema in order to parse this data for filtering I'll have
> to either parameterize the json decoder for user agent field(s) or perform
> the user agent tranformation/pii scrubbing specially on the aggregator. This
> is totally doable (and is in fact mostly done), but if we can avoid it I'd
> like to.
> 
> Katie, what do you think of this approach?

Looks like the user agent issue is moot, we're removing agent & lang fields. If that was the main issue, can we stick with one event logged?

Comment 8

[Wesley Dawson [:whd]]

(In reply to Katie Parlante from comment #7)
> Looks like the user agent issue is moot, we're removing agent & lang fields.
> If that was the main issue, can we stick with one event logged?

Yep.

Comment 9

[Alexis Metaireau (:alexis)]

Okay, thanks. We'll be adding these metrics soon then :)

Comment 10

[Rémy Hubscher (:natim)]

Attachment: Link to Github PR — #186

Comment 11

[Rémy Hubscher (:natim)]

> can we stick with one event logged

Katie — If I understand correctly you would like only one log that just says:

 - this callToken call setup succeed (on connected state) 
 - this callToken call setup failed (on terminated state)

Comment 12

[Rémy Hubscher (:natim)]

After discussion with Alexis we are pretty sure it is what you want.

Comment 13

[Katie Parlante]

(In reply to Rémy Hubscher (:natim) from comment #11)
> > can we stick with one event logged
> 
> Katie — If I understand correctly you would like only one log that just says:
> 
>  - this callToken call setup succeed (on connected state) 
>  - this callToken call setup failed (on terminated state)

Ideally, we'd like the uid of the caller and the callee logged on the same line.

Adding the callid to the request.summary is a good idea.

Comment 14

[Alexis Metaireau (:alexis)]

https://github.com/mozilla-services/loop-server/commit/053f683a7fc5bf1b98298858aa18aef9616f5f4f

Comment 15

[Katie Parlante]

Comment on attachment 8478232 [details] [review]
Link to Github PR — #186

Looks reasonable.