Closed Bug 1213932 Opened 4 years ago Closed 4 years ago

Service Worker logs in webconsole show up in all tabs (even ones that aren't on the same origin as the worker)

Categories

(DevTools :: Console, defect)

defect
Not set

Tracking

(firefox43 wontfix, firefox44 fixed, firefox45 fixed)

RESOLVED FIXED
Firefox 45
Tracking Status
firefox43 --- wontfix
firefox44 --- fixed
firefox45 --- fixed

People

(Reporter: bgrins, Assigned: bgrins)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 1 obsolete file)

STR: 

Make sure devtools.webconsole.filter.serviceworkers is true in about:config or by checking the Logging -> Service Workers item in the webconsole

1) Open https://bgrins.github.io/devtools-demos/worker/push.html
2) Click 'init service worker'
3) Open webconsole
4) Notice a bunch of logs:
 * ServiceWorker initialized [object ServiceWorkerGlobalScope]
 * Handling fetch event for "https://bgrins.github.io/devtools-demos/worker/push.html"
 * ..etc (a bunch more logs)
5) Reload the page and notice that one of the logs is missing:
 * ServiceWorker initialized [object ServiceWorkerGlobalScope]
6) Close and reopen the toolbox and notice that the same log is back
 * ServiceWorker initialized [object ServiceWorkerGlobalScope]

The visible logs shouldn't ever change due to closing and reopening the toolbox.

The particular log in question is running outside of any callbacks in the SW: https://github.com/bgrins/devtools-demos/blob/37098cda65656d028f0c2db33d9387c035d2f460/worker/push-service-worker.js#L13.

The behavior seems unpredictable too - if I close the toolbox, reload the page, reopen the toolbox enough times it seems like I see the "ServiceWorker initialized [object ServiceWorkerGlobalScope]" a varying number of times in the log (it showed up three times and one point and then after opening and closing again it showed up twice).
The browser is free to kill and relaunch the service worker at any point.  As a developer you cannot rely on the global state or code executing outside of an event handler in service workers.

So at step 5, the browser probably did not need to restart the service worker because it was already running.

Its unclear to me what happened in step 6, though.  Does opening the toolbox trigger any network requests for the page (for script source, etc)?  If so, then it might cause the service worker to get launched again if it timed out.
One more thing I just noticed.  If I follow steps 1-4, then open a new tab on about:blank and open the toolbox then I see the same logs.  I'm thinking that logs from a service worker should only show up on the relevant tabs/domains that a service worker is active on, right?
Flags: needinfo?(bkelly)
Yes, something seems wrong here.  In step 6 its actually loading the logs for both the original load of the page and the refresh of the page.  Thats why that log message comes back.  Or at least thats what I'm seeing when I run the steps here.

The same original logs are loaded in about:blank like you said in comment 2.  That does seems bogus to me.
Flags: needinfo?(bkelly)
(In reply to Ben Kelly [:bkelly] from comment #3)
> Yes, something seems wrong here.  In step 6 its actually loading the logs
> for both the original load of the page and the refresh of the page.  Thats
> why that log message comes back.  Or at least thats what I'm seeing when I
> run the steps here.
> 
> The same original logs are loaded in about:blank like you said in comment 2.
> That does seems bogus to me.

Alright, let's get that sorted out before landing bug 1201962.

From Bug 1125205: "The idea is that the web console would show these messages iff the worker filename matches one of the scripts loaded in the page."  Panos, any ideas what's going on here?  Seems that the console isn't filtering messages based on the script name / origin of the service worker.  Was this working at some point?

0) Enable Logging -> Service Workers in the web console
1) Open https://bgrins.github.io/devtools-demos/worker/push.html
2) Click 'init service worker'
3) Open webconsole
4) Notice a bunch of logs:
 * ServiceWorker initialized [object ServiceWorkerGlobalScope]
 * Handling fetch event for "https://bgrins.github.io/devtools-demos/worker/push.html"
 * ..etc (a bunch more logs)
5) Open a new tab to eg https://www.mozilla.org/en-US/
6) Notice the same logs from step 4
Blocks: 1125205
Flags: needinfo?(past)
Summary: Some Service Worker logs in webconsole disappear after a reload but come back when reopening the toolbox → Service Worker logs in webconsole show up in all tabs (even ones that aren't on the same origin as the worker)
Also, is there a way to check the origin of the SW that logged the message instead of the file name so we wouldn't get any false positives if two separate origins had a service worker registered with the same file name?
(In reply to Brian Grinstead [:bgrins] from comment #5)
> Also, is there a way to check the origin of the SW that logged the message
> instead of the file name so we wouldn't get any false positives if two
> separate origins had a service worker registered with the same file name?

SW scripts are required to be same-origin.  So I don't think that can happen.
(In reply to Ben Kelly [:bkelly] from comment #6)
> (In reply to Brian Grinstead [:bgrins] from comment #5)
> > Also, is there a way to check the origin of the SW that logged the message
> > instead of the file name so we wouldn't get any false positives if two
> > separate origins had a service worker registered with the same file name?
> 
> SW scripts are required to be same-origin.  So I don't think that can happen.

I believe the logs are observed by all listeners in the process regardless of origin, so if a log happens from Tab A, then Tab B's observer sees it (and explicitly decides to ignore it).  If I'm reading Bug 1125205 correctly, then it appears that all SW logs get fired with a window ID of 'ServiceWorker' and each tab needs to process that log and decide if it should be shown.  And it seems something is going wrong in that process, at least when they are fetched via the ConsoleAPIStorage (since it reproduces when the tab is originally opened).
I don't think my original idea to filter out scripts by origin was actually implemented. Looking at the change in bug 1125205 it seems that it doesn't attempt to filter on ID, only innerID. It should be possible however to do so:

https://hg.mozilla.org/mozilla-central/diff/c8f9adecb1bc/dom/workers/test/test_consoleSharedWorkers.html

That was the reason these options aren't enabled by default in the web console, but only in the browser console.
Flags: needinfo?(past)
(In reply to Panos Astithas [:past] from comment #8)
> I don't think my original idea to filter out scripts by origin was actually
> implemented. Looking at the change in bug 1125205 it seems that it doesn't
> attempt to filter on ID, only innerID. It should be possible however to do
> so:
> 
> https://hg.mozilla.org/mozilla-central/diff/c8f9adecb1bc/dom/workers/test/
> test_consoleSharedWorkers.html
> 
> That was the reason these options aren't enabled by default in the web
> console, but only in the browser console.

Oh interesting, thanks for the info.  Definitely should block enabling the logs by default until this is fixed then.  I'll take a look at this.
Assignee: nobody → bgrinstead
Status: NEW → ASSIGNED
Attached patch serviceworker-messages.patch (obsolete) — Splinter Review
Work in progress.  This filters messages based on the worker's scope and window.location for the current window and all frames
This uses an approach I discussed with bkelly to determine whether a message logged from a SW is relevant to a particular page.  That is, instead of passing the filename as the ID field for SW messages, we are passing the worker's scope.

Then we can check if window.location.toString().startsWith to see if the message should be shown.  This is better than using scriptURL and the filename of the script, because it handles log messages that happen from a script loaded with importScripts().

Andrea, can you please look at the Console.cpp change?  I went ahead and renamed the local 'id' variable to 'innerID' to match how it's used.

Panos, if you are able to can you look at the JS changes?  Let me know if you aren't and I can re-assign.  I centralized the function to check for whether a message should be ignored since this is adding some extra logic into that.
Attachment #8682828 - Attachment is obsolete: true
Attachment #8683266 - Flags: review?(past)
Attachment #8683266 - Flags: review?(amarchesini)
Comment on attachment 8683266 [details] [diff] [review]
serviceworker-messages.patch

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

for the Console.cpp changes.
Attachment #8683266 - Flags: review?(amarchesini) → review+
Brian, I guess we should try to compare the scope to more than just window.location.  Can you show the message if it matches any of:

1) window.location
2) frame.src of any embedded iframe on the page
3) script URL of any Worker or SharedWorker used by the page

I'm not sure if you have the information for (2) or (3) readily available, but ultimately we want to match on those as well.  In theory the top level window may not be controlled, but one of its child frames or workers could be controlled.

This can be a follow-up.
Flags: needinfo?(bgrinstead)
(In reply to Ben Kelly [:bkelly] from comment #13)
> Brian, I guess we should try to compare the scope to more than just
> window.location.  Can you show the message if it matches any of:
> 
> 1) window.location
> 2) frame.src of any embedded iframe on the page
> 3) script URL of any Worker or SharedWorker used by the page
> 
> I'm not sure if you have the information for (2) or (3) readily available,
> but ultimately we want to match on those as well.  In theory the top level
> window may not be controlled, but one of its child frames or workers could
> be controlled.
> 
> This can be a follow-up.

For 2) that's already handled by the patch (see getLocationsForFrames in the patch).  For 3) an interesting thing is that normal web workers come through with the normal innerID/ID process and I'm not sure in what case a worker doesn't have a window and *isn't* a shared or service worker
Flags: needinfo?(bgrinstead)
(In reply to Brian Grinstead [:bgrins] from comment #14)
> For 2) that's already handled by the patch (see getLocationsForFrames in the
> patch).

Awesome!

> For 3) an interesting thing is that normal web workers come through
> with the normal innerID/ID process and I'm not sure in what case a worker
> doesn't have a window and *isn't* a shared or service worker

I'm not sure what you mean here.  What I'm trying to say is:

1) window at https://foo.com/index.html
2) creates new Worker('https://foo.com/lib/background.js');
3) the service worker scope is 'https://foo.com/lib'

So the message has an id of 'ServiceWorker:https://foo.com/lib'.  This does *not* match window.location or any iframe.  It does, however, match the Worker script.

Since Workers can be controlled even when their owning window is not controlled, we should show the console message.  (Of course we have SW bugs which prevent this atm.)
Blocks: 1221772
Comment on attachment 8683266 [details] [diff] [review]
serviceworker-messages.patch

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

Looks good to me, thanks!

::: devtools/shared/webconsole/test/test_console_serviceworker.html
@@ +3,5 @@
> +<head>
> +  <meta charset="utf8">
> +  <title>Test for the Console API and Service Workers</title>
> +  <script type="text/javascript" src="chrome://mochikit/content/tests/SimpleTest/SimpleTest.js"></script>
> +  <script type="text/javascript;version=1.8" src="common.js"></script>

Just curious: is the version number still needed now that "let" is enabled globally?

@@ +39,5 @@
> +  attachConsoleToTab(["ConsoleAPI"], onAttach);
> +});
> +addEventListener("load", startTest);
> +
> +function onAttach(aState, aResponse)

Heh, still liking the aFoo style?

@@ +44,5 @@
> +{
> +  onConsoleAPICall = onConsoleAPICall.bind(null, aState);
> +  aState.dbgClient.addListener("consoleAPICall", onConsoleAPICall);
> +
> +  info("Loading a ServiceWorker that will use console API")

Nit: missing semicolon

::: devtools/shared/webconsole/utils.js
@@ +977,5 @@
>      this.owner.onConsoleAPICall(apiMessage);
>    },
>  
>    /**
> +   * Given a message, return false if this window should show it and false

Typo: "return true if this window should show it"
Attachment #8683266 - Flags: review?(past) → review+
(In reply to Panos Astithas [:past] from comment #16)
> Comment on attachment 8683266 [details] [diff] [review]
> serviceworker-messages.patch
> 
> Review of attachment 8683266 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good to me, thanks!
> 
> ::: devtools/shared/webconsole/test/test_console_serviceworker.html
> @@ +3,5 @@
> > +<head>
> > +  <meta charset="utf8">
> > +  <title>Test for the Console API and Service Workers</title>
> > +  <script type="text/javascript" src="chrome://mochikit/content/tests/SimpleTest/SimpleTest.js"></script>
> > +  <script type="text/javascript;version=1.8" src="common.js"></script>
> 
> Just curious: is the version number still needed now that "let" is enabled
> globally?

It does work without version number, but asked some js folks and it sounds like it's safest to leave the version in for now just in case that feature doesn't ride the train.
https://hg.mozilla.org/mozilla-central/rev/1ed402253ec6
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 45
No longer blocks: 1217909
Blocks: 1222617
Comment on attachment 8683266 [details] [diff] [review]
serviceworker-messages.patch

Approval Request Comment
[Feature/regressing bug #]: service workers
[User impact if declined]: We want to ship service workers in 44 if we can.  Getting console.log() working correctly is needed.
[Describe test coverage new/current, TreeHerder]: None, as far as I can see.  Not sure how devtools tests work.
[Risks and why]: Minimal as this only affects service workers.
[String/UUID change made/needed]: None
Attachment #8683266 - Flags: approval-mozilla-aurora?
Ben, it was unclear to me, have you tested the fix manually? This is because you said "None" for test coverage. Given that size of the patch, I would like to feel a bit more reassured on whether we know the patch fixes the original problem or not. Sorry if I missed that in the history of the bug.
Flags: needinfo?(bkelly)
(In reply to Ritu Kothari (:ritu) from comment #21)
> Ben, it was unclear to me, have you tested the fix manually? This is because
> you said "None" for test coverage. Given that size of the patch, I would
> like to feel a bit more reassured on whether we know the patch fixes the
> original problem or not. Sorry if I missed that in the history of the bug.

There is a new mochitest added for this feature (it accounts for much of the size of the patch) - test_console_serviceworker.html.  It attaches the console to a tab, then registers a service worker for that window and makes sure log statements show up.
Oh, there is a test.  See comment 22.  I'm sorry for my confusion!  And yes, I did test locally.
Flags: needinfo?(bkelly)
That's awesome, patches that include new tests are always great! Thanks guys for the clarification.
Comment on attachment 8683266 [details] [diff] [review]
serviceworker-messages.patch

This has been in Nightly for a few days already and the patch adds a new test. Let's uplift to Aurora44.
Attachment #8683266 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
backed out from aurora for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=1472034&repo=mozilla-aurora
Flags: needinfo?(bgrinstead)
I'll take a look at this.
Flags: needinfo?(bkelly)
(In reply to Ben Kelly [:bkelly] from comment #28)
> I'll take a look at this.

Ah, I added an attachConsoleToTab function but it's only on 45.  The call to attachConsoleToTab(["ConsoleAPI"], onAttach); should be able to be replaced by _attachConsole(["ConsoleAPI"], onAttach, true);
Flags: needinfo?(bgrinstead)
Thanks!  Fixed patch pushed.

remote:   https://hg.mozilla.org/releases/mozilla-aurora/rev/056d07ff03c8
Flags: needinfo?(bkelly)
I'm assuming there's nothing else to uplift to aurora, so setting 44 to fixed.
Blocks: 1226061
I have reproduced this bug with Firefox aurora 43.0a2(build id:20151012004021)on
windows 7(64 bit)

I have verified as fixed this bug with Firefox beta 45.0b3(build id:20160204142810)
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.