Open Bug 1243263 Opened 8 years ago Updated 10 months ago

Intermittent browser/base/content/test/alerts/browser_notification_tab_switching.js | single tracking bug

Categories

(Toolkit :: Alerts Service, defect, P3)

Product:
Toolkit
Component:
Alerts Service
Type:
defect

Tracking

()

Tracking Flags:
Tracking Status
e10s + ---
firefox57 --- disabled
firefox58 --- disabled
firefox59 --- disabled

People

(Reporter: philor, Unassigned)

References

(Blocks 2 open bugs)

Details

(Keywords: intermittent-failure, intermittent-testcase, leave-open, Whiteboard: [stockwell disabled])

Blocks: e10s-tests
tracking-e10s: --- → +
Summary: Intermittent e10s Linux browser_notification_tab_switching.js | Test timed ou → Intermittent e10s Linux browser_notification_tab_switching.js | Test timed out
Intermittent e10s test failure
Priority: -- → P5
this has picked up frequency as of June 5th. primarily on linux32/64 debug for e10s.

from this linux64 log:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=105863712

I see this screenshot:
https://queue.taskcluster.net/v1/task/ZZBmQUvrSNuqSipkca0bSA/runs/0/artifacts/public/test_info//mozilla-test-fail-screenshot_V2k6zt.png

and see this in the log file:
task 2017-06-09T15:23:53.685141Z] 15:23:53     INFO - GECKO(1089) | --DOMWINDOW == 16 (0x7fbca8529000) [pid = 1089] [serial = 60] [outer = (nil)] [url = about:blank]
[task 2017-06-09T15:24:57.887065Z] 15:24:57     INFO - TEST-INFO | started process screentopng
[task 2017-06-09T15:24:59.026030Z] 15:24:59     INFO - TEST-INFO | screentopng: exit 0
[task 2017-06-09T15:24:59.029009Z] 15:24:59     INFO - Buffered messages logged at 15:23:27
[task 2017-06-09T15:24:59.031214Z] 15:24:59     INFO - Entering test bound test_notificationPreventDefaultAndSwitchTabs
[task 2017-06-09T15:24:59.032653Z] 15:24:59     INFO - Buffered messages logged at 15:23:28
[task 2017-06-09T15:24:59.035990Z] 15:24:59     INFO - TEST-PASS | browser/base/content/test/alerts/browser_notification_tab_switching.js | Notification page loaded as a background tab - 
[task 2017-06-09T15:24:59.038280Z] 15:24:59     INFO - Console message: [JavaScript Warning: "Error in parsing value for ‘direction’.  Declaration dropped." {file: "chrome://global/content/alerts/alert.xul" line: 0 column: 0 source: "auto"}]
[task 2017-06-09T15:24:59.040253Z] 15:24:59     INFO - Notification alert showing
[task 2017-06-09T15:24:59.048011Z] 15:24:59     INFO - Clicking on notification
[task 2017-06-09T15:24:59.052536Z] 15:24:59     INFO - TEST-PASS | browser/base/content/test/alerts/browser_notification_tab_switching.js | The event handler for the first notification cancels the event - 
[task 2017-06-09T15:24:59.054633Z] 15:24:59     INFO - TEST-PASS | browser/base/content/test/alerts/browser_notification_tab_switching.js | Notification page still a background tab - 
[task 2017-06-09T15:24:59.058143Z] 15:24:59     INFO - Console message: [JavaScript Warning: "Error in parsing value for ‘direction’.  Declaration dropped." {file: "chrome://global/content/alerts/alert.xul" line: 0 column: 0 source: "auto"}]
[task 2017-06-09T15:24:59.062471Z] 15:24:59     INFO - Buffered messages logged at 15:23:34
[task 2017-06-09T15:24:59.065198Z] 15:24:59     INFO - TEST-PASS | browser/base/content/test/alerts/browser_notification_tab_switching.js | Clicking on the second notification should select its originating tab - 
[task 2017-06-09T15:24:59.067089Z] 15:24:59     INFO - Buffered messages finished
[task 2017-06-09T15:24:59.069106Z] 15:24:59     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/alerts/browser_notification_tab_switching.js | Test timed out - 
[task 2017-06-09T15:24:59.074619Z] 15:24:59     INFO - GECKO(1089) | MEMORY STAT | vsize 2149MB | residentFast 247MB | heapAllocated 103MB
[task 2017-06-09T15:24:59.077644Z] 15:24:59     INFO - TEST-OK | browser/base/content/test/alerts/browser_notification_tab_switching.js | took 90453ms
[task 2017-06-09T15:24:59.079795Z] 15:24:59     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-06-09T15:24:59.082073Z] 15:24:59     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/alerts/browser_notification_tab_switching.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/alerts/file_dom_notifications.html - 
[task 2017-06-09T15:24:59.084181Z] 15:24:59     INFO - GECKO(1089) | ++DOCSHELL 0x7fbca852c800 == 8 [pid = 1089] [id = {8adb5c62-179b-4fee-a9b4-5c14f3c243ac}]
[task 2017-06-09T15:24:59.086142Z] 15:24:59     INFO - GECKO(1089) | ++DOMWINDOW == 17 (0x7fbca852d000) [pid = 1089] [serial = 77] [outer = (nil)]
[task 2017-06-09T15:24:59.088191Z] 15:24:59     INFO - GECKO(1089) | ++DOMWINDOW == 18 (0x7fbca8536000) [pid = 1089] [serial = 78] [outer = 0x7fbca852d000]
[task 2017-06-09T15:24:59.090463Z] 15:24:59     INFO - checking window state
[task 2017-06-09T15:24:59.118627Z] 15:24:59     INFO - GECKO(1089) | ++DOMWINDOW == 19 (0x7fbca85d1800) [pid = 1089] [serial = 79] [outer = 0x7fbcbf1ca800]
[task 2017-06-09T15:24:59.194932Z] 15:24:59     INFO - GECKO(1089) | ++DOMWINDOW == 20 (0x7fbca85db000) [pid = 1089] [serial = 80] [outer = 0x7fbcbf1ca800]
[task 2017-06-09T15:25:01.026618Z] 15:25:01     INFO - GECKO(1089) | --DOCSHELL 0x7fbcbc489000 == 7 [pid = 1089] [id = {b2133c62-e71e-4e9d-91c1-0fb7b87e5916}]
[task 2017-06-09T15:25:01.029268Z] 15:25:01     INFO - GECKO(1089) | --DOCSHELL 0x7fbcbc3c2000 == 6 [pid = 1089] [id = {8233c1f9-c6cf-4ed6-bca9-32293fe4b27a}]
[task 2017-06-09T15:25:02.855914Z] 15:25:02     INFO - GECKO(1089) | --DOCSHELL 0x7fbca83a8000 == 5 [pid = 1089] [id = {642b07e9-dc29-40b0-b5bd-14eca40cd255}]
[task 2017-06-09T15:25:08.880239Z] 15:25:08     INFO - GECKO(1089) | --DOMWINDOW == 19 (0x7fbca85d1800) [pid = 1089] [serial = 79] [outer = (nil)] [url = about:blank]
[task 2017-06-09T15:25:08.883371Z] 15:25:08     INFO - GECKO(1089) | --DOMWINDOW == 18 (0x7fbcbca2b800) [pid = 1089] [serial = 9] [outer = (nil)] [url = about:blank]
[task 2017-06-09T15:25:10.816373Z] 15:25:10     INFO - GECKO(1089) | --DOMWINDOW == 17 (0x7fbca85ce800) [pid = 1089] [serial = 68] [outer = (nil)] [url = about:blank]
[task 2017-06-09T15:25:10.819568Z] 15:25:10     INFO - GECKO(1089) | --DOMWINDOW == 16 (0x7fbca85d5000) [pid = 1089] [serial = 69] [outer = (nil)] [url = about:blank]
[task 2017-06-09T15:25:10.821871Z] 15:25:10     INFO - GECKO(1089) | --DOMWINDOW == 15 (0x7fbcbc477000) [pid = 1089] [serial = 70] [outer = (nil)] [url = http://example.org/browser/browser/base/content/test/alerts/file_dom_notifications.html]
[task 2017-06-09T15:25:10.823309Z] 15:25:10     INFO - GECKO(1089) | --DOMWINDOW == 14 (0x7fbcbc486800) [pid = 1089] [serial = 18] [outer = (nil)] [url = about:newtab]
[task 2017-06-09T15:25:10.825177Z] 15:25:10     INFO - GECKO(1089) | --DOMWINDOW == 13 (0x7fbcbc489800) [pid = 1089] [serial = 16] [outer = (nil)] [url = about:newtab]
[task 2017-06-09T15:25:10.827148Z] 15:25:10     INFO - GECKO(1089) | --DOMWINDOW == 12 (0x7fbca87d1000) [pid = 1089] [serial = 72] [outer = (nil)] [url = http://example.org/browser/browser/base/content/test/alerts/file_dom_notifications.html]
[task 2
017-06-09T15:25:20.448639Z] 15:25:20     INFO - GECKO(1089) | Completed ShutdownLeaks collections in process 1089
[task 2017-06-09T15:25:20.454306Z] 15:25:20     INFO - TEST-START | Shutdown
[task 2017-06-09T15:25:20.458014Z] 15:25:20     INFO - Browser Chrome Test Summary
[task 2017-06-09T15:25:20.469382Z] 15:25:20     INFO - Passed:  24
[task 2017-06-09T15:25:20.471412Z] 15:25:20     INFO - Failed:  2
[task 2017-06-09T15:25:20.471699Z] 15:25:20     INFO - Todo:    0
[task 2017-06-09T15:25:20.475943Z] 15:25:20     INFO - Mode:    non-e10s
[task 2017-06-09T15:25:20.478406Z] 15:25:20     INFO - *** End BrowserChrome Test Results ***
Component: General → Notifications and Alerts
Product: Firefox → Toolkit
Whiteboard: [stockwell needswork]
:mattn, can you find someone on the notification and alerts team to look into this sometime in the next 2 weeks?
Flags: needinfo?(MattN+bmo)
Kit, any chance you want to look at this?
Flags: needinfo?(MattN+bmo) → needinfo?(kit)
I can have a look, but it'll have to wait until after the work week. Keeping ni? until then.
Flags: needinfo?(kit)
Whiteboard: [stockwell needswork] → [stockwell unknown]
Summary: Intermittent e10s Linux browser_notification_tab_switching.js | Test timed out → Intermittent browser_notification_tab_switching.js | Test timed out
:kit, is there a chance you could look at this?  the total failures have increased and we ignored this because it was marked [stockwell unknown], otherwise we would have pinged you about it much earlier.
Flags: needinfo?(kit)
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c4c7dae25aff
Disable browser_notification_tab_switching.js for frequency failures. r=me, a=test-only
please remember to re-enable this while working on a fix!
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
this test was disabled, then re-enabled in bug 1352791, now it is failing on linux* debug (not on windows anymore!)

:mattn, you turned this test back on 16 days ago:
https://hg.mozilla.org/mozilla-central/rev/314590a2d588

can you look into the intermittent failures?
Blocks: 1352791
Flags: needinfo?(kit) → needinfo?(MattN+bmo)
the failure rate has been pretty low, lets assume there is nothing to do for now.
Flags: needinfo?(MattN+bmo)
Even more of these failures are being incorrectly reported in bug 1265225.
See comment 59. Failures have become quite frequent again (especially considering those assigned to bug 1265225). Most failures are on Windows 10, but Windows 7 and Linux are also affected.
Flags: needinfo?(MattN+bmo)
Whiteboard: [stockwell disabled] → [stockwell needswork]
There's clearly a fundamental issue with the tests in the whole directory. The first test that runs in the directory happens to get the blame. I wasn't able to reproduce the issue in one of the earlier tests in the directory so tests got disabled one-by-one[1] in order. Now we're left with this one last test before losing total code coverage from this test directory. Most, if not all, of these tests are only doing real testing on Windows with the XUL backend so disabling on windows-only is basically a `skip-if = true`.

Dolske, can you help find someone to fix these tests so the alert service doesn't lose all of its b-c coverage?

[1] https://dxr.mozilla.org/mozilla-central/rev/1624b88874765bf57e9feba176d30149c748d9d2/browser/base/content/test/alerts/browser.ini#16
Flags: needinfo?(MattN+bmo) → needinfo?(dolske)
Priority: P5 → P1
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/86ec6a8d5704
Disable browser_notification_tab_switching.js on windows for ongoing intermittent failures; r=me, a=test-only
Note comment 75 -- all of the tests in this manifest have now been skipped on Windows.
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Over the last 7 days there are 33 failures on this bug. Most of these happen on Linux, Linux x64, linux32-stylo-disabled, linux64-stylo-disabled.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=163868392&lineNumber=2280

Here is a relevant part from the log:

[task 2018-02-23T03:25:09.060Z] 03:25:09     INFO - Buffered messages finished
[task 2018-02-23T03:25:09.062Z] 03:25:09     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/alerts/browser_notification_tab_switching.js | Test timed out - 
[task 2018-02-23T03:25:09.063Z] 03:25:09     INFO - GECKO(1044) | MEMORY STAT | vsize 968MB | residentFast 266MB | heapAllocated 65MB
[task 2018-02-23T03:25:09.064Z] 03:25:09     INFO - TEST-OK | browser/base/content/test/alerts/browser_notification_tab_switching.js | took 90060ms
[task 2018-02-23T03:25:09.066Z] 03:25:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-02-23T03:25:09.067Z] 03:25:09     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/alerts/browser_notification_tab_switching.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/alerts/file_dom_notifications.html - 
[task 2018-02-23T03:25:09.068Z] 03:25:09     INFO - GECKO(1044) | ++DOCSHELL 0xe7994c00 == 1 [pid = 1182] [id = {799165b7-b283-40eb-a94d-d767122bce52}]
[task 2018-02-23T03:25:09.069Z] 03:25:09     INFO - GECKO(1044) | ++DOMWINDOW == 1 (0xf714a6c0) [pid = 1182] [serial = 3] [outer = (nil)]
[task 2018-02-23T03:25:09.070Z] 03:25:09     INFO - checking window state
Flags: needinfo?(MattN+bmo)
This (and related bugs) is on Mike de Boer's team's radar for investigation soon.
Flags: needinfo?(dolske)
Flags: needinfo?(MattN+bmo)
Priority: P1 → P3
Severity: normal → S3
Keywords: intermittent-testcase
Summary: Intermittent browser_notification_tab_switching.js | Test timed out → Intermittent browser_notification_tab_switching.js | single tracking bug
Summary: Intermittent browser_notification_tab_switching.js | single tracking bug → Intermittent browser/base/content/test/alerts/browser_notification_tab_switching.js | single tracking bug
Component: Notifications and Alerts → DOM: Notifications
Product: Toolkit → Core
Blocks: 1844176
Component: DOM: Notifications → Alerts Service
Product: Core → Toolkit
You need to log in before you can comment on or make changes to this bug.