[GCM] Reset store on checkin rejection and add checkin state to internals

[GCM] Reset store on checkin rejection and add checkin state to internals

First, this now handles cases where checkin is rejected for a non-retryable
reason by resetting the GCM store. UMA data shows that this is happening
less than 1% of the time, and likely implies profile corruption. Currently
we do not have any way to recover from this state.

Secondly, to help diagnose other checkin issues, I've also added checkin
information to chrome://gcm-internals. Namely last checkin time and next
scheduled checkin time. Recording is now on by default to make it easier
to record checkin events.

BUG=659373
Committed: https://crrev.com/76342abff9abbb4413572ebb27d8a1dd6a5c91b6
Cr-Commit-Position: refs/heads/master@{#429033}

[Nicolas Zea, 2016-10-27 19:42:44]

Description was changed from

==========
[GCM] Reset store on checkin rejection and add checkin state to internals

First, this now handles cases where checkin is rejected for a non-retryable
reason by resetting the GCM store. UMA data shows that this is happening
less than 1% of the time, and likely implies profile corruption. Currently
we do not have any way to recover from this state.

Secondly, to help diagnose other checkin issues, I've also added checkin
information to chrome://gcm-internals. Namely last checkin time and next
scheduled checkin time. As part of this I also turned recording on by default.

BUG=659373
==========

to

==========
[GCM] Reset store on checkin rejection and add checkin state to internals

First, this now handles cases where checkin is rejected for a non-retryable
reason by resetting the GCM store. UMA data shows that this is happening
less than 1% of the time, and likely implies profile corruption. Currently
we do not have any way to recover from this state.

Secondly, to help diagnose other checkin issues, I've also added checkin
information to chrome://gcm-internals. Namely last checkin time and next
scheduled checkin time. Recording is now on by default to make it easier
to record checkin events.

BUG=659373
==========

[Nicolas Zea, 2016-10-27 20:01:09]

The CQ bit was checked by zea@chromium.org to run a CQ dry run

[Nicolas Zea, 2016-10-27 20:01:22]

zea@chromium.org changed reviewers:
+ peter@chromium.org

[Nicolas Zea, 2016-10-27 20:01:23]

+Peter for review.

[commit-bot: I haz the power, 2016-10-27 20:02:33]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-27 20:07:37]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-27 20:07:38]

Dry run: Try jobs failed on following builders:
  android_arm64_dbg_recipe on master.tryserver.chromium.android (JOB_FAILED,
https://build.chromium.org/p/tryserver.chromium.android/builders/android_arm6...)
  chromeos_daisy_chromium_compile_only_ng on master.tryserver.chromium.linux
(JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/chromeos_daisy_...)
  linux_chromium_clobber_rel_ng on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[Nicolas Zea, 2016-10-27 21:21:43]

The CQ bit was checked by zea@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-27 21:22:33]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-27 22:31:21]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-27 22:31:24]

Dry run: This issue passed the CQ dry run.

[Peter Beverloo, 2016-10-28 15:52:30]

Thanks! Generally LG, but with one concern I'd love your ideas on.

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_client_impl.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_client_impl.cc:708: ResetStore();
I'm a bit concerned that this opens up a path for a bug in server-side GCM to
cause mass destruction of client-side databases. (E.g. responding with
401/Unauthorized in prod.)

There are a fair number of authentication changes being considered and pushed
through in the GCM team right now, so it's not unlikely that we'll see some
bugs.

How impactful would it be to only ResetStore() when the failure persists for
more than a day or two?

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_client_impl_unittest.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_client_impl_unittest.cc:1245: // checkin response is
persisted.
fwiw, I've found using the base::HistogramTester an excellent tool in verifying
such "should"s, since we record them as UMAs. See the GCMKeyStoreTest, for
example.

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_internals_helper.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_internals_helper.cc:125: stats->last_checkin)));
last_checkin can be NULL here when the CheckinRequest is still retrying, in
which case TimeFormatFriendlyDateAndTime returns a date in 1969 -- probably want
the !is_null check here too.

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/r...
File components/gcm_driver/resources/gcm_internals.html (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/r...
components/gcm_driver/resources/gcm_internals.html:87: <tr>
<if expr="not is_android">

[Nicolas Zea, 2016-11-01 00:08:12]

The CQ bit was checked by zea@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-11-01 00:08:43]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Nicolas Zea, 2016-11-01 00:18:05]

The CQ bit was checked by zea@chromium.org to run a CQ dry run

[Nicolas Zea, 2016-11-01 00:18:16]

PTAL

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_client_impl.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_client_impl.cc:708: ResetStore();
On 2016/10/28 15:52:30, Peter Beverloo wrote:
> I'm a bit concerned that this opens up a path for a bug in server-side GCM to
> cause mass destruction of client-side databases. (E.g. responding with
> 401/Unauthorized in prod.)
> 
> There are a fair number of authentication changes being considered and pushed
> through in the GCM team right now, so it's not unlikely that we'll see some
> bugs.
> 
> How impactful would it be to only ResetStore() when the failure persists for
> more than a day or two?

Updated to only perform a reset for 400/401 response codes.

Re: persistent failure, thinking about this I wonder how much such a check would
really accomplish. How confident are we such a bug to get caught within a day or
two? I suspect the main reason we'd notice a regression would be from this reset
store event, and adding such a delay might actually make it harder to detect.

Thoughts?

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_client_impl_unittest.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_client_impl_unittest.cc:1245: // checkin response is
persisted.
In this scenario there aren't any new histograms being recorded though. The
checkin has its own histogram for the response, but I'm not sure that's
something we should be verifying here.

Or do you think that we should record a different histogram in this scenario?

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_internals_helper.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_internals_helper.cc:125: stats->last_checkin)));
On 2016/10/28 15:52:30, Peter Beverloo wrote:
> last_checkin can be NULL here when the CheckinRequest is still retrying, in
> which case TimeFormatFriendlyDateAndTime returns a date in 1969 -- probably
want
> the !is_null check here too.

Done.

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/r...
File components/gcm_driver/resources/gcm_internals.html (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/r...
components/gcm_driver/resources/gcm_internals.html:87: <tr>
On 2016/10/28 15:52:30, Peter Beverloo wrote:
> <if expr="not is_android">

This all within that conditional already (see line 58)

[commit-bot: I haz the power, 2016-11-01 00:18:28]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-01 00:53:31]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-11-01 00:53:32]

Dry run: Try jobs failed on following builders:
  linux_chromium_clobber_rel_ng on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[Nicolas Zea, 2016-11-01 00:57:23]

The CQ bit was checked by zea@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-11-01 00:57:54]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-01 02:19:07]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-11-01 02:19:08]

Dry run: This issue passed the CQ dry run.

[Peter Beverloo, 2016-11-01 15:19:14]

lgtm

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_client_impl.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_client_impl.cc:708: ResetStore();
On 2016/11/01 00:18:16, Nicolas Zea wrote:
> On 2016/10/28 15:52:30, Peter Beverloo wrote:
> > I'm a bit concerned that this opens up a path for a bug in server-side GCM
to
> > cause mass destruction of client-side databases. (E.g. responding with
> > 401/Unauthorized in prod.)
> > 
> > There are a fair number of authentication changes being considered and
pushed
> > through in the GCM team right now, so it's not unlikely that we'll see some
> > bugs.
> > 
> > How impactful would it be to only ResetStore() when the failure persists for
> > more than a day or two?
> 
> Updated to only perform a reset for 400/401 response codes.
> 
> Re: persistent failure, thinking about this I wonder how much such a check
would
> really accomplish. How confident are we such a bug to get caught within a day
or
> two? I suspect the main reason we'd notice a regression would be from this
reset
> store event, and adding such a delay might actually make it harder to detect.
> 
> Thoughts?

Chirp (go/finch-chirp) could help for automated warnings of such a UMA. The idea
of a mass self destruct of subscriptions frightens me.

You're much more experienced with Chrome's server <--> client interaction,
however, so I'm OK deferring to your judgement here.

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
File components/gcm_driver/gcm_client_impl_unittest.cc (right):

https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
components/gcm_driver/gcm_client_impl_unittest.cc:1245: // checkin response is
persisted.
On 2016/11/01 00:18:16, Nicolas Zea wrote:
> In this scenario there aren't any new histograms being recorded though. The
> checkin has its own histogram for the response, but I'm not sure that's
> something we should be verifying here.
> 
> Or do you think that we should record a different histogram in this scenario?

Resetting the store would record to the GCM.ResetStore histogram, right? That
means you'd be able to test it with something like

ASSERT_TRUE(histogram_tester_.ExpectTotalCount("GCM.ResetStore", 1));

Anyway, neither important nor blocking.

[Nicolas Zea, 2016-11-01 17:19:15]

On 2016/11/01 15:19:14, Peter Beverloo wrote:
> lgtm
> 
>
https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
> File components/gcm_driver/gcm_client_impl.cc (right):
> 
>
https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
> components/gcm_driver/gcm_client_impl.cc:708: ResetStore();
> On 2016/11/01 00:18:16, Nicolas Zea wrote:
> > On 2016/10/28 15:52:30, Peter Beverloo wrote:
> > > I'm a bit concerned that this opens up a path for a bug in server-side GCM
> to
> > > cause mass destruction of client-side databases. (E.g. responding with
> > > 401/Unauthorized in prod.)
> > > 
> > > There are a fair number of authentication changes being considered and
> pushed
> > > through in the GCM team right now, so it's not unlikely that we'll see
some
> > > bugs.
> > > 
> > > How impactful would it be to only ResetStore() when the failure persists
for
> > > more than a day or two?
> > 
> > Updated to only perform a reset for 400/401 response codes.
> > 
> > Re: persistent failure, thinking about this I wonder how much such a check
> would
> > really accomplish. How confident are we such a bug to get caught within a
day
> or
> > two? I suspect the main reason we'd notice a regression would be from this
> reset
> > store event, and adding such a delay might actually make it harder to
detect.
> > 
> > Thoughts?
> 
> Chirp (go/finch-chirp) could help for automated warnings of such a UMA. The
idea
> of a mass self destruct of subscriptions frightens me.
> 
> You're much more experienced with Chrome's server <--> client interaction,
> however, so I'm OK deferring to your judgement here.
> 
>
https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
> File components/gcm_driver/gcm_client_impl_unittest.cc (right):
> 
>
https://codereview.chromium.org/2450383003/diff/40001/components/gcm_driver/g...
> components/gcm_driver/gcm_client_impl_unittest.cc:1245: // checkin response is
> persisted.
> On 2016/11/01 00:18:16, Nicolas Zea wrote:
> > In this scenario there aren't any new histograms being recorded though. The
> > checkin has its own histogram for the response, but I'm not sure that's
> > something we should be verifying here.
> > 
> > Or do you think that we should record a different histogram in this
scenario?
> 
> Resetting the store would record to the GCM.ResetStore histogram, right? That
> means you'd be able to test it with something like
> 
> ASSERT_TRUE(histogram_tester_.ExpectTotalCount("GCM.ResetStore", 1));
> 
> Anyway, neither important nor blocking.

GCM.ResetStore, despite it's name, does not in fact record the times we reset
the store. Looks like it just records errors. I agree that we should probably
record reset store instances (and add chirp monitoring of volume). Will start a
followup CL for that.

[Nicolas Zea, 2016-11-01 17:19:31]

The CQ bit was checked by zea@chromium.org

[commit-bot: I haz the power, 2016-11-01 17:19:49]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-01 17:26:27]

Description was changed from

==========
[GCM] Reset store on checkin rejection and add checkin state to internals

First, this now handles cases where checkin is rejected for a non-retryable
reason by resetting the GCM store. UMA data shows that this is happening
less than 1% of the time, and likely implies profile corruption. Currently
we do not have any way to recover from this state.

Secondly, to help diagnose other checkin issues, I've also added checkin
information to chrome://gcm-internals. Namely last checkin time and next
scheduled checkin time. Recording is now on by default to make it easier
to record checkin events.

BUG=659373
==========

to

==========
[GCM] Reset store on checkin rejection and add checkin state to internals

First, this now handles cases where checkin is rejected for a non-retryable
reason by resetting the GCM store. UMA data shows that this is happening
less than 1% of the time, and likely implies profile corruption. Currently
we do not have any way to recover from this state.

Secondly, to help diagnose other checkin issues, I've also added checkin
information to chrome://gcm-internals. Namely last checkin time and next
scheduled checkin time. Recording is now on by default to make it easier
to record checkin events.

BUG=659373
==========

[commit-bot: I haz the power, 2016-11-01 17:26:28]

Committed patchset #6 (id:100001)

[commit-bot: I haz the power, 2016-11-01 17:53:04]

Description was changed from

==========
[GCM] Reset store on checkin rejection and add checkin state to internals

First, this now handles cases where checkin is rejected for a non-retryable
reason by resetting the GCM store. UMA data shows that this is happening
less than 1% of the time, and likely implies profile corruption. Currently
we do not have any way to recover from this state.

Secondly, to help diagnose other checkin issues, I've also added checkin
information to chrome://gcm-internals. Namely last checkin time and next
scheduled checkin time. Recording is now on by default to make it easier
to record checkin events.

BUG=659373
==========

to

==========
[GCM] Reset store on checkin rejection and add checkin state to internals

First, this now handles cases where checkin is rejected for a non-retryable
reason by resetting the GCM store. UMA data shows that this is happening
less than 1% of the time, and likely implies profile corruption. Currently
we do not have any way to recover from this state.

Secondly, to help diagnose other checkin issues, I've also added checkin
information to chrome://gcm-internals. Namely last checkin time and next
scheduled checkin time. Recording is now on by default to make it easier
to record checkin events.

BUG=659373

Committed: https://crrev.com/76342abff9abbb4413572ebb27d8a1dd6a5c91b6
Cr-Commit-Position: refs/heads/master@{#429033}
==========

[commit-bot: I haz the power, 2016-11-01 17:53:05]

Patchset 6 (id:??) landed as
https://crrev.com/76342abff9abbb4413572ebb27d8a1dd6a5c91b6
Cr-Commit-Position: refs/heads/master@{#429033}