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

RESOLVED FIXED in Firefox 44

Status

()

Firefox
Developer Tools: Console
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: bgrins, Assigned: bgrins)

Tracking

(Blocks: 2 bugs)

unspecified
Firefox 45
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox44 fixed, firefox45 fixed)

Details

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment, 1 obsolete attachment)

(Assignee)

Description

3 years ago
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
(Assignee)

Comment 1

3 years ago
Created attachment 8689218 [details] [diff] [review]
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).
Flags: needinfo?(bkelly)

Comment 2

3 years ago
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?
Flags: needinfo?(bkelly)
(Assignee)

Updated

3 years ago
Blocks: 1226061
(Assignee)

Comment 3

3 years ago
Filed Bug 1226061 to handle this less critical case, and I'll wrap this one up by writing a new test without frames involved.
Assignee: nobody → bgrinstead
Status: NEW → ASSIGNED
(Assignee)

Comment 4

3 years ago
Created attachment 8689833 [details]
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
Attachment #8689833 - Flags: review?(bkelly)
(Assignee)

Comment 5

3 years ago
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.
(Assignee)

Updated

3 years ago
Attachment #8689218 - Attachment is obsolete: true

Comment 6

3 years ago
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!
Attachment #8689833 - Flags: review?(bkelly) → review+

Comment 7

3 years ago
Brian, can you flag this for uplift to aurora after you land it?
Flags: needinfo?(bgrinstead)
(Assignee)

Updated

3 years ago
Blocks: 943220
Flags: needinfo?(bgrinstead)

Comment 9

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/8cab032fa1e9
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
status-firefox45: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 45
(Assignee)

Comment 10

3 years ago
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]:
Attachment #8689833 - Flags: approval-mozilla-aurora?
Depends on: 1227139

Updated

3 years ago
status-firefox44: --- → affected
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.
Attachment #8689833 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+

Comment 12

3 years ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/b02dc2a2305e
status-firefox44: affected → fixed
sorry had to back this out for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=1537006&repo=mozilla-aurora
Flags: needinfo?(bgrinstead)
(Assignee)

Comment 15

3 years ago
https://hg.mozilla.org/releases/mozilla-aurora/rev/27a9ba2d01e9
status-b2g-v2.5: fixed → ---
Flags: needinfo?(bgrinstead)
You need to log in before you can comment on or make changes to this bug.