fix(metrics): separate the begin and view flow events

[philbooth]

Related to mozilla/fxa-activity-metrics#19.

This PR makes two changes:

• flow.${viewName}.begin is renamed to flow.begin (yes, again).

• A new flow.${viewName}.view event is added.

The rationale is that we wanted to simplify the model for people writing queries in redash. And removing the view name from the flow.begin event makes it pleasingly symmetrical with the flow.complete, which is emitted by the auth server.

Adding the flow.${viewName}.view event enables us to more explicitly track which views any given flow travels through. And because it is emitted at the end of afterVisible its flow_time can be used as an approximation of the aggregated request time + initial client-side execution time, which may or may not be useful.

Here is an excerpt from the logs, showing what a flow looks like when a user lands on sign-in, then clicks on Create account to show the sign-up view, then clicks on Have an account? to go back to the sign-in view, then clicks on Forgot password to show the reset-password view:

{"event":"flow.begin","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":0,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:27:45.739Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}
{"event":"flow.signin.view","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":721,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:27:46.460Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}
{"event":"flow.signin.create-account","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":10465,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:27:56.204Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}
{"event":"flow.signup.view","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":10521,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:27:56.260Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}
{"event":"flow.signup.have-account","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":19411,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:28:05.150Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}
{"event":"flow.signin.view","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":19450,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:28:05.189Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}
{"event":"flow.signin.forgot-password","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":23778,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:28:09.517Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}
{"event":"flow.reset-password.view","flow_id":"362c4127d4139f1303891b7dfe44cfe73eb7aa3c479bcae6ba38d866aa4ae94c","flow_time":23796,"hostname":"pbooth-22205.local","op":"flowEvent","pid":34526,"time":"2016-11-23T12:28:09.535Z","userAgent":"Firefox-iOS-FxA/5.3 (Firefox)","v":1,"context":"fx_desktop_v3","entrypoint":"menupanel","service":"sync"}

@shane-tomlinson r?

[shane-tomlinson]

Each child view of the settings page is logged at once when the settings page is opened:

To avoid this problem with the "normal" events, we log the screen being opened in app.js in two places, here for top level views, here for child views.

I like the concept here though, and think there's a lot of merit in only logging a view iff it's actually displayed, after all of the possible startup XHR stuff. Maybe that's what the normal events should do too, view.logView() could possibly move to just before line 116. If that happened, it seems like logView could log the view flow event itself.

[shane-tomlinson]

Attempting to summarize some comments that we discussed IRL, none of which I think need to block this PR:

• It seems like there's a lot of duplication between the normal event stream and flow events. It might be nice to unify the two as much as possible so that we can look for flow events in datadog and normal events in re:dash?
• Similarly, can flow events by generated from normal events, perhaps via server side processing?

The only possible blocker on this PR is https://github.com/mozilla/fxa-content-server/pull/4440/files#r89324776

[philbooth]

Thanks for the feedback @shane-tomlinson. I've tried to implement two of your suggestions in 07218ab:

• flow.${viewName}.view is now generated server-side, driven by the screen events.

• I moved the call to logView in views/app.js to immediately after the view is written to the DOM.

Can I get another r?

[shane-tomlinson]

If the tests all go green, ! Thanks @philbooth!

[shane-tomlinson]

👍 - I think this moving logView here is a good change.

[rfk]

flow.${viewName}.begin is renamed to flow.begin (yes, again).

FWIW, one other potential benefit of this, is that we could one day log the flow.begin event on the server when they first request the page. This would help us capture all the flows that abort before even waiting for all the resources to download.

[philbooth]

...we could one day log the flow.begin event on the server when they first request the page.

Although that would mean we also emit flow.begin for users that are already signed in. Which may be fine, I don't know, but it's different to what happens at the moment.