623080 - Make Resource more robust and loggy

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Richard Newman [:rnewman]]

... and prepare for retries, if that proves to be necessary.

Comment 1

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v1

This patch does the following:

* Correction of old grammar and spelling errors in comments. I can't help myself.

* Additional logging throughout _doRequest, _onComplete, onStartRequest, onStopRequest.

* Removes the hacky retry on status 0, which I believe to have been caused by coding errors in this module. Removes the test for that retry.

* Restructures onComplete to process headers after more important things, and use more sophisticated error handling to get through unscathed (and with more logging).

* Notifies on failure using the same mechanism as for 401s; eventually this will allow Weave.Service to suggest a retry. This code will arrive in a later patch, because it's not done yet, but I'd rather get this part in with its friends.

* Exceptions are attached to Errors and propagated. This will allow observers to see the original network error (and error code), rather than examining strings.

Tests pass. I would like more of them, but given that we can't reproduce the failures that this is trying to work around...

Comment 2

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v2

This is an updated version of v1, against current fx-sync.

Unlike v1, it makes no attempt to notify observers or otherwise handle failures in any new way; it just logs things that we and the necko devs need to debug problems, and rejigs _onComplete to not screw things up if an error occurs fetching headers.

Comment 3

[Richard Newman [:rnewman]]

Nominating for blocking (b12? Final?) per IRC discussion with Philipp. This achieves two goals:

* Fixes some sucky code in onComplete.
* Makes it easier to debug.

Your call, mconnor.

Comment 4

[Mike Connor [:mconnor]]

Not a blocker, but would likely approve a safe patch.

Comment 5

[Philipp von Weitershausen [:philikon]]

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

In that case I propose mconnor reviewed this to assess the "safety"

Comment 6

[Richard Newman [:rnewman]]

Away!

https://hg.mozilla.org/services/services-central/rev/7b7cb3e1360d

Comment 7

[Richard Newman [:rnewman]]

Attachment: STR example log.

Very minor STR for QA:

* Set services.sync.log.logger.network.resources to Trace.
* Restart.
* Sync now.
* In about:sync-log, you should see something structurally similar to the attached log; in particular, note that Status: and Success: are logged. Note that "Processing response headers" is logged *after* status and success are logged.

Comment 8

[Tracy Walker [:tracy]]

Verified with s-c central builds from last night.

Comment 9

[Philipp von Weitershausen [:philikon]]

http://hg.mozilla.org/mozilla-central/rev/7b7cb3e1360d

Comment 10

[Richard Newman [:rnewman]]

Attachment: Missing code deletion.

Missed this the first time around.

Comment 11

[Richard Newman [:rnewman]]

Attachment: Missing code deletion. v2

Forgot to delete dead tests, too.

Comment 12

[Philipp von Weitershausen [:philikon]]

Comment on attachment 527461 [details] [diff] [review]
Missing code deletion. v2

11:36 <@philikon> since the original patch went in
11:36 <@philikon> we first get the status code
11:36 <@philikon> and then prepare to fail on headers
11:36 <@philikon> separately, that is
11:36 <@philikon> so that's all good
11:37 <@philikon> and it probably means the if (status == 0) code that you're removing is now defunkt anyway
11:37 <@rnewman> exactly
11:37 <@philikon> however
11:37 <@philikon> doesn't it still mean we're seeing cached responses?
11:37 <@philikon> worse even, we're now not refetching them
11:37 <@philikon> like we used to
11:37 <@rnewman> unknown
11:38 <@rnewman> I haven't seen any reports that would suggest it
11:38 <@philikon> so the cached response thing was just a hypothesis?
11:38 <@philikon> for when fetching headers failed
11:38 <@philikon> symptom: fetching headers  failed. root cause: unknown?
11:39 <@rnewman> well, the caching...
11:39 <@rnewman> was the diagnosis that mardak wrote in the original code
11:39 <@philikon> oh
11:39 <@rnewman> no idea what the actual root cause was
11:39 <@philikon> ok
11:40 <@philikon> but it might've just been guess work on his side
11:40 <@rnewman> an alternative version of this patch added observers for failures, so if we wanted to do logic like 
                 "retry if we fail to get headers", we could do so
11:40 <@rnewman> but the status 0 check is no longer relevant
11:40 <@philikon> yeah i understand that
11:41 <@philikon> i just want us to be aware of the fact that the original patch for that bug made us regress
11:41 <@philikon> in a way
11:41 <@philikon> failing to get headers now no longer causes a re-get
11:41 <@philikon> that's probably fine
11:41 <@rnewman> yus
11:41 <@philikon> (i honestly don't know)
11:41 <@philikon> i juts wanted to clarify that