Closed Bug 1585859 Opened 1 year ago Closed 8 months ago

Intermittent dom/tests/mochitest/bugs/test_bug440572.html | received the right number of messages. - got 3, expected 4

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla76
Fission Milestone M4.1
Tracking Status
firefox-esr68 --- unaffected
firefox74 --- wontfix
firefox75 --- wontfix
firefox76 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=269535496&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/FVIYjhnPT9-3hP4q94z3hw/runs/0/artifacts/public/logs/live_backing.log


INFO - TEST-START | dom/tests/mochitest/bugs/test_bug440572.html
[task 2019-10-02T23:50:42.145Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.181Z] 23:50:42     INFO - GECKO(4216) | [Parent 4216, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4516
[task 2019-10-02T23:50:42.204Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 27 (0x7f7237994000) [pid = 4388] [serial = 123] [outer = 0x7f723a79c6a0]
[task 2019-10-02T23:50:42.286Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f72377ae000 == 4 [pid = 4388] [id = {23779eb1-c8d5-47a1-a8b6-d9b7cd8aa33b}]
[task 2019-10-02T23:50:42.286Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 28 (0x7f7239b7eb60) [pid = 4388] [serial = 124] [outer = (nil)]
[task 2019-10-02T23:50:42.286Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f72377ae800 == 5 [pid = 4388] [id = {b64dabcb-f4e9-442e-9047-b7adb41dfd16}]
[task 2019-10-02T23:50:42.287Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 29 (0x7f7239b7ef20) [pid = 4388] [serial = 125] [outer = (nil)]
[task 2019-10-02T23:50:42.287Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f7237921800 == 6 [pid = 4388] [id = {b5027ae2-7862-4e20-8139-716aca0a83bd}]
[task 2019-10-02T23:50:42.287Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 30 (0x7f7239b7f100) [pid = 4388] [serial = 126] [outer = (nil)]
[task 2019-10-02T23:50:42.287Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f7237922000 == 7 [pid = 4388] [id = {26f0ca9d-82ad-4bb6-9555-774bba43ffae}]
[task 2019-10-02T23:50:42.287Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 31 (0x7f7239b7f2e0) [pid = 4388] [serial = 127] [outer = (nil)]
[task 2019-10-02T23:50:42.342Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.342Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.498Z] 23:50:42     INFO - GECKO(4216) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpkaJJ34.mozrunner/runtests_leaks_tab_pid4586.log
[task 2019-10-02T23:50:42.620Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.620Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.621Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.621Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.636Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.637Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 41
[task 2019-10-02T23:50:42.673Z] 23:50:42     INFO - GECKO(4216) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-10-02T23:50:42.702Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2019-10-02T23:50:42.703Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2019-10-02T23:50:42.703Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2019-10-02T23:50:42.703Z] 23:50:42     INFO - GECKO(4216) | [Child 4388, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2019-10-02T23:50:42.703Z] 23:50:42     INFO - GECKO(4216) | --DOMWINDOW == 30 (0x7f7239b7eb60) [pid = 4388] [serial = 124] [outer = (nil)] [url = ]
[task 2019-10-02T23:50:42.704Z] 23:50:42     INFO - GECKO(4216) | --DOMWINDOW == 29 (0x7f7239b7ef20) [pid = 4388] [serial = 125] [outer = (nil)] [url = ]
[task 2019-10-02T23:50:42.704Z] 23:50:42     INFO - GECKO(4216) | --DOMWINDOW == 28 (0x7f7239b7f100) [pid = 4388] [serial = 126] [outer = (nil)] [url = ]
[task 2019-10-02T23:50:42.704Z] 23:50:42     INFO - GECKO(4216) | --DOMWINDOW == 27 (0x7f7239b7f2e0) [pid = 4388] [serial = 127] [outer = (nil)] [url = ]
[task 2019-10-02T23:50:42.827Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f9377fc1000 == 1 [pid = 4586] [id = {61b5ecff-8724-47dc-9560-ded4d9e4d9b9}]
[task 2019-10-02T23:50:42.875Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 1 (0x7f93918f14c0) [pid = 4586] [serial = 1] [outer = (nil)]
[task 2019-10-02T23:50:42.875Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 2 (0x7f9377f32400) [pid = 4586] [serial = 2] [outer = 0x7f93918f14c0]
[task 2019-10-02T23:50:42.899Z] 23:50:42     INFO - GECKO(4216) | --DOCSHELL 0x7f7237928800 == 6 [pid = 4388] [id = {d1f33baf-09e7-4d7a-8cce-da6338ed948a}] [url = http://mochi.test:8888/tests/dom/tests/mochitest/bugs/iframe_bug430276-2.html]
[task 2019-10-02T23:50:42.900Z] 23:50:42     INFO - GECKO(4216) | --DOMWINDOW == 26 (0x7f72377d7000) [pid = 4388] [serial = 101] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/tests/mochitest/bugs/test_bug427744.html]
[task 2019-10-02T23:50:42.902Z] 23:50:42     INFO - GECKO(4216) | --DOMWINDOW == 25 (0x7f7239b40c00) [pid = 4388] [serial = 100] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
[task 2019-10-02T23:50:42.904Z] 23:50:42     INFO - GECKO(4216) | --DOMWINDOW == 24 (0x7f7237779c00) [pid = 4388] [serial = 102] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
[task 2019-10-02T23:50:42.912Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f937909c800 == 2 [pid = 4586] [id = {fd1042b9-e85b-4251-bbb7-840738bdf4e6}]
[task 2019-10-02T23:50:42.912Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 3 (0x7f93918f1a60) [pid = 4586] [serial = 3] [outer = (nil)]
[task 2019-10-02T23:50:42.916Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 4 (0x7f9379065c00) [pid = 4586] [serial = 4] [outer = 0x7f93918f1a60]
[task 2019-10-02T23:50:42.932Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f93790a0000 == 3 [pid = 4586] [id = {1e2dca6e-58c4-45aa-8c20-23df913473ab}]
[task 2019-10-02T23:50:42.933Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 5 (0x7f9378852020) [pid = 4586] [serial = 5] [outer = (nil)]
[task 2019-10-02T23:50:42.934Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 6 (0x7f9379068000) [pid = 4586] [serial = 6] [outer = 0x7f9378852020]
[task 2019-10-02T23:50:42.942Z] 23:50:42     INFO - GECKO(4216) | ++DOCSHELL 0x7f93790a3000 == 4 [pid = 4586] [id = {7deb70d3-2fba-4de8-aaaa-3e81a78a2ef6}]
[task 2019-10-02T23:50:42.943Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 7 (0x7f93788527a0) [pid = 4586] [serial = 7] [outer = (nil)]
[task 2019-10-02T23:50:42.946Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 8 (0x7f937906a400) [pid = 4586] [serial = 8] [outer = 0x7f93788527a0]
[task 2019-10-02T23:50:42.974Z] 23:50:42     INFO - GECKO(4216) | ++DOMWINDOW == 9 (0x7f937906ec00) [pid = 4586] [serial = 9] [outer = 0x7f93918f14c0]
[task 2019-10-02T23:50:43.004Z] 23:50:43     INFO - GECKO(4216) | ++DOMWINDOW == 10 (0x7f9378f7a000) [pid = 4586] [serial = 10] [outer = 0x7f93918f1a60]
[task 2019-10-02T23:50:43.025Z] 23:50:43     INFO - GECKO(4216) | ++DOMWINDOW == 11 (0x7f9378f7c000) [pid = 4586] [serial = 11] [outer = 0x7f9378852020]
[task 2019-10-02T23:50:43.045Z] 23:50:43     INFO - GECKO(4216) | ++DOMWINDOW == 12 (0x7f9378f7e000) [pid = 4586] [serial = 12] [outer = 0x7f93788527a0]
[task 2019-10-02T23:50:43.187Z] 23:50:43     INFO - TEST-INFO | started process screentopng
[task 2019-10-02T23:50:43.976Z] 23:50:43     INFO - TEST-INFO | screentopng: exit 0
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - Buffered messages logged at 23:50:43
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender! 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender! 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender! 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - Buffered messages finished
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | received the right number of messages. - got 3, expected 4
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO -     runtests@dom/tests/mochitest/bugs/test_bug440572.html:30:5
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO -     onload@dom/tests/mochitest/bugs/test_bug440572.html:1:1
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | test in frame failed. 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | "dump" in frame failed. 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | "open" in frame failed. 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | parent["close"] should be the WebIDL property of Window. 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - GECKO(4216) | MEMORY STAT | vsize 2531MB | residentFast 154MB | heapAllocated 16MB
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender! 
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - TEST-OK | dom/tests/mochitest/bugs/test_bug440572.html | took 1116ms
[task 2019-10-02T23:50:43.977Z] 23:50:43     INFO - GECKO(4216) | [Parent 4216, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4516
[task 2019-10-02T23:50:43.977Z] 23:50:43    ERROR - /tests/dom/tests/mochitest/bugs/test_bug440572.html logged result after SimpleTest.finish(): wrong sender!
[task 2019-10-02T23:50:43.978Z] 23:50:43     INFO - GECKO(4216) | ++DOMWINDOW == 25 (0x7f7237779c00) [pid = 4388] [serial = 128] [outer = 0x7f723a79c6a0]
[task 2019-10-02T23:50:43.980Z] 23:50:43     INFO - GECKO(4216) | [Parent 4216, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4516
[task 2019-10-02T23:50:43.980Z] 23:50:43     INFO - TEST-START | dom/tests/mochitest/bugs/test_bug456151.html

My patch changed timing during process-switching navigations. I'm guessing this test was already buggy with fission before, but the new timing changes made this more frequent.

A quick look at the test suggests that it is dependent on the load event in the embedder not firing until after messages from each cross-origin subframe have been received. I am inclined to think that this test's reliance on this timing is broken, but there's a chance that this ordering is one which we want to guarantee. Either way, it's not likely to be a "new" bug.

If we look at a test failure log, the messages are clearly arriving after the checks are being made: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269711916&repo=autoland&lineNumber=13131

First the load event fires:

INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | received the right number of messages. - got +0, expected 4
INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | test in frame failed. - got undefined, expected "success"
INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | "dump" in frame failed. - got undefined, expected "success"
INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | "open" in frame failed. - got undefined, expected "success"
INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | parent["close"] should be the WebIDL property of Window.

... and then the messages start arriving

INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
INFO - TEST-OK | dom/tests/mochitest/bugs/test_bug440572.html | took 1068ms

Flags: needinfo?(nika)
See Also: → 1587365

There have been 32 failures within the last 7 days, all of them on Linux x64 QuantumRender debug (fission).
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=270982765&repo=autoland&lineNumber=13147

[task 2019-10-12T03:15:15.162Z] 03:15:15 INFO - GECKO(4044) | ++DOCSHELL 0x7f3f7e842000 == 4 [pid = 4390] [id = {429e498b-9ff8-420a-bd1a-41e808213bcd}]
[task 2019-10-12T03:15:15.162Z] 03:15:15 INFO - GECKO(4044) | ++DOMWINDOW == 7 (0x7f3f7e14b7a0) [pid = 4390] [serial = 7] [outer = (nil)]
[task 2019-10-12T03:15:15.162Z] 03:15:15 INFO - GECKO(4044) | ++DOMWINDOW == 8 (0x7f3f7e80c800) [pid = 4390] [serial = 8] [outer = 0x7f3f7e14b7a0]
[task 2019-10-12T03:15:15.210Z] 03:15:15 INFO - GECKO(4044) | ++DOMWINDOW == 9 (0x7f3f7e810400) [pid = 4390] [serial = 9] [outer = 0x7f3f7e8d94c0]
[task 2019-10-12T03:15:15.246Z] 03:15:15 INFO - GECKO(4044) | ++DOMWINDOW == 10 (0x7f3f7d4cb800) [pid = 4390] [serial = 10] [outer = 0x7f3f7e8d9a60]
[task 2019-10-12T03:15:15.266Z] 03:15:15 INFO - GECKO(4044) | ++DOMWINDOW == 11 (0x7f3f7d4cdc00) [pid = 4390] [serial = 11] [outer = 0x7f3f7e14b020]
[task 2019-10-12T03:15:15.282Z] 03:15:15 INFO - GECKO(4044) | ++DOMWINDOW == 12 (0x7f3f7d4cfc00) [pid = 4390] [serial = 12] [outer = 0x7f3f7e14b7a0]
[task 2019-10-12T03:15:15.405Z] 03:15:15 INFO - TEST-INFO | started process screentopng
[task 2019-10-12T03:15:16.193Z] 03:15:16 INFO - TEST-INFO | screentopng: exit 0
[task 2019-10-12T03:15:16.194Z] 03:15:16 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | received the right number of messages. - got +0, expected 4
[task 2019-10-12T03:15:16.194Z] 03:15:16 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-12T03:15:16.195Z] 03:15:16 INFO - runtests@dom/tests/mochitest/bugs/test_bug440572.html:30:5
[task 2019-10-12T03:15:16.195Z] 03:15:16 INFO - onload@dom/tests/mochitest/bugs/test_bug440572.html:1:1
[task 2019-10-12T03:15:16.196Z] 03:15:16 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-12T03:15:16.197Z] 03:15:16 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | test in frame failed. - got undefined, expected "success"
[task 2019-10-12T03:15:16.197Z] 03:15:16 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-12T03:15:16.198Z] 03:15:16 INFO - runtests@dom/tests/mochitest/bugs/test_bug440572.html:31:5
[task 2019-10-12T03:15:16.199Z] 03:15:16 INFO - onload@dom/tests/mochitest/bugs/test_bug440572.html:1:1
[task 2019-10-12T03:15:16.199Z] 03:15:16 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-12T03:15:16.200Z] 03:15:16 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | "dump" in frame failed. - got undefined, expected "success"
[task 2019-10-12T03:15:16.201Z] 03:15:16 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-12T03:15:16.201Z] 03:15:16 INFO - runtests@dom/tests/mochitest/bugs/test_bug440572.html:32:5
[task 2019-10-12T03:15:16.202Z] 03:15:16 INFO - onload@dom/tests/mochitest/bugs/test_bug440572.html:1:1
[task 2019-10-12T03:15:16.203Z] 03:15:16 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-12T03:15:16.203Z] 03:15:16 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | "open" in frame failed. - got undefined, expected "success"
[task 2019-10-12T03:15:16.204Z] 03:15:16 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-12T03:15:16.205Z] 03:15:16 INFO - runtests@dom/tests/mochitest/bugs/test_bug440572.html:33:5
[task 2019-10-12T03:15:16.206Z] 03:15:16 INFO - onload@dom/tests/mochitest/bugs/test_bug440572.html:1:1
[task 2019-10-12T03:15:16.206Z] 03:15:16 INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | parent["close"] should be the WebIDL property of Window.
[task 2019-10-12T03:15:16.207Z] 03:15:16 INFO - GECKO(4044) | MEMORY STAT | vsize 2525MB | residentFast 141MB | heapAllocated 16MB
[task 2019-10-12T03:15:16.207Z] 03:15:16 INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
[task 2019-10-12T03:15:16.208Z] 03:15:16 INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
[task 2019-10-12T03:15:16.209Z] 03:15:16 INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
[task 2019-10-12T03:15:16.209Z] 03:15:16 INFO - TEST-PASS | dom/tests/mochitest/bugs/test_bug440572.html | wrong sender!
[task 2019-10-12T03:15:16.210Z] 03:15:16 INFO - TEST-OK | dom/tests/mochitest/bugs/test_bug440572.html | took 1094ms
[task 2019-10-12T03:15:16.211Z] 03:15:16 ERROR - /tests/dom/tests/mochitest/bugs/test_bug440572.html logged result after SimpleTest.finish(): wrong sender!

Flags: needinfo?(htsai)
Whiteboard: [stockwell needswork:owner]

it has been enabled on Fission but then we saw higher failure frequency.

Assignee: nobody → alchen
Flags: needinfo?(htsai)
Priority: -- → P2
Fission Milestone: --- → M4.1

There are 26 total failures in the last 7 days.

debug: linux64-qr, linux64

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=281833934&repo=autoland&lineNumber=11009

Flags: needinfo?(htsai)

Hi Chris, This bug has been enabled for Fission. I'm thinking we should remove it from fission-mochitests meta bug as well as Fission M4.1, though there appears intermittent failures. What do you think?

Flags: needinfo?(htsai) → needinfo?(cpeterson)

(In reply to Hsin-Yi Tsai [:hsinyi] from comment #20)

This bug has been enabled for Fission. I'm thinking we should remove it from fission-mochitests meta bug as well as Fission M4.1, though there appears intermittent failures. What do you think?

This test runs in both Fission and non-Fission mode, but it fails much more frequently in Fission mode (40 Fission failures vs 8 non-Fission failures over the last two weeks). Comment 1 says the failure rate increased after Nika fixed bug 1576714.

So this intermittent test failure still looks like a Fission bug, but perhaps a lower priority than P2.

No longer blocks: fission-mochitests
Flags: needinfo?(cpeterson)
Priority: P2 → P3

In the last 7 days, there have been 40 failures on linux64-qr platform, debug build type.

An example of a recent log file:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=284498438&repo=autoland&lineNumber=10969

And the relevant part of the log:
[task 2020-01-11T02:03:39.400Z] 02:03:39 INFO - TEST-START | dom/tests/mochitest/bugs/test_bug440572.html
[task 2020-01-11T02:03:39.476Z] 02:03:39 INFO - GECKO(5385) | [Parent 5385, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-11T02:03:39.512Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.655Z] 02:03:39 INFO - GECKO(5385) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp8D086O.mozrunner/runtests_leaks_tab_pid5995.log
[task 2020-01-11T02:03:39.679Z] 02:03:39 INFO - GECKO(5385) | [Child 5995, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp, line 721
[task 2020-01-11T02:03:39.740Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.741Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.741Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(request) failed: file /builds/worker/workspace/build/src/netwerk/base/nsLoadGroup.cpp, line 584
[task 2020-01-11T02:03:39.741Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2020-01-11T02:03:39.748Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.748Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.748Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(request) failed: file /builds/worker/workspace/build/src/netwerk/base/nsLoadGroup.cpp, line 584
[task 2020-01-11T02:03:39.764Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2020-01-11T02:03:39.820Z] 02:03:39 INFO - GECKO(5385) | [Parent 5385, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-11T02:03:39.837Z] 02:03:39 INFO - GECKO(5385) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-01-11T02:03:39.837Z] 02:03:39 INFO - GECKO(5385) | [Parent 5385, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-11T02:03:39.837Z] 02:03:39 INFO - GECKO(5385) | [Child 5995, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/workspace/build/src/dom/media/CubebUtils.cpp, line 381
[task 2020-01-11T02:03:39.857Z] 02:03:39 INFO - GECKO(5385) | [Parent 5385, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-11T02:03:39.859Z] 02:03:39 INFO - GECKO(5385) | [Parent 5385, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-11T02:03:39.981Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.982Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.982Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(request) failed: file /builds/worker/workspace/build/src/netwerk/base/nsLoadGroup.cpp, line 584
[task 2020-01-11T02:03:39.984Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.985Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-11T02:03:39.986Z] 02:03:39 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(request) failed: file /builds/worker/workspace/build/src/netwerk/base/nsLoadGroup.cpp, line 584
[task 2020-01-11T02:03:40.008Z] 02:03:40 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2020-01-11T02:03:40.008Z] 02:03:40 INFO - GECKO(5385) | [Child 5561, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/workspace/build/src/dom/base/WindowDestroyedEvent.cpp, line 106
[task 2020-01-11T02:03:40.024Z] 02:03:40 INFO - GECKO(5385) | [Child 5995, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/workspace/build/src/dom/ipc/ContentChild.cpp, line 1822
[task 2020-01-11T02:03:40.065Z] 02:03:40 INFO - GECKO(5385) | [Child 5995, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 848
[task 2020-01-11T02:03:40.308Z] 02:03:40 INFO - TEST-INFO | started process screentopng
[task 2020-01-11T02:03:41.074Z] 02:03:41 INFO - TEST-INFO | screentopng: exit 0
[task 2020-01-11T02:03:41.075Z] 02:03:41 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/bugs/test_bug440572.html | received the right number of messages. - got +0, expected 4
[task 2020-01-11T02:03:41.075Z] 02:03:41 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:325:16
[task 2020-01-11T02:03:41.075Z] 02:03:41 INFO - runtests@dom/tests/mochitest/bugs/test_bug440572.html:30:5
[task 2020-01-11T02:03:41.075Z] 02:03:41 INFO - onload@dom/tests/mochitest/bugs/test_bug440572.html:1:1
[task 2020-01-11T02:03:41.075Z] 02:03:41 INFO - Not taking screenshot here: see the one that was previously logged

Chris, this is how orange Factor looks for the last 30 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-12-12&endday=2020-01-11&tree=trunk&bug=1585859. Can you please take a look again?
For Comment 1, there was a spike 3 months ago.

Thank you!

Flags: needinfo?(chrispetersen)

I have been mistakenly added to this ticket for more info. Since one of the contributors of this ticket has a similar name as myself.

Flags: needinfo?(cpeterson)

WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64

Matt, does this warning indicate a bug in DocumentChannel or a bug in the caller?

Flags: needinfo?(cpeterson) → needinfo?(matt.woodrow)

(In reply to Chris Peterson [:cpeterson] from comment #29)

WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64

Matt, does this warning indicate a bug in DocumentChannel or a bug in the caller?

Neither, it's just overzealous. I'll remove it in bug 1612683.

Flags: needinfo?(matt.woodrow)

Over the last 7 days there are a total of 32 failures on this bug. These happen on windows10-64-qr, linux1804-64-qr and linux1804-64

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=291938739&repo=autoland&lineNumber=3814

Pushed by rmaries@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/69b4f7dc5973
Don't depend on load event to run the test. r=edgar
Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla76
You need to log in before you can comment on or make changes to this bug.