622760 - Log exceptions thrown in _onProgress callbacks

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Philipp von Weitershausen [:philikon]]

Collection extends Resource to define _onProgress. That allows it to process data as it comes in over the network. Each chunk (read: WBO) is processed by recordHandler, a function that's set by whoever uses the collection. The only case that ever happens is in SyncEngine where the record is parsed, decrypted, and store.applyIncoming() is called on it.

If we fail anywhere along the line of there (and there are many potential places), Necko seems to catch the exception that occurred and pass it into the _onComplete callback as a status code. We then convert the status code to an exception and throw it. Res_get() will be on the resulting stack.

I think Necko's behaviour is sensible and we should keep it because a dodgy _onProgress call should throw. We should still log the actual exception, though.

Comment 1

[Philipp von Weitershausen [:philikon]]

To be clear, I think the catching and logging should be done in ChannelListener.onDataAvailable() where we call this._onProgress().

Comment 2

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v1

A little verbose, but gives more clarity than an all-encompassing try block about precisely what went wrong.

Comment 3

[Philipp von Weitershausen [:philikon]]

Comment on attachment 500975 [details] [diff] [review]
Proposed patch. v1

Uh, this is a patch for bug 622762. It doesn't at all change ChannelListener.onDataAvailable()'s behaviour.

Comment 4

[Richard Newman [:rnewman]]

(In reply to comment #3)

> Uh, this is a patch for bug 622762. It doesn't at all change
> ChannelListener.onDataAvailable()'s behaviour.

Nope, this is catch + log + rethrow, at the point of error: "Log exceptions thrown in _onProgress callbacks". No change in behavior beyond useful log messages.

Bug 622762 is log, yes, but that (IMO) is the bug for "... and keep processing". This patch doesn't address that.

Comment 5

[Philipp von Weitershausen [:philikon]]

(In reply to comment #3)
> Uh, this is a patch for bug 622762.

Actually not even that, even though it's similar to what we want for bug 622762. Anyway, the reason why I split this up into this bug and bug 622762 is as follows:

I think we want to do some general exception logging for all _onProgress handlers, not just specific ones. This should be done in resource, specifically in ChannelListener.onDataAvailable() where we call _onProgress in the first place. This place is completely agnostic of collections, engines etc. It's our way of ensuring that when Necko passes in a failure that doesn't smell like a network failure, it happened in the _onProgress handler.

So this bug will take care of logging that exception. Bug 622762 is about making sure we do exception handling for anything thrown in SyncEngine's recordHandler. We should log those exceptions and catch them, but at the end of the day still report the failure back. We don't have to do that in form of an exception, we can maybe do it by means of an observer notification or just setting the right Status bits.

Comment 6

[Philipp von Weitershausen [:philikon]]

(In reply to comment #4)
> Nope, this is catch + log + rethrow, at the point of error: "Log exceptions
> thrown in _onProgress callbacks". No change in behavior beyond useful log
> messages.

Yes, absolutely useful. My critique really is about the level where we're doing this. I think we should do it in ChannelListener.onDataAvailable() because that's a generic place. After all, this could happen to any _onProgress handler.

> Bug 622762 is log, yes, but that (IMO) is the bug for "... and keep
> processing". This patch doesn't address that.

You're right, I misread the patch initially.

Comment 7

[Richard Newman [:rnewman]]

(In reply to comment #6)

> Yes, absolutely useful. My critique really is about the level where we're doing
> this. I think we should do it in ChannelListener.onDataAvailable() because
> that's a generic place. After all, this could happen to any _onProgress
> handler.

Agreed! Good catch. Didn't occur to me. (NEED MOAR SLEEPS)

Comment 8

[:Atoll]

We'll need this to continue diagnosing mrz's issues.

Comment 9

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v2

Logs in onDataAvailable. Tests show the effects on logging, and also the exceptions we get from native code versus JS.

Comment 10

[Philipp von Weitershausen [:philikon]]

Comment on attachment 501190 [details] [diff] [review]
Proposed patch. v2

>+    try {
>+      this._onProgress();
>+    } catch (ex) {
>+      this._log.warn("Got exception calling onProgress handler during fetch of "
>+                     + req.URI.spec);
>+      Utils.stackTrace(ex);

I think you're confusing what Utils.stackTrace does. It just trims all the rubbish out of the stack trace and returns it. So you really want to wrap that in a log call, e.g.:

  this._log.debug(Utils.stackTrace(ex));

>+      this._log.debug("Rethrowing; expect a failure code from the HTTP channel.");

This sounds verbose if not unnecessary... Maybe make it trace?

>diff --git a/services/sync/tests/unit/test_resource.js b/services/sync/tests/unit/test_resource.js
>index 264e81d..d3ccacd 100644
>--- a/services/sync/tests/unit/test_resource.js
>+++ b/services/sync/tests/unit/test_resource.js

Please add those tests to test_resource_async.js as well!

r=me with those changes.

Comment 11

[Richard Newman [:rnewman]]

Pushed with review changes.

http://hg.mozilla.org/services/fx-sync/rev/cb2f7e7896da