Closed Bug 1494151 Opened 6 years ago Closed 6 years ago

Intermittent TEST-UNEXPECTED-PASS | /dom/events/EventListener-incumbent-global-1.sub.html | Check the incumbent global EventListeners are called with - expected TIMEOUT

Categories

(Core :: DOM: Core & HTML, defect, P2)

Product:
Core
Component:
DOM: Core & HTML
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla64
Tracking Flags:
Tracking Status
firefox64 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: bzbarsky)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended][wptsync upstream])

Attachments

(1 file, 1 obsolete file)

Fix broken web platform test that was trying to connect on a non-existent port
2.65 KB, patch
jgraham
: review+
Details | Diff | Splinter Review 
Filed by: toros [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=201548941&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/K7190bSwTMCN7fL69aEJNg/runs/0/artifacts/public/logs/live_backing.log

15:59:13     INFO - TEST-START | /dom/events/EventListener-incumbent-global-1.sub.html
15:59:13     INFO - PID 767 | ++DOCSHELL 0x11e8c2000 == 6 [pid = 770] [id = {bb1439a9-793c-124e-b389-b1c48c83b530}]
15:59:13     INFO - PID 767 | ++DOMWINDOW == 12 (0x10ed40c00) [pid = 770] [serial = 119] [outer = 0x0]
15:59:13     INFO - PID 767 | ++DOMWINDOW == 13 (0x11f9c6400) [pid = 770] [serial = 120] [outer = 0x10ed40c00]
15:59:13     INFO - PID 767 | ++DOMWINDOW == 14 (0x11e1bd000) [pid = 770] [serial = 121] [outer = 0x10ed40c00]
15:59:13     INFO - PID 767 | ++DOCSHELL 0x11fa99800 == 7 [pid = 770] [id = {028d9839-6c3d-7d46-a4d9-0136422943e0}]
15:59:13     INFO - PID 767 | ++DOMWINDOW == 15 (0x11f9dee00) [pid = 770] [serial = 122] [outer = 0x0]
15:59:13     INFO - PID 767 | ++DOMWINDOW == 16 (0x11fac3000) [pid = 770] [serial = 123] [outer = 0x11f9dee00]
15:59:13     INFO - PID 767 | ++DOCSHELL 0x11fa96800 == 8 [pid = 770] [id = {af1d7e22-bfa2-854d-a146-53a2741138ef}]
15:59:13     INFO - PID 767 | ++DOMWINDOW == 17 (0x11f9dec00) [pid = 770] [serial = 124] [outer = 0x0]
15:59:13     INFO - PID 767 | ++DOMWINDOW == 18 (0x11fac8000) [pid = 770] [serial = 125] [outer = 0x11f9dec00]
15:59:14     INFO - 
15:59:14     INFO - TEST-UNEXPECTED-PASS | /dom/events/EventListener-incumbent-global-1.sub.html | Check the incumbent global EventListeners  are called with - expected TIMEOUT
15:59:14     INFO - TEST-INFO | expected TIMEOUT
15:59:14     INFO - TEST-UNEXPECTED-OK | /dom/events/EventListener-incumbent-global-1.sub.html | expected TIMEOUT
15:59:14     INFO - TEST-INFO expected TIMEOUT | took 633ms
15:59:14     INFO - PID 767 | 1537916354135	Marionette	INFO	Stopped listening on port 2828
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/workspace/build/src/widget/cocoa/nsAppShell.mm, line 763
15:59:14     INFO - PID 767 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 867
15:59:14     INFO - PID 767 | --DOMWINDOW == 3 (0x11eddcc00) [pid = 769] [serial = 4] [outer = 0x0] [url = moz-extension://246cd15d-e9db-704a-b650-69f4d8bdf871/_generated_background_page.html]
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | --DOMWINDOW == 2 (0x10f93c800) [pid = 769] [serial = 1] [outer = 0x0] [url = moz-extension://6b460a9b-9262-1b49-bdf2-7e5807e05db4/_generated_background_page.html]
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | [Child 769, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 564
15:59:14     INFO - PID 767 | --DOCSHELL 0x11f534000 == 1 [pid = 769] [id = {e8a4f3bd-675f-b449-a486-cfb2057389b7}]
15:59:14     INFO - PID 767 | --DOCSHELL 0x1178a5800 == 0 [pid = 769] [id = {756c716e-9f41-8d4a-9a68-7ec21eb8a266}]
15:59:14     INFO - PID 767 | --DOMWINDOW == 1 (0x11edb9c00) [pid = 769] [serial = 3] [outer = 0x0] [url = moz-extension://6b460a9b-9262-1b49-bdf2-7e5807e05db4/_generated_background_page.html]
15:59:14     INFO - PID 767 | --DOMWINDOW == 0 (0x11edc1c00) [pid = 769] [serial = 6] [outer = 0x0] [url = moz-extension://246cd15d-e9db-704a-b650-69f4d8bdf871/_generated_background_page.html]
15:59:14     INFO - PID 767 | nsStringStats
15:59:14     INFO - PID 767 |  => mAllocCount:           9828
15:59:14     INFO - PID 767 |  => mReallocCount:            0
15:59:14     INFO - PID 767 |  => mFreeCount:            9828
15:59:14     INFO - PID 767 |  => mShareCount:           6959
15:59:14     INFO - PID 767 |  => mAdoptCount:            552
15:59:14     INFO - PID 767 |  => mAdoptFreeCount:        564
15:59:14     INFO - PID 767 |  => Process ID: 769, Thread ID: 140735162848000
15:59:14     INFO - PID 767 | [Child 770, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/workspace/build/src/widget/cocoa/nsAppShell.mm, line 763
15:59:14     INFO - PID 767 | [Child 771, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/workspace/build/src/widget/cocoa/nsAppShell.mm, line 763
15:59:14     INFO - PID 767 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
15:59:14     INFO - PID 767 | [Child 771, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 867
15:59:14     INFO - PID 767 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
15:59:14     INFO - PID 767 | [Child 770, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 867
15:59:14     INFO - PID 767 | nsStringStats
15:59:14     INFO - PID 767 |  => mAllocCount:           6551
15:59:14     INFO - PID 767 |  => mReallocCount:            0
15:59:14     INFO - PID 767 |  => mFreeCount:            6551
15:59:14     INFO - PID 767 |  => mShareCount:           6376
15:59:14     INFO - PID 767 |  => mAdoptCount:            113
15:59:14     INFO - PID 767 |  => mAdoptFreeCount:        113
Any ideas, Olli? This is an OS X only intermittent unexpected pass in a WPT test.
Flags: needinfo?(bugs)
https://searchfox.org/mozilla-central/source/testing/web-platform/meta/dom/events/EventListener-incumbent-global-1.sub.html.ini

But bz added the test in bug 1273529, and he is using a Mac, IIRC ;)
It is surprising that the test does timeout at all.
Flags: needinfo?(bugs) → needinfo?(bzbarsky)
So this test file annotates the test as timing out only if:

1) On Mac.
2) Not a webrender build.
3) OS X 10.10.5

So if we assume the test _never_ times out, it will pass on all other platforms, but unexpected-pass on the one above.

That said, it does look like it sometimes times out.  https://taskcluster-artifacts.net/UbQRNiW0RJuy0gMm3RxHYg/0/public/logs/live_backing.log is a log showing that, from https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&selectedJob=204608042&revision=203a8e58e64c86ba7b9cf8b66aec101b10eca3ec

That said, the "this test times out" annotation was _just_ added on September 25.  Which is a bit odd, because none of the testing/web-platform/tests/dom/events/EventListener-incumbent-global* files have changed since May 2016.

The changeset that added the annotation looks like https://hg.mozilla.org/mozilla-central/rev/31214f9ca0413312e0b037dce1df23c698bde279 and the things it merged in are:

  https://hg.mozilla.org/mozilla-central/rev/4970df27110a
  https://hg.mozilla.org/mozilla-central/rev/15543f763944
  https://hg.mozilla.org/mozilla-central/rev/d03965cb9d48
  https://hg.mozilla.org/mozilla-central/rev/67d533e232f2
  https://hg.mozilla.org/mozilla-central/rev/239a348c8945

as far as I can tell.  None of those seem to be touching files that should be relevant to dom/events tests.

I'll try to reproduce the timeout locally, but I'm on OSX 10.12, not 10.10, in case that matters.  But I really don't see why this test would ever time out at first glance.

James, any idea why this .ini got added?
Flags: needinfo?(james)
So I can't reproduce this timeout locally so far.

What I _can_ reproduce is the timeout for dom/events/EventListener-addEventListener.sub.window.js.  That test is  timing out because the iframe gets an error page, with this message:

  Unable to connect

  Firefox can’t establish a connection to the server at not-web-platform.test.

    The site could be temporarily unavailable or too busy. Try again in a few moments.
    If you are unable to load any pages, check your computer’s network connection.
    If your computer or network is protected by a firewall or proxy, make sure that Nightly is permitted to access the Web.

The script at http://web-platform.test:8000/dom/events/EventListener-addEventListener.sub.window.js is looking like this:

  crossOriginFrame.src = 'https://not-web-platform.test/common/blank.html';

That's coming from this line in the original .sub.window.js file:

  crossOriginFrame.src = 'https://{{hosts[alt][]}}/common/blank.html'

so something is up there.  Now interestingly, EventListener-addEventListener.sub.window.js _was_ added in those changesets in comment 6 (specifically in <https://hg.mozilla.org/mozilla-central/rev/239a348c8945d4836d3318627db9927d48eef640>).  I wonder whether that test timing out sometimes causes the other test to time out for some reason or something...
So this got added because of the failure in https://treeherder.mozilla.org/#/jobs?repo=try&revision=6ac4338c2a77b7c4139db8a32cfde54da40b0032&selectedJob=201161587 which caused the metadata to update. The metadata update doesn't have a complete picture of which tests changed (because we don't have a full graph of dependencies), so it doesn't even try; it just makes the metadata match the observed results.

Apparently the log file there no longer exists, but it certainly seems possible that the bug is something related to a previous test. not-web-platform.test isn't supposed to resolve but maybe we're doing something that upsets the network stack and causes the next test to also fail? A cheap trick to workaround the issue (or at least test the hypothesis) would be to put restart-after: true or similar in the ini file for the addEventListener test, so that state is less likely to leak into subsequent tests.
Flags: needinfo?(james)
Yep, fixing the broken test make the test this bug is about start consistently pasing on Mac.
Attachment #9016527 - Flags: review?(james)
Assignee: nobody → bzbarsky
Status: NEW → ASSIGNED
Flags: needinfo?(bzbarsky)
Comment on attachment 9016527 [details] [diff] [review]
Fix broken web platform test that was trying to connect on a non-existent port

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

::: testing/web-platform/tests/dom/events/EventListener-addEventListener.sub.window.js
@@ +1,3 @@
>  async_test(function(t) {
>    let crossOriginFrame = document.createElement('iframe');
> +  crossOriginFrame.src = 'https://{{hosts[alt][]}}:{ports[http]}/common/blank.html';

I think this should be {{ports[http][0]}} or it won't work.
Attachment #9016527 - Flags: review?(james) → review-
Attachment #9016527 - Attachment is obsolete: true
Comment on attachment 9016672 [details] [diff] [review]
Fix broken web platform test that was trying to connect on a non-existent port

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

::: testing/web-platform/tests/dom/events/EventListener-addEventListener.sub.window.js
@@ +1,3 @@
>  async_test(function(t) {
>    let crossOriginFrame = document.createElement('iframe');
> +  crossOriginFrame.src = 'https://{{hosts[alt][]}}:{{ports[https][0]}}/common/blank.html';

Did you intentionally write https rather than http? The test is loaded over http, but I think it's fine in either case, just want to be sure that you agree :)
Attachment #9016672 - Flags: review?(james) → review+
Priority: -- → P2
> Did you intentionally write https rather than http?

The test was already using an https url.  It's probably safer this way, in case anyone wants to load it over http or both....
Pushed by bzbarsky@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4f99223da021
Fix broken web platform test that was trying to connect on a non-existent port.  r=jgraham
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/13521 for changes under testing/web-platform/tests
Whiteboard: [stockwell disable-recommended] → [stockwell disable-recommended][wptsync upstream]
Upstream web-platform-tests status checks passed, PR will merge once commit reaches central.
https://hg.mozilla.org/mozilla-central/rev/4f99223da021
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox64: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: