Closed Bug 1215140 Opened 9 years ago Closed 9 years ago

log service worker interception errors to the console for non-navigations

Categories

(Core :: DOM: Service Workers, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla45
Tracking Status
firefox43 --- wontfix
firefox44 --- fixed
firefox45 --- fixed
b2g-v2.5 --- fixed

People

(Reporter: bkelly, Assigned: bkelly)

References

Details

Attachments

(10 files, 24 obsolete files)

11.07 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
7.44 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
3.10 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
7.19 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
4.94 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
22.26 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
9.59 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
4.79 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
11.54 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
8.35 KB, patch
bzbarsky
: review+
Details | Diff | Splinter Review
In bug 1173934 I added some logging when a navigation triggers a service worker interception that then fails.  We should really log messages for all failed interceptions.
I'm not going to be able to do this immediately, so let me write down my current plan:

1) Add a helper routine to log messages given an intercepted channel.  This could possible be InterceptedChannel::LogMessage() or something.  It would:
  a) Get the base channel from the intercepted channel
  b) Get the load info from the base channel
  c) Call nsILoadInfo::GetLoadingDocument() to maybe get the original document for the channel.
  d) If the document is available, get its window.
  e) Log the message, optionally using the window information if its present.
2) Change all the code that cancels the channel with an interception specific error code to directly log a message using the helper routine in (1).
3) Remove interception logging from nsDocShell and nsContentUtils.
4) Remove all interception specific error codes except for NS_ERROR_INTERCEPTION_FAILED.

Also, I'd like to improve the log messages themselves by doing:

5) Use JS::DescribeScriptedCaller() in FetchEvent::RespondWith() to capture the script file name and line number.  These can then be included in the log messages to link things up to the service worker script in devtools.
6) Update the log messages in dom.properties to include a %s format flag for the request URL that failed to be intercepted.
7) Include a %s format flag for the error value when respondWith() receives a rejected promise.
The main result of the changes in comment 1 would be:

1) Interception errors logged for all network requests, not just navigations.
2) Shown in web console for document related network requests.  Otherwise browser console.
3) Shows request URL to help the developer.
4) Shows respondWith() file and line number to help developer.
5) Shows respondWith() rejection value to help developer.
Blocks: ServiceWorkers-v1
No longer blocks: ServiceWorkers-postv1
Utility method for logging intercepted channel errors.  Note, this is main thread only, though, so I will need some runnable bouncing in the respondWith() handler.
Attached file logging_wip (obsolete) —
More work-in-progress.  This will probably not need P1 in the end.  Putting it on the in the channel.
It seems I may need to adjust my plan further.  I can't just log from the channel because the following happens on navigations:

1) Log message on intercepted channel's document.
2) nsDocShell gets an error and loads about:neterror
3) Message for (1) is wiped from the console by changing documents.

I think what I really need to do is push the pending log messages all the way to the nsINetworkInterceptController.  The controller can then log the message where appropriate.  For navigations this would be after any inner window changes.
Attached patch logging_wip (obsolete) — Splinter Review
This logs correctly for things like fetch(), but navigation logs go to browser console as mentioned in the previous comment.

Its possible I could also log the message to the outer window ID, but I'm not sure if that will really work or not with the web console wiping on navigation.
Attachment #8678353 - Attachment is obsolete: true
Attachment #8678403 - Attachment is patch: true
Ben, thanks for the pointer to the current code in nsDocShell::DisplayLoadError.

So here's one viable option.... Last I checked, our channels all implemented nsI(Writable)PropertyBag.  So one moderately hacky but likely effective thing to do would be to stash the message you want, or the info needed to generate the message, on the channel and then get it from there in DisplayLoadError, assuming aFailedChannel is the channel in question.
(In reply to Boris Zbarsky [:bz] from comment #7)
> So here's one viable option.... Last I checked, our channels all implemented
> nsI(Writable)PropertyBag.  So one moderately hacky but likely effective
> thing to do would be to stash the message you want, or the info needed to
> generate the message, on the channel and then get it from there in
> DisplayLoadError, assuming aFailedChannel is the channel in question.

I think that would work, but I'd prefer not to abuse PropertyBag.

I think maybe I will make an nsILogCollector native-only QI'able interface.  It will basically have

  interface nsILogCollector
  {
    void addPendingLog(<log params>);
    void maybeReportLogs(nsIDocument);
  }

I can then make HttpBaseChannel implement this interface.  The interception code will call MaybeReportLogs() on the channel when it is done intercepting, except if its a navigation.  For a navigation it will let nsDocShell call MaybeReportLogs() so it can pass the new document.
I still have some more work to do here, but what do you think of this Boris?

To use this I will:

1) Make InterceptedChannel* and HttpBaseChannel implement nsILogCollector.
2) These will just forward calls down to a mozilla::LogCollector owned by HttpBaseChannel.
3) For non-navigations, I will call MaybeReportLogs() inside the channel when it completes.
4) For navigations, I will wait and let nsDocShell call MaybeReportLogs using the new document.

Sound reasonable?
Attachment #8678456 - Flags: feedback?(bzbarsky)
Attachment #8677696 - Attachment is obsolete: true
Attachment #8678403 - Attachment is obsolete: true
Attachment #8678456 - Attachment is obsolete: true
Attachment #8678456 - Flags: feedback?(bzbarsky)
I still need to do some cleanup, but these patches correctly log the message on in the web console for both navigations and non-navigations.
Tweak some of the logged text.  Don't crash in the rejection case.
Attachment #8679094 - Attachment is obsolete: true
Still be done here:

1) Remove old interception logging.
2) Remove old error codes from ErrorList.h.  We only need a single NS_ERROR_INTERCEPTION_FAILED now.
3) Refactor ReportToConsole() to accept a spec string instead of nsIURI.
4) Add variadic template version of nsILogCollector::AddPendingLog() for convenience and use it in the FetchEvent.preventDefault() case.
Comment on attachment 8678456 [details] [diff] [review]
Add an nsILogCollector interface to support navigation channel logging. r=bz

Fwiw, the plan in comment 9 seems reasonable.
Attachment #8678492 - Attachment is obsolete: true
Attachment #8678493 - Attachment is obsolete: true
One last thing to do here before flagging for review.  I want to make FetchEvent.preventDefault() log the file/line in the console error message.
Blocks: 1217909
Attachment #8679677 - Flags: review?(bzbarsky)
Comment on attachment 8679678 [details] [diff] [review]
P2 Make HttpBaseChannel implement nsILogCollector.

Jason, for service workers we need to report logs after the channel completes in some cases.  For example, if a navigation is intercepted and something fails, the channel's LoadingDocument is disconnected already.  We need docshell to perform the log on the new about:neterror window so its visible in devtools.

This patch adds a new interface to HttpBaseChannel to let us accumulate logs on the channel that can later be flushed to the console.
Attachment #8679678 - Flags: review?(jduell.mcbugs)
Comment on attachment 8679680 [details] [diff] [review]
P3 Report pending logs on http channels.

This patch does the flushing of the accumulated log messages.  Jason, can you review the necko part?  Boris, can you review the docshell part?
Attachment #8679680 - Flags: review?(jduell.mcbugs)
Attachment #8679680 - Flags: review?(bzbarsky)
Comment on attachment 8679682 [details] [diff] [review]
P4 Make service worker respondWith() use channel LogCollector.

Convert current logging over to the new LogCollector approach.

Note, I think there is a minor merge error in the order of some of the AddPendingLog() calls here.  This is corrected in a later patch.  The overall patch queue compiles.  Sorry for this confusion, but it didn't seem worth spending time to fix an intermediate patch.
Attachment #8679682 - Flags: review?(bzbarsky)
Comment on attachment 8679683 [details] [diff] [review]
P5 Report the line number where respondWith() was called.

Enhance the FetchEvent.respondWith() code to log the correct file and line number.
Attachment #8679683 - Flags: review?(bzbarsky)
Comment on attachment 8679685 [details] [diff] [review]
P6 Update service worker interception error strings to include detailed par ameters.

This adds new log messages that take more detailed information about what went wrong.  All of them include at least the FetchEvent.request.url value which is essential for diagnosing any problem.

The old messages are removed in a later patch in this queue.

I'm sorry that this patch required more refactoring than I expected in order to pipe the arguments around correctly.
Attachment #8679685 - Flags: review?(bzbarsky)
Comment on attachment 8679686 [details] [diff] [review]
P7 Remove old service worker interception logging.

De-orbit old log messages.
Attachment #8679686 - Flags: review?(bzbarsky)
Comment on attachment 8679689 [details] [diff] [review]
P8 Remove now unnecessary interception values from ErrorList.h.

De-orbit specific interception failure codes.

We only had this level of detail in the nsresult value in order to log the right message.  Now that we include more information in the message, though, we have to log earlier.  So these error codes are no longer needed.
Attachment #8679689 - Flags: review?(bzbarsky)
Provide the file and line number where FetchEvent.preventDefault() was invoked to cancel the network request.
Attachment #8679760 - Flags: review?(bzbarsky)
Note, I used this site to test the various messages:

  https://blog.wanderview.com/sw-opaque-intercept/

I don't have a good way to provoke "unexpected" errors, though.

Note, the "throw in handler" case is not covered by this bug.  Its still broken and I need to fix in bug 1217909.  I figured I shouldn't hold this bug up, though.  I want to land before the merge due to the string changes.
Hmm, I will probably need to make a non-localized AddPendingLog() call to nsILogCollector in order to fix bug 1217909.  Not sure if I should do that here or just add it in the follow-up.
Comment on attachment 8679677 [details] [diff] [review]
P1 Add an nsILogCollector interface to support navigation channel logging. r=bz

So the only issue I have here is whether we should call it nsIConsoleReportCollector or something (and similar for the concrete class name), since it's not for general logging at all...

And then AddPendingConsoleReport instead of AddPendingLog.

Also, is there a reason we have the separate pure-virtual class?  Why do AddPendingLog/MaybeReportLogs really need to be virtual?  Do we expect them to be used from outside libxul?

>+LogCollector::MaybeReportLogs(nsIDocument* aDocument)
>+    // It would be nice if we did not have to do this since ReportToConsole()

I know you decided dealing with this was more trouble than it's worth for the moment, but is it worth a followup?

>+    UniquePtr<char16_t*> params;

This will do a delete on the pointer when done, whereas we want delete[], right?

I think this needs to be:

  UniquePtr<const char16_t*[]> params;

and then you can do things like params[j] = log.mStringParams[j].get().

>+        params.get()[j] = const_cast<char16_t*>(log.mStringParams[j].get());

Cast not needed if you make the type in the UniquePtr be const.

>+                                  const_cast<const char16_t**>(params.get()),

Again, cast should not be needed.

I worry a bit about calling out to the console service while still holding our mutex.  I don't trust that to not reenter random things.  It would be better, imo, to put an nsTArray<PendingLog> on the stack, take the mutex, SwapElements() into that array, release the mutex, then report the stuff from the stack array...

>+  MaybeReportLogs(nsIDocument* aDocument) = 0;

Why "Maybe"?  At the very least that needs to be documented, as does the fact that this clears the stuff we have queued up.

r=me with the above fixed.
Attachment #8679677 - Flags: review?(bzbarsky) → review+
Comment on attachment 8679678 [details] [diff] [review]
P2 Make HttpBaseChannel implement nsILogCollector.

Ah, this explains why you wanted a separate interface.  r=me; going to pretend like I'm still a necko peer.  ;)
Attachment #8679678 - Flags: review?(jduell.mcbugs) → review+
Comment on attachment 8679680 [details] [diff] [review]
P3 Report pending logs on http channels.

r=me
Attachment #8679680 - Flags: review?(bzbarsky) → review+
Comment on attachment 8679682 [details] [diff] [review]
P4 Make service worker respondWith() use channel LogCollector.

r=me
Attachment #8679682 - Flags: review?(bzbarsky) → review+
Comment on attachment 8679683 [details] [diff] [review]
P5 Report the line number where respondWith() was called.

r=me
Attachment #8679683 - Flags: review?(bzbarsky) → review+
Comment on attachment 8679685 [details] [diff] [review]
P6 Update service worker interception error strings to include detailed par ameters.

>+InterceptionFailedWithURL=Failed to load '%S'. A ServiceWorker intercepted the request and encounted an unexpected error.

s/encounted/encountered/

>+  JS::Rooted<JSString*> jsString(aCx, JS::ToString(aCx, aValue));

This is not great for two reasons:

1)  It can throw on aCx.  At the very least you need to clear the pending exception if it does.

2)  It can trigger side-effects depending on what aValue is.

I guess as long as we're ok with the latter, this is fine...

But, importantly, just because ToString() fails, e.g. because aValue is
{ toString: function() { throw "suckers"; } }, doesn't mean we shouldn't log.  It just means that we can't log the string.

r=me with those fixed.
Attachment #8679685 - Flags: review?(bzbarsky) → review+
Comment on attachment 8679686 [details] [diff] [review]
P7 Remove old service worker interception logging.

r=me
Attachment #8679686 - Flags: review?(bzbarsky) → review+
Comment on attachment 8679689 [details] [diff] [review]
P8 Remove now unnecessary interception values from ErrorList.h.

r=me
Attachment #8679689 - Flags: review?(bzbarsky) → review+
Comment on attachment 8679760 [details] [diff] [review]
P9 Provide file and line number when FetchEvent.preventDefault() cancels a request.

r=me
Attachment #8679760 - Flags: review?(bzbarsky) → review+
Attachment #8679680 - Flags: review?(jduell.mcbugs)
seems there are conflicts in part 1

renamed 1215140 -> bug1215140_p1_logcollector.patch
applying bug1215140_p1_logcollector.patch
patching file dom/base/ScreenOrientation.cpp
Hunk #1 FAILED at 10
1 out of 1 hunks FAILED -- saving rejects to file dom/base/ScreenOrientation.cpp.rej
patch failed, unable to continue (try -v)
patch failed, rejects left in working directory
errors during apply, please fix and refresh bug1215140_p1_logcollector.patch
Flags: needinfo?(bkelly)
Thanks Carsten, but I still need to rebase and address review feedback before these can land.  Sorry for the confusion.  I was not clear in my release-drivers email.
Flags: needinfo?(bkelly)
See Also: → 1219762
Blocks: 1219852
Attached patch P9 interdiff 001 (obsolete) — Splinter Review
Boris, does this look ok to you?  I need to forward the virtual PreventDefault(JSContext*) in order to silence these gcc build errors:

  https://treeherder.mozilla.org/#/jobs?repo=try&revision=b7a94354bfaf
Attachment #8680854 - Flags: review?(bzbarsky)
Attached patch P9 interdiff 001 (obsolete) — Splinter Review
I missed that there were two forward macros in Event.h.
Attachment #8680854 - Attachment is obsolete: true
Attachment #8680854 - Flags: review?(bzbarsky)
Attachment #8680860 - Flags: review?(bzbarsky)
Attached patch P9 interdiff 001 (obsolete) — Splinter Review
And one more tweak to not forward PreventDefault(JSContext*) from FetchEvent down to Event.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=08e44153aaaa
Attachment #8680860 - Attachment is obsolete: true
Attachment #8680860 - Flags: review?(bzbarsky)
Attachment #8680872 - Flags: review?(bzbarsky)
Comment on attachment 8680872 [details] [diff] [review]
P9 interdiff 001

r=me, I guess.  We should really kill off nsIDOMEvent....
Attachment #8680872 - Flags: review?(bzbarsky) → review+
Unfortunately HttpChannelChild does not have threadsafe ref-counting.  So these patches don't quite work on e10s.
So, I can't easily do a QI from nsIChannel to nsIConsoleReportCollector because the channel objects do not have thread safe ref counting.  (Well, HttpChannelChild does not, anyway.)

This patch exposes a method on the intercepted channel that casts the inner channel directly as a raw pointer.  Obviously, this is only safe due to the over-arching interception state machine.  While handling the FetchEvent in the ServiceWorker the nsIInterceptedChannel and its inner nsIChannel are kept alive.

I'm not thrilled about leaning on these life-cycle invariants, but its the best I can do in the short window I have to get the strings landed.  Also, the previous patches also depended on the same life-cycle rules in order to get the inner channel safely.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3afa39bb3639
Attachment #8680989 - Flags: review?(bzbarsky)
Comment on attachment 8680989 [details] [diff] [review]
P10 Avoid AddRef'ing the nsIChannel OMT. r=bz

r=me in the interests of getting this landed, but this seems really fragile.  Can we not, in a followup, stash the logs on the intercepted channel itself and them move them over to the right place when we're back on the main thread?
Attachment #8680989 - Flags: review?(bzbarsky) → review+
Blocks: 1220007
The try in comment 65 is not complete, but the problem tests in M-e10s(4) and W-e10s(8) have passed.  I'm going to land.
Attachment #8680989 - Attachment description: bug1215140_p10_noaddref.patch → P10 Avoid AddRef'ing the nsIChannel OMT. r=bz
Something bad happened when I was trying folding patches.  I lost some interdiffs somewhere.  Backing out.
Ah, all the code is there.  I just accidentally folded the P1 action items into P9.  The final files all look good relative to the review comments.  The console service is not used while holding a lock.  UniquePtr<[]> is used.  I also re-verified the code does not use ToString() and uses nsAutoJSString.Init() instead.

Sorry for the false alarm in comment 69.  Not backing out.
These patches apply cleanly to aurora.  Once they land in m-c I will flag for uplift approval.
While inbound has not merged to central yet, these patches look like they will stick.
Comment on attachment 8680774 [details] [diff] [review]
P1 Add an nsIConsoleReportCollector interface to support navigation channel log ging. r=bz

Requesting approval for all patches (P1 to P10).

Approval Request Comment
[Feature/regressing bug #]: Service workers
[User impact if declined]: Our current service worker error reporting is quite weak and gives web devs a bad experience.  This patch greatly improves the information we report for common errors.
[Describe test coverage new/current, TreeHerder]: Local testing of the console reporting.  Existing mochitests/wpt tests to verify I didn't break anything functional.
[Risks and why]: Minimal as it only affects service workers.
[String/UUID change made/needed]: Yes.  I needed to change the dom.properties strings to include detailed information format parameters. Note, this should land prior to the original string freeze of Nov 2.
Attachment #8680774 - Flags: approval-mozilla-aurora?
Blocks: 1220936
removing the b2g 2.5 flag since this commit has been reverted due to an incorrect merge, sorry for the confusion
Comment on attachment 8680774 [details] [diff] [review]
P1 Add an nsIConsoleReportCollector interface to support navigation channel log ging. r=bz

While this is a higher than normal code change in Aurora cycle, given that we are planning to ship Service Workers in FF44 and these patches have been in Nightly for about a week, it seems safe to uplift to Aurora. I wanted these patches to bake in Nightly a bit before uplifting and therefore missed the string change deadline by a few days, will keep pike posted.
Attachment #8680774 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Pike, please note this is another case where there are string changes in Aurora cycle and it makes sense to take them as we plan to ship Service Workers in FF44.
Flags: needinfo?(l10n)
Tomcat, Wes: N-I'ing to highlight that all the patches need to land on Aurora. Thanks!
Flags: needinfo?(wkocher)
Flags: needinfo?(cbook)
Flags: needinfo?(l10n)
Flags: needinfo?(cbook)
Depends on: 1261070
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: