Duplicate flow begin events are emitted

[philbooth]

Some flow begin events appear to be emitted twice, with identical timestamp, type and flow id. These are visible both in redash and kibana, so it's definitely not caused by any processing weirdness in the metrics pipeline:

fxa=# select e.timestamp, e.flow_id, e.flow_time, e.type from flow_events as e where flow_id = 'ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54';
      timestamp      |                             flow_id                              | flow_time |          type
---------------------+------------------------------------------------------------------+-----------+------------------------
 2016-11-26 23:57:47 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |         0 | flow.force-auth.begin
 2016-11-26 23:57:47 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |         0 | flow.force-auth.begin
 2016-11-26 23:57:55 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |      8314 | flow.force-auth.engage
 2016-11-26 23:57:56 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |      8460 | flow.force-auth.engage
 2016-11-26 23:58:08 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |     20759 | flow.force-auth.submit
 2016-11-26 23:58:08 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |     20995 | flow.signin.attempt
 2016-11-26 23:58:08 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |     20613 | flow.force-auth.submit
 2016-11-26 23:58:08 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |     20849 | flow.signin.attempt
 2016-11-26 23:58:09 | ebafd8e1103968aab73b94f512382f5a3e1cadc1d925457202baadb3fb798a54 |     21769 | account.login
(9 rows)

[philbooth]

Something I only just noticed is that the difference between flow times on the duplicated events shown above remains constant. It is 146 milliseconds in each case, which suggests to me that these really are the same events on the client but they've been sent to the /metrics endpoint twice, with a slightly different (by 146 milliseconds) base time in each case and thus logged twice. Digging into the client-side metrics stuff now to see if I can reproduce it somehow.

[philbooth]

I have a theory!

Currently, we flush the events and timers when we know that the data has been successfully posted to /metrics. So, if a second metrics-triggering event (blur or unload) happens before we receive that response, we will send the same data to the server twice and it will be logged twice.

I've tried to simulate this by indulging in a spot of lightning-fast tab/window switching locally, but haven't managed it yet (the problem seems to be common to all user agents).

But anyway, if something like the above is the cause of the problem (and it's the best idea I have so far), explicitly checking for and preventing re-entrancy would fix it. Going to open a PR to see what people think.