Brian Grinstead [:bgrins] Assignee
	Description • 9 years ago

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).

	Ben Kelly [:bkelly, not reviewing]
	Comment 1 • 9 years ago

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.

	Brian Grinstead [:bgrins] Assignee
	Comment 2 • 9 years ago

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?

	Ben Kelly [:bkelly, not reviewing]
	Comment 3 • 9 years ago

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.

	Brian Grinstead [:bgrins] Assignee
	Comment 4 • 9 years ago

(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

	Brian Grinstead [:bgrins] Assignee
	Comment 5 • 9 years ago

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?

	Ben Kelly [:bkelly, not reviewing]
	Comment 6 • 9 years ago

(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.

	Brian Grinstead [:bgrins] Assignee
	Comment 7 • 9 years ago

(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).

	Panos Astithas (he/him) [:past] (please ni?)
	Comment 8 • 9 years ago

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.

	Brian Grinstead [:bgrins] Assignee
	Comment 9 • 9 years ago

(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.

	Brian Grinstead [:bgrins] Assignee
	Comment 10 • 9 years ago

Work in progress.  This filters messages based on the worker's scope and window.location for the current window and all frames

	Brian Grinstead [:bgrins] Assignee
	Comment 11 • 9 years ago

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.

	Andrea Marchesini [:baku]
	Comment 12 • 9 years ago

Comment on attachment 8683266 [details] [diff] [review]
serviceworker-messages.patch

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

for the Console.cpp changes.

	Ben Kelly [:bkelly, not reviewing]
	Comment 13 • 9 years ago

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.

	Brian Grinstead [:bgrins] Assignee
	Comment 14 • 9 years ago

(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

	Ben Kelly [:bkelly, not reviewing]
	Comment 15 • 9 years ago

(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.)

	Panos Astithas (he/him) [:past] (please ni?)
	Comment 16 • 9 years ago

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"

	Brian Grinstead [:bgrins] Assignee
	Comment 17 • 9 years ago

(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.

	Pulsebot
	Comment 18 • 9 years ago

https://hg.mozilla.org/integration/fx-team/rev/1ed402253ec6

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 19 • 9 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/1ed402253ec6

	Ben Kelly [:bkelly, not reviewing]
	Comment 20 • 9 years ago

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

	Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)
	Comment 21 • 9 years ago

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.

	Brian Grinstead [:bgrins] Assignee
	Comment 22 • 9 years ago

(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.

	Ben Kelly [:bkelly, not reviewing]
	Comment 23 • 9 years ago

Oh, there is a test.  See comment 22.  I'm sorry for my confusion!  And yes, I did test locally.

	Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)
	Comment 24 • 9 years ago

That's awesome, patches that include new tests are always great! Thanks guys for the clarification.

	Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)
	Comment 25 • 9 years ago

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.

	Carsten Book [:Tomcat]
	Comment 26 • 9 years ago
bugherder uplift

https://hg.mozilla.org/releases/mozilla-aurora/rev/73a1ad6ba6ed

	Carsten Book [:Tomcat]
	Comment 27 • 9 years ago

backed out from aurora for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=1472034&repo=mozilla-aurora

	Ben Kelly [:bkelly, not reviewing]
	Comment 28 • 9 years ago

I'll take a look at this.

	Brian Grinstead [:bgrins] Assignee
	Comment 29 • 9 years ago

(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);

	Ben Kelly [:bkelly, not reviewing]
	Comment 30 • 9 years ago

Thanks!  Fixed patch pushed.

remote:   https://hg.mozilla.org/releases/mozilla-aurora/rev/056d07ff03c8

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 31 • 9 years ago

I'm assuming there's nothing else to uplift to aurora, so setting 44 to fixed.

	Carsten Book [:Tomcat]
	Comment 32 • 9 years ago
bugherder uplift

https://hg.mozilla.org/releases/mozilla-b2g44_v2_5/rev/056d07ff03c8

	Kazi Nuzhat Tasnem
	Comment 33 • 9 years ago

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