1010531 - Sync spinning callback error path throws in two places, causing unhandled promise rejections and potential terror

Status: VERIFIED FIXED

(Cloud Services :: Firefox: Common, defect)

Description

[David Teller [:Yoric] - still alive but not very active]

This is one of the last few blockers for bug 976205. Unfortunately, I seems that I don't understand the code of Sync/FxA sufficiently to fix this.

Comment 1

[Mark Hammond [:markh] [:mhammond]]

Marco, can you please add this to the current iteration?

Comment 2

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0002-Bug-1010531-avoid-unhandled-promise-rejection-fetchi.patch

This seems to be caused by an unexpected (to me) implementation of makeSpinningCallback() - hence asking rnewman for review as he has the best understanding of those semantics.

consider this code:

   let cb = Async.makeSpinningCallback();
   somePromise().then(..., err => {cb(null, err)};
   cb.wait();

I've always understood that the cb.wait() will throw - that's kind-of the point.  What I *didn't* understand is that the cb(null, err) call *also* itself throws the very exception being passed in.

Richard, assuming I'm not missing something, then this patch simply catches and ignores the error doing the cb(null, err), which would be the right thing to do.

Or I am missing something and this patch would not be correct :)  With this patch the tests all still pass without logging the promise rejection message.

(FTR, the specific test failing is test_fxa_service_cluster.js)

Comment 3

[Marco Mucci [:MarcoM]]

Thanks for the update Mark.  Bug has been added to the iteration.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

Note that these tests show up as EXPECTED-FAIL at the moment. The will show as UNEXPECTED-FAIL once bug 976205 lands.

Comment 5

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8422858 [details] [diff] [review]
0002-Bug-1010531-avoid-unhandled-promise-rejection-fetchi.patch

Review of attachment 8422858 [details] [diff] [review]:
-----------------------------------------------------------------

::: services/sync/modules/browserid_identity.js
@@ +673,5 @@
>        } else {
>          // callback with an error - cb.wait() completes by raising an exception.
> +        // BUT - it *also* causes cb(err) to throw the same exception!  This
> +        // causes this promise chain to see an unhandled rejection - so mute
> +        // this exception (cb.wait() still throws though)

Nit: I'd put that comment in the `catch` clause.

Comment 6

[Richard Newman [:rnewman]]

Comment on attachment 8422858 [details] [diff] [review]
0002-Bug-1010531-avoid-unhandled-promise-rejection-fetchi.patch

Review of attachment 8422858 [details] [diff] [review]:
-----------------------------------------------------------------

I wonder if this is simply an error?

E.g., we have storage callbacks like

    handleError: function handleError(error) {
      this.syncCb.throw(error);
    },

and I'd be surprised if every single internal invoker of callback APIs will correctly handle errors in callbacks.

I'd be inclined to try removing that caller-throw, leaving only the one in waitForSyncCallback, and see if anything breaks...

Clearing review pending that investigation.

Comment 7

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0001-Prevent-async-callback-from-throwing-when-a-callback.patch

There were a couple of obvious places where the code assumed the current behaviour.  These were relatively easy to fix, but it leaves me worries I missed a couple that aren't covered by unit tests.  OTOH, a grep for ".throw" didn't show any.

ISTM this fix is potentially more risky, but YMMV.

Comment 8

[Richard Newman [:rnewman]]

Comment on attachment 8425143 [details] [diff] [review]
0001-Prevent-async-callback-from-throwing-when-a-callback.patch

Review of attachment 8425143 [details] [diff] [review]:
-----------------------------------------------------------------

It worries me that this doesn't cause any test failures.

::: services/common/async.js
@@ -80,5 @@
>        onComplete.state = CB_FAIL;
>        onComplete.value = data;
> -
> -      // Cause the caller to get an exception and stop execution.
> -      throw data;

Let's document this behavior at the top of the method.

Comment 9

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0001-Prevent-async-callback-from-throwing-when-a-callback.patch

(In reply to Richard Newman [:rnewman] from comment #8)
> It worries me that this doesn't cause any test failures.

Not quite sure what you mean here, but try at https://tbpl.mozilla.org/?tree=Try&rev=a51e9ca4e5e0

> Let's document this behavior at the top of the method.

Done

Comment 10

[Richard Newman [:rnewman]]

Comment on attachment 8428437 [details] [diff] [review]
0001-Prevent-async-callback-from-throwing-when-a-callback.patch

Review of attachment 8428437 [details] [diff] [review]:
-----------------------------------------------------------------

By "worries me" I mean that we're evidently not testing the failure paths enough, else you would have had to fix some tests that were expecting an exception!

Comment 11

[Richard Newman [:rnewman]]

Let's take this for 32, making sure that TPS is happy, and getting some manual QA for whatever error approaches are possible to induce by hand.

Comment 12

[Mark Hammond [:markh] [:mhammond]]

https://hg.mozilla.org/integration/fx-team/rev/3c801fd746db

Comment 13

[Tim Taubert [:ttaubert] (inactive)]

https://hg.mozilla.org/mozilla-central/rev/3c801fd746db

Comment 14

[[SV Manager] Florin Mezei, QA (:FlorinMezei)]

Assigning to Tracy for verification, since this is related to Sync.

Comment 15

[Marco Mucci [:MarcoM]]

Hi Tracy, will it be possible to have this bug verified by end of day this Friday?  Our current Iteration ends on Monday June 9.

Comment 16

[Tracy Walker [:tracy]]

(In reply to Marco Mucci [:MarcoM] from comment #15)
> Hi Tracy, will it be possible to have this bug verified by end of day this
> Friday?  Our current Iteration ends on Monday June 9.

Yes, but this one is clear cut reproducible, indicated by the initial [qa-].

rnewman, what can trigger this potential terror manually on the client side here?  no network?

Comment 17

[Richard Newman [:rnewman]]

We've always used [qa-] as "doesn't need QA" (usually covered by tests). [qa+] means "please test this for me".

Comment 18

[Tracy Walker [:tracy]]

rnewman, sorry, my statement was missing "not" as in "is *not* clear cut reproducible."  

Thus why I asked for guidance to reproduce. I don't know what callback rejections and unhandled promise rejections are. So I don't know what to be testing for here.

Comment 19

[Richard Newman [:rnewman]]

(In reply to [:tracy] Tracy Walker - QA Mentor from comment #18)
> rnewman, sorry, my statement was missing "not" as in "is *not* clear cut
> reproducible."  

Gotcha.

> Thus why I asked for guidance to reproduce. I don't know what callback
> rejections and unhandled promise rejections are. So I don't know what to be
> testing for here.

This patch affects handling of internal error flows. If you have a way of testing a corrupt bookmark DB, a non-functioning passwords DB (e.g., install Keychain Services Integration add-on), or network errors, just make sure that behavior hasn't changed.

Comment 20

[Marco Mucci [:MarcoM]]

Hey Kairo, with Tracy on PTO can this bug be reassigned to another QA contact for verification.

Comment 21

[Robert Kaiser]

Per Firefox QA meeting, forwarding this to Kevin for now. Marco, thanks for spotting this!

Comment 22

[Marco Mucci [:MarcoM]]

Hi Kevin, the desktop iteration ends on Monday.  Is it possible to have this bug verified by then.

Comment 23

[Kevin Brosnan [Ex-Mozilla]]

I looked into this to be able to verify this I would need a subtly corrupted sqlite database based on comment 19. I have created several corrupt databases however Firefox detects them at startup and moves them to .corrupt files. So unless Tracy has such a file we won't be able to verify this issue.

Comment 24

[Tracy Walker [:tracy]]

I checked this fix this morning by installing the add-on rnewman suggested.  With the add-on enabled, Syncing gets the encountered an error message bar with the following in the log.

1405347201740	Sync.ErrorHandler	DEBUG	passwords failed: TypeError: Services.logins is undefined (resource://gre/modules/services-sync/engines/passwords.js:162:8) JS Stack trace: [e-mail]:162:9 < [e-mail]:884:22 < [e-mail]:1479:7 < [e-mail]:141:21 < [e-mail]:655:5 < [e-mail]:199:7 < [e-mail]:149:15 < [e-mail]:1271:7 < [e-mail]:141:21 < [e-mail]:96:16 < [e-mail]:1261:12 < sync/<@service.js:1253:14 < [e-mail]:70:16 < [e-mail]:1241:5

<snip>

1405347202058	Sync.Synchronizer	INFO	Sync completed at 2014-07-14 09:13:22 after 0.87 secs.
1405347202059	Sync.Declined	DEBUG	Handling remote declined: ["passwords"]
1405347202059	Sync.Declined	DEBUG	Handling local declined: []
1405347202059	Sync.Declined	DEBUG	Declined changed? true
1405347202059	Sync.Service	DEBUG	Uploading meta/global: {"payload":"{\"syncID\":\"Wd0jgDsvVqLT\",\"storageVersion\":5,\"declined\":[],\"engines\":{\"clients\":{\"version\":1,\"syncID\":\"AN0PscwpQmYJ\"},\"bookmarks\":{\"version\":2,\"syncID\":\"dDcjb5qILv7R\"},\"forms\":{\"version\":1,\"syncID\":\"Zwh_LTALGv9M\"},\"history\":{\"version\":1,\"syncID\":\"_ifP_Qibx7Pe\"},\"prefs\":{\"version\":2,\"syncID\":\"WFBxpS7p448T\"},\"tabs\":{\"version\":1,\"syncID\":\"N_W7KkI8x9gO\"},\"addons\":{\"version\":1,\"syncID\":\"VkMM6mkTdaj7\"},\"passwords\":{\"version\":1,\"syncID\":\"AkW4is88t7Fh\"}}}","modified":1400522058.97,"id":"global"}
1405347202060	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
1405347202060	Sync.Resource	DEBUG	PUT Length: 577
1405347202156	Sync.Resource	DEBUG	mesg: PUT success 200 https://sync-34-us-west-2.sync.services.mozilla.com/1.5/1407510/storage/meta/global
1405347202156	Sync.Resource	DEBUG	PUT success 200 https://sync-34-us-west-2.sync.services.mozilla.com/1.5/1407510/storage/meta/global
1405347202158	Sync.SyncScheduler	DEBUG	Next sync in 90000 ms.
1405347202158	Sync.ErrorHandler	DEBUG	Some engines did not sync correctly.

I think this is now expected.

Comment 25

[:Gavin Sharp [email: [e-mail]]]

Marco: we should drop this from the backlog while Mark is away.

Comment 26

[:Gavin Sharp [email: [e-mail]]]

Er, I misread! Nevermind!