1222617 - Service worker logs should disappear after a reload and opening the console

Status: RESOLVED FIXED

(DevTools :: Console, defect)

Description

[Brian Grinstead [:bgrins]]

Usually console API messages are removed when a window is reloaded.  For SW messages they persist beyond the lifetime of a page so if you reload a page and they open the console you will see messages that happened way earlier.

SW messages should match the behavior of normal messages in this regard.  We probably need to somehow compare the timeStamp of a message with the time that a page was last destroyed.  I believe this happens here for normal messages: https://dxr.mozilla.org/mozilla-central/source/dom/base/ConsoleAPIStorage.js#66

Comment 1

[Brian Grinstead [:bgrins]]

Attachment: console-sw-cached-messages.patch

I started working on this and have something that appears to fix this particular case, but I noticed something weird when working on a test for it.  Since shouldReportToWindow is only called once getCachedMessages is called, it will decide to filter out or include messages based on the state of the page when that function is called instead of the state of the page when the message is logged.

As a user, I'd expect that any messages that were relevant at the time they were logged would show up.  The changes to the test case here demonstrate the issue.  Specifically, notice that we need to re-navigate to a scoped URL on the frame before calling getCachedMessages or else no messages are returned.  And after we do the navigation, ALL messages are returned (even those that are expected to be filtered like 'message event: Tic Tock').

Ben, does the problem here make sense?  Any ideas of ways that we could encode the shouldReportToWindow decision into the message itself (my best idea so far would be to somehow serialize relevant window ids into the innerID field on the message).

Comment 2

[Ben Kelly [:bkelly, not reviewing]]

Ok, so if I understand correctly a nested iframe is becoming controlled, but we're not changing the top level window.  So the code here only checks the timestamp of the top level window we end up replaying all console messages and get the new state.

IMO this is not going to be something devs see very much.  The code does, however, make the current situation materially better because the vast majority of duplicate logs are filtered out.

I would like to land this change, enable service worker logging, and file a bug about nested iframe weirdness.  What do you think?

Comment 3

[Brian Grinstead [:bgrins]]

Filed Bug 1226061 to handle this less critical case, and I'll wrap this one up by writing a new test without frames involved.

Comment 4

[Brian Grinstead [:bgrins]]

Attachment: MozReview Request: Bug 1222617 - Filter out service worker messages that happened before a page load;r=bkelly

Bug 1222617 - Filter out service worker messages that happened before a page load;r=bkelly

Comment 5

[Brian Grinstead [:bgrins]]

Ben, can you please review that this is filtering out what you'd expect?  I've added a new test case that attaches two tabs to check to be sure the script eval / install / activate logs don't happen on the second tab (although a fetch for the page itself does).

I'm not positive that performance.timing.requestStart is exactly the timestamp what we want in all cases (like I'm not sure *exactly* the moment when the SW is controlling a window), but it seems to work for me on all my test pages and in this new test.

Comment 6

[Ben Kelly [:bkelly, not reviewing]]

Comment on attachment 8689833 [details]
MozReview Request: Bug 1222617 - Filter out service worker messages that happened before a page load;r=bkelly

https://reviewboard.mozilla.org/r/25731/#review23151

Looks great.  Thanks!

Comment 7

[Ben Kelly [:bkelly, not reviewing]]

Brian, can you flag this for uplift to aurora after you land it?

Comment 8

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/8cab032fa1e9

Comment 9

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/8cab032fa1e9

Comment 10

[Brian Grinstead [:bgrins]]

Comment on attachment 8689833 [details]
MozReview Request: Bug 1222617 - Filter out service worker messages that happened before a page load;r=bkelly

Approval Request Comment
[Feature/regressing bug #]: Service workers (bug 1059784)
[User impact if declined]: Webconsole logs coming from a service worker will show up in a tab even if the log statement happened before the tab was loaded
[Describe test coverage new/current, TreeHerder]: A new mochitest for the webconsole was added for this chagne
[Risks and why]: Pretty small code change that affects webconsole filtering, specifically targeted at only Service Worker logs.  As such it won't affect 'normal' logs and isn't super risky.
[String/UUID change made/needed]:

Comment 11

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8689833 [details]
MozReview Request: Bug 1222617 - Filter out service worker messages that happened before a page load;r=bkelly

This fix has been on Nightly for a few days so it seems safe. Also, removing SW logs from webconsole when a page is closed and re-opened makes sense. Let's uplift to Aurora44.

Comment 12

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b02dc2a2305e

Comment 13

[Carsten Book [:Tomcat]]

sorry had to back this out for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=1537006&repo=mozilla-aurora

Comment 14

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-b2g44_v2_5/rev/27a9ba2d01e9

Comment 15

[Brian Grinstead [:bgrins]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/27a9ba2d01e9