Closed Bug 1482983 Opened 6 years ago Closed 1 year ago

Intermittent toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html | message queue is empty - got "[\"onBeforeRequest\"]", expected "[]"

Categories

(WebExtensions :: General, defect, P5)

Unspecified
Linux
defect

Tracking

(firefox-esr102 wontfix, firefox113 wontfix, firefox114 fixed)

RESOLVED FIXED
114 Branch
Tracking Status
firefox-esr102 --- wontfix
firefox113 --- wontfix
firefox114 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell disabled][addons-jira])

Attachments

(2 files)

Filed by: dvarga [at] mozilla.com

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

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

[task 2018-08-13T17:05:46.688Z] 17:05:46     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html | null principal documentUrl for sandboxed request 
[task 2018-08-13T17:05:46.688Z] 17:05:46     INFO - Buffered messages logged at 17:05:46
[task 2018-08-13T17:05:46.689Z] 17:05:46     INFO - AddTask.js | Leaving test test_webRequest_main_frame
[task 2018-08-13T17:05:46.689Z] 17:05:46     INFO - Buffered messages finished
[task 2018-08-13T17:05:46.689Z] 17:05:46     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html | message queue is empty - got "[\"onBeforeRequest\"]", expected "[]"
[task 2018-08-13T17:05:46.689Z] 17:05:46     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2018-08-13T17:05:46.689Z] 17:05:46     INFO -     ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:27:7
[task 2018-08-13T17:05:46.692Z] 17:05:46     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1227:19
[task 2018-08-13T17:05:46.693Z] 17:05:46     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1236:13
[task 2018-08-13T17:05:46.694Z] 17:05:46     INFO -     SimpleTest.finish@SimpleTest/SimpleTest.js:1240:5
[task 2018-08-13T17:05:46.694Z] 17:05:46     INFO -     add_task/</<@SimpleTest/AddTask.js:72:11
[task 2018-08-13T17:05:46.695Z] 17:05:46     INFO -     async*add_task/<@SimpleTest/AddTask.js:31:10
[task 2018-08-13T17:05:46.695Z] 17:05:46     INFO -     setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:676:12
[task 2018-08-13T17:05:46.696Z] 17:05:46     INFO -     add_task@SimpleTest/AddTask.js:30:7
[task 2018-08-13T17:05:46.697Z] 17:05:46     INFO -     @toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html:190:1
[task 2018-08-13T17:05:46.697Z] 17:05:46     INFO - GECKO(3067) | MEMORY STAT | vsize 1744MB | residentFast 371MB | heapAllocated 34MB
[task 2018-08-13T17:05:46.699Z] 17:05:46     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html | took 7198ms
[task 2018-08-13T17:05:46.699Z] 17:05:46     INFO - GECKO(3067) | [Parent 3067, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/DOMEventTargetHelper.h, line 146
[task 2018-08-13T17:05:46.700Z] 17:05:46     INFO - GECKO(3067) | [Parent 3067, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/DOMEventTargetHelper.h, line 146
[task 2018-08-13T17:05:46.701Z] 17:05:46    ERROR - /tests/toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html logged result after SimpleTest.finish(): message queue is empty
[task 2018-08-13T17:05:46.702Z] 17:05:46     INFO - GECKO(3067) | ++DOMWINDOW == 26 (0x7f3eac56e000) [pid = 3123] [serial = 352] [outer = 0x7f3eb378d800]
[task 2018-08-13T17:05:46.703Z] 17:05:46     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_redirect_data_uri.html
[task 2018-08-13T17:05:46.780Z] 17:05:46     INFO - GECKO(3067) | ++DOMWINDOW == 27 (0x7f3eac56c400) [pid = 3123] [serial = 353] [outer = 0x7f3eb378d800]
[task 2018-08-13T17:05:47.971Z] 17:05:47     INFO - GECKO(3067) | Console message: Warning: attempting to write 9598 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2018-08-13T17:05:47.972Z] 17:05:47     INFO - GECKO(3067) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_redirect_data_uri.html" line: 0}]
[task 2018-08-13T17:05:48.053Z] 17:05:48     INFO - GECKO(3067) | [Parent 3067, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
[task 2018-08-13T17:05:48.135Z] 17:05:48     INFO - GECKO(3067) | ++DOCSHELL 0x7f5fea777800 == 9 [pid = 3067] [id = {cf97e0e9-7e32-470b-aadc-67f0a16ebaab}]
[task 2018-08-13T17:05:48.137Z] 17:05:48     INFO - GECKO(3067) | ++DOMWINDOW == 35 (0x7f5ff9b2dc00) [pid = 3067] [serial = 482] [outer = (nil)]
There have been 34 failures in the last week.
Failures occur only on debug.
The most affected platform is linux64-qr.

Recent relevant log: 
https://treeherder.mozilla.org/logviewer.html#?job_id=198202225&repo=mozilla-inbound&lineNumber=20401


[task 2018-09-08T05:26:37.879Z] 05:26:37     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html | sub_frame has ancestors 
[task 2018-09-08T05:26:37.883Z] 05:26:37     INFO - AddTask.js | Leaving test test_webRequest_main_frame
[task 2018-09-08T05:26:37.884Z] 05:26:37     INFO - Buffered messages finished
[task 2018-09-08T05:26:37.885Z] 05:26:37     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html | message queue is empty - got "[\"onBeforeRequest\"]", expected "[]"
[task 2018-09-08T05:26:37.886Z] 05:26:37     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2018-09-08T05:26:37.887Z] 05:26:37     INFO -     ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:27:7
[task 2018-09-08T05:26:37.888Z] 05:26:37     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1227:19
[task 2018-09-08T05:26:37.889Z] 05:26:37     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1236:13
[task 2018-09-08T05:26:37.893Z] 05:26:37     INFO -     SimpleTest.finish@SimpleTest/SimpleTest.js:1240:5
[task 2018-09-08T05:26:37.894Z] 05:26:37     INFO -     add_task/</<@SimpleTest/AddTask.js:72:11
[task 2018-09-08T05:26:37.894Z] 05:26:37     INFO -     async*add_task/<@SimpleTest/AddTask.js:31:10
[task 2018-09-08T05:26:37.894Z] 05:26:37     INFO -     setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:676:12
[task 2018-09-08T05:26:37.895Z] 05:26:37     INFO -     add_task@SimpleTest/AddTask.js:30:7
[task 2018-09-08T05:26:37.895Z] 05:26:37     INFO -     @toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html:190:1
[task 2018-09-08T05:26:37.895Z] 05:26:37     INFO - GECKO(3370) | MEMORY STAT | vsize 1548MB | residentFast 169MB | heapAllocated 32MB
[task 2018-09-08T05:26:37.896Z] 05:26:37     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test-oop-extensions/test_ext_webrequest_frameId.html | took 7619ms
Flags: needinfo?(ddurst)
Whiteboard: [stockwell needswork:owner]
In the last 7 days there are 92 failures associated with this bug.

This started to increase after https://bugzilla.mozilla.org/show_bug.cgi?id=1480951 landed.

Did some retriggers and this is the result: https://tinyurl.com/yahx6hn2 

Intermittent Failures View: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-09-04&endday=2018-09-11&tree=all&bug=1482983

:mconley, Could you please have a look at this frequently failing bug? Thanks!
Flags: needinfo?(mconley)
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner][retriggered]
Attached patch Skipped test on linux webrender (deleted) — Splinter Review
I added a patch to disable test_ext_webrequest_frameId.html
Attachment #9008344 - Flags: review?(aryx.bugmail)
Keywords: leave-open
Pushed by ebalazs@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3059f63d7f56
Disable test_ext_webrequest_frameId.html on linux webrender for frequent failures caused by 1480951. r=aryx
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Flags: needinfo?(ddurst)
No longer blocks: 1480951
Severity: normal → S3
Regressed by: 1480951
Keywords: regression
OS: Unspecified → Linux
Has Regression Range: --- → yes

I ran all webRequest tests again and encountered this failure again. This is not the first time I'm seeing it. The failure is not even necessary, so I'll attach a patch.

Assignee: nobody → rob
Flags: needinfo?(mconley)
Keywords: leave-open
Whiteboard: [retriggered][stockwell disabled] → [retriggered][stockwell disabled][addons-jira]

The test was getting stuck because it was expecting a favicon.ico
request that never happened. The test logic was copied from
test_ext_webrequest_filter.html which suffers from exactly the same
issue. Since the favicon.ico test was meant to serve as a regression
test, this patch fixes only one of the two tests.

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE

Why did the bot close this bug when there is a patch?

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → ASSIGNED
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/d59210a65575
Fix intermittent test failure in test_ext_webrequest_frameId.html r=rpl

Backed out for causing failures on test_ext_webrequest_frameId.html

[task 2023-05-03T20:23:48.070Z] 20:23:48     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_frameId.html | Got only one request for file_simple_sandboxed_subframe.html 
[task 2023-05-03T20:23:48.070Z] 20:23:48     INFO - Waiting for request 12 out of 13
[task 2023-05-03T20:23:48.071Z] 20:23:48     INFO - Expecting one of: example.txt
[task 2023-05-03T20:23:48.071Z] 20:23:48     INFO - Buffered messages finished
[task 2023-05-03T20:23:48.072Z] 20:23:48     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_frameId.html | Test timed out. - 
[task 2023-05-03T20:23:48.890Z] 20:23:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-05-03T20:23:48.894Z] 20:23:48     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_frameId.html | Extension left running at test shutdown 
[task 2023-05-03T20:23:48.894Z] 20:23:48     INFO - SimpleTest.ok@https://mochi.test:8888/tests/SimpleTest/SimpleTest.js:424:16
[task 2023-05-03T20:23:48.894Z] 20:23:48     INFO - ExtensionTestUtils.loadExtension/<@https://mochi.test:8888/tests/SimpleTest/ExtensionTestUtils.js:132:18
[task 2023-05-03T20:23:48.894Z] 20:23:48     INFO - executeCleanupFunction@https://mochi.test:8888/tests/SimpleTest/SimpleTest.js:1527:13
[task 2023-05-03T20:23:48.894Z] 20:23:48     INFO - SimpleTest.finish@https://mochi.test:8888/tests/SimpleTest/SimpleTest.js:1541:3
[task 2023-05-03T20:23:48.895Z] 20:23:48     INFO - killTest@https://mochi.test:8888/tests/SimpleTest/TestRunner.js:202:22
[task 2023-05-03T20:23:48.895Z] 20:23:48     INFO - async*delayedKillTest@https://mochi.test:8888/tests/SimpleTest/TestRunner.js:239:17
[task 2023-05-03T20:23:48.895Z] 20:23:48     INFO - setTimeout handler*TestRunner._checkForHangs@https://mochi.test:8888/tests/SimpleTest/TestRunner.js:237:17
[task 2023-05-03T20:23:48.898Z] 20:23:48     INFO - TestRunner.runTests/<@https://mochi.test:8888/tests/SimpleTest/TestRunner.js:530:16
[task 2023-05-03T20:23:48.899Z] 20:23:48     INFO - Async*TestRunner.runTests@https://mochi.test:8888/tests/SimpleTest/TestRunner.js:517:48
[task 2023-05-03T20:23:48.899Z] 20:23:48     INFO - RunSet.runtests@https://mochi.test:8888/tests/SimpleTest/setup.js:276:14
[task 2023-05-03T20:23:48.899Z] 20:23:48     INFO - RunSet.runall@https://mochi.test:8888/tests/SimpleTest/setup.js:255:12
[task 2023-05-03T20:23:48.899Z] 20:23:48     INFO - getPrefList/<@https://mochi.test:8888/tests/SimpleTest/setup.js:342:14
[task 2023-05-03T20:23:48.899Z] 20:23:48     INFO - loadFile/req.onload@https://mochi.test:8888/tests/SimpleTest/setup.js:80:19
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - EventHandlerNonNull*loadFile@https://mochi.test:8888/tests/SimpleTest/setup.js:75:3
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - getPrefList@https://mochi.test:8888/tests/SimpleTest/setup.js:340:13
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - hookupTests@https://mochi.test:8888/tests/SimpleTest/setup.js:363:5
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - parseTestManifest@https://mochi.test:8888/manifestLibrary.js:53:13
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - getTestManifest/req.onload@https://mochi.test:8888/manifestLibrary.js:66:28
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - EventHandlerNonNull*getTestManifest@https://mochi.test:8888/manifestLibrary.js:62:3
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - hookup@https://mochi.test:8888/tests/SimpleTest/setup.js:328:20
[task 2023-05-03T20:23:48.900Z] 20:23:48     INFO - EventHandlerNonNull*@https://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true&ignorePrefsFile=ignorePrefs.json:10:32
[task 2023-05-03T20:23:48.904Z] 20:23:48     INFO - GECKO(5377) | [Parent 5377, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-05-03T20:23:48.905Z] 20:23:48     INFO - GECKO(5377) | [Parent 5377, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-05-03T20:23:48.914Z] 20:23:48     INFO - GECKO(5377) | [Parent 5377, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-05-03T20:23:48.927Z] 20:23:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-05-03T20:23:48.929Z] 20:23:48     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_frameId.html | message queue is empty - got "[\"tab-created\"]", expected "[]"
Flags: needinfo?(rob)

The test failed on http3 tests, because in that test configuration, there is only a https server, no http.

When I run the test locally in that configuration, ./mach test toolkit/components/extensions/test/mochitest/test_ext_webrequest_frameId.html --tag=remote-webextensions --headless --use-http3-server, I see the following:

Console message: [JavaScript Error: "Blocked loading mixed active content “http://example.org/example.txt”" {file: "https://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_simple_xhr.html?topframe=true&nocache=0.7112531975458067" line: 14}]

Without --use-http3-server, I see the following at some point:

INFO Checking details for request 3: {"requestId":"24","url":"http://example.org/example.txt","originUrl":"http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_simple_xhr.html?topframe=true&nocache=0.02077408161558536", (... cut off by me)

This looks like a class of problems that may be relevant to others who are interested in re-enabling more tests without skip-if = http3.

I fixed this particular test by changing http to https at https://searchfox.org/mozilla-central/rev/85b4f7363292b272eb9b606e00de2c37a6be73f0/toolkit/components/extensions/test/mochitest/file_simple_xhr.html#13

Flags: needinfo?(rob)
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/87f16577a95a
Fix intermittent test failure in test_ext_webrequest_frameId.html r=rpl
Status: ASSIGNED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED
Target Milestone: --- → 114 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: