Intermittent tier2 devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | The output contains the the expected messages, in the expected order - Got [

RESOLVED FIXED in Firefox 64

Status

defect
P5
normal
RESOLVED FIXED
11 months ago
10 months ago

People

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

Tracking

({intermittent-failure})

unspecified
Firefox 64
Points:
---

Firefox Tracking Flags

(firefox64 fixed)

Details

Attachments

(1 attachment)

Filed by: rgurzau [at] mozilla.com

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

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

18:14:08     INFO - TEST-START | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js
18:14:08     INFO - GECKO(3504) | ++DOCSHELL 01467000 == 2 [pid = 1108] [id = {c3c2f916-72f6-4828-a32c-2b689f7afcea}]
18:14:08     INFO - GECKO(3504) | ++DOMWINDOW == 3 (014BF410) [pid = 1108] [serial = 30] [outer = 00000000]
18:14:08     INFO - GECKO(3504) | ++DOMWINDOW == 4 (07FD9800) [pid = 1108] [serial = 31] [outer = 014BF410]
18:14:08     INFO - GECKO(3504) | ++DOMWINDOW == 5 (07FDB800) [pid = 1108] [serial = 32] [outer = 014BF410]
18:14:08     INFO - GECKO(3504) | ++DOCSHELL 00799C00 == 7 [pid = 3504] [id = {4b58393d-b955-48d9-89d2-15cbb3383837}]
18:14:08     INFO - GECKO(3504) | ++DOMWINDOW == 27 (0B35EB30) [pid = 3504] [serial = 129] [outer = 00000000]
18:14:08     INFO - GECKO(3504) | ++DOMWINDOW == 28 (17884800) [pid = 3504] [serial = 130] [outer = 0B35EB30]
18:14:09     INFO - GECKO(3504) | ++DOMWINDOW == 29 (19DB1800) [pid = 3504] [serial = 131] [outer = 0B35EB30]
18:14:09     INFO - GECKO(3504) | ++DOCSHELL 19DB5C00 == 8 [pid = 3504] [id = {03e7691c-9a5e-4560-a3e8-e531041e1fa1}]
18:14:09     INFO - GECKO(3504) | ++DOMWINDOW == 30 (0B3601C0) [pid = 3504] [serial = 132] [outer = 00000000]
18:14:09     INFO - GECKO(3504) | ++DOMWINDOW == 31 (1B10E400) [pid = 3504] [serial = 133] [outer = 0B3601C0]
18:14:15     INFO - GECKO(3504) | --DOCSHELL 00A6B800 == 0 [pid = 3596] [id = {d606f750-0783-46e9-bcb9-d2cbf0c3eaf9}]
18:14:16     INFO - GECKO(3504) | --DOMWINDOW == 30 (0B360C70) [pid = 3504] [serial = 122] [outer = 00000000] [url = about:blank]
18:14:16     INFO - GECKO(3504) | --DOMWINDOW == 29 (0B35EFF0) [pid = 3504] [serial = 125] [outer = 00000000] [url = chrome://devtools/content/webconsole/index.html]
18:14:16     INFO - GECKO(3504) | --DOMWINDOW == 28 (1EBB0D90) [pid = 3504] [serial = 120] [outer = 00000000] [url = chrome://devtools/content/webconsole/index.html]
18:14:16     INFO - GECKO(3504) | --DOMWINDOW == 27 (0B35E410) [pid = 3504] [serial = 117] [outer = 00000000] [url = about:blank]
18:14:16     INFO - GECKO(3504) | ++DOCSHELL 00A6B800 == 1 [pid = 3596] [id = {e2c777f9-b147-472c-88f4-551ea0a1dbfc}]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 3 (00AAD410) [pid = 3596] [serial = 28] [outer = 00000000]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 4 (079D8800) [pid = 3596] [serial = 29] [outer = 00AAD410]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 5 (0ADA9400) [pid = 3596] [serial = 30] [outer = 00AAD410]
18:14:16     INFO - GECKO(3504) | --DOMWINDOW == 4 (014BF540) [pid = 1108] [serial = 27] [outer = 00000000] [url = about:blank]
18:14:16     INFO - GECKO(3504) | --DOCSHELL 0146A000 == 1 [pid = 1108] [id = {cb281809-a92a-4e44-9e25-0ceeb8348fbe}]
18:14:16     INFO - GECKO(3504) | ++DOCSHELL 0079CC00 == 9 [pid = 3504] [id = {7ebca0db-68c4-4f60-80e0-0c63cbc9be7d}]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 28 (1EBB0D90) [pid = 3504] [serial = 134] [outer = 00000000]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 29 (17088C00) [pid = 3504] [serial = 135] [outer = 1EBB0D90]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 30 (1B1A6400) [pid = 3504] [serial = 136] [outer = 1EBB0D90]
18:14:16     INFO - GECKO(3504) | --DOMWINDOW == 4 (015C9540) [pid = 5424] [serial = 25] [outer = 00000000] [url = data:text/html;charset=utf-8,Web Console test top-level await]
18:14:16     INFO - GECKO(3504) | --DOCSHELL 0156A400 == 1 [pid = 5424] [id = {6d6d09d6-b9a3-4645-9c1b-1bb7c1a72581}]
18:14:16     INFO - GECKO(3504) | ++DOCSHELL 17886C00 == 10 [pid = 3504] [id = {34f45ac2-eb17-4882-a597-79ad5f42b3af}]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 31 (0B35EFF0) [pid = 3504] [serial = 137] [outer = 00000000]
18:14:16     INFO - GECKO(3504) | ++DOMWINDOW == 32 (1BD9D000) [pid = 3504] [serial = 138] [outer = 0B35EFF0]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 31 (1B1A9800) [pid = 3504] [serial = 124] [outer = 00000000] [url = about:devtools-toolbox]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 30 (19DB4000) [pid = 3504] [serial = 119] [outer = 00000000] [url = about:devtools-toolbox]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 29 (1BDA3C00) [pid = 3504] [serial = 126] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 28 (17888C00) [pid = 3504] [serial = 123] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 27 (1B19FC00) [pid = 3504] [serial = 121] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 26 (19DAAC00) [pid = 3504] [serial = 118] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 25 (19DA7800) [pid = 3504] [serial = 127] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 24 (00799000) [pid = 3504] [serial = 128] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 3 (07FD9800) [pid = 1108] [serial = 31] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 2 (0AFA1000) [pid = 1108] [serial = 29] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 3 (0B6A0400) [pid = 5424] [serial = 29] [outer = 00000000] [url = about:blank]
18:14:20     INFO - GECKO(3504) | --DOMWINDOW == 2 (08AD2C00) [pid = 5424] [serial = 27] [outer = 00000000] [url = data:text/html;charset=utf-8,Web Console test top-level await]
18:14:22     INFO - GECKO(3504) | --DOMWINDOW == 4 (00AAD540) [pid = 3596] [serial = 25] [outer = 00000000] [url = data:text/html;charset=utf-8,Web Console test top-level await]
18:14:24     INFO - TEST-INFO | started process screenshot
18:14:24     INFO - TEST-INFO | screenshot: exit 0
18:14:24     INFO - Buffered messages logged at 18:14:08
18:14:24     INFO - Entering test bound 
18:14:24     INFO - Adding a new tab with URL: data:text/html;charset=utf-8,Web Console test top-level await
18:14:24     INFO - Tab added and finished loading
18:14:24     INFO - Opening the toolbox
18:14:24     INFO - Buffered messages logged at 18:14:10
18:14:24     INFO - Toolbox opened and focused
18:14:24     INFO - Evaluate a top-level await expression
18:14:24     INFO - Buffered messages logged at 18:14:11
18:14:24     INFO - Matched a message with text: "await1", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | The output contains the the expected messages - 
18:14:24     INFO - Check that assigning the result of a top-level await expression works
18:14:24     INFO - Buffered messages logged at 18:14:12
18:14:24     INFO - Matched a message with text: "await2", all messages received.
18:14:24     INFO - Matched a message with text: ""-await2-"", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | `x` was assigned as expected - 
18:14:24     INFO - Check that awaiting for a rejecting promise displays an error
18:14:24     INFO - Buffered messages logged at 18:14:13
18:14:24     INFO - Matched a message with text: "await-rej", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | awaiting for a rejecting promise displays an error message - 
18:14:24     INFO - Check that concurrent await expression work fine
18:14:24     INFO - Buffered messages logged at 18:14:16
18:14:24     INFO - Matched a message with text: "await-concurrent-2000", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | The output contains the the expected messages, in the expected order - 
18:14:24     INFO - Check that a logged promise is still displayed as a promise
18:14:24     INFO - Matched a message with text: "Promise {", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | Promise are displayed as expected - 
18:14:24     INFO - Adding a new tab with URL: data:text/html;charset=utf-8,Web Console test top-level await
18:14:24     INFO - Tab added and finished loading
18:14:24     INFO - Opening the toolbox
18:14:24     INFO - Buffered messages logged at 18:14:17
18:14:24     INFO - Toolbox opened and focused
18:14:24     INFO - Evaluate a top-level await expression
18:14:24     INFO - Buffered messages logged at 18:14:19
18:14:24     INFO - Matched a message with text: "await1", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | The output contains the the expected messages - 
18:14:24     INFO - Check that assigning the result of a top-level await expression works
18:14:24     INFO - Buffered messages logged at 18:14:21
18:14:24     INFO - Matched a message with text: "await2", all messages received.
18:14:24     INFO - Matched a message with text: ""-await2-"", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | `x` was assigned as expected - 
18:14:24     INFO - Check that awaiting for a rejecting promise displays an error
18:14:24     INFO - Buffered messages logged at 18:14:22
18:14:24     INFO - Matched a message with text: "await-rej", all messages received.
18:14:24     INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | awaiting for a rejecting promise displays an error message - 
18:14:24     INFO - Check that concurrent await expression work fine
18:14:24     INFO - Buffered messages logged at 18:14:24
18:14:24     INFO - Matched a message with text: "await-concurrent-2000", all messages received.
18:14:24     INFO - Buffered messages finished
18:14:24     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | The output contains the the expected messages, in the expected order - Got [
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 2000), 2000))",
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 500), 500))",
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 1000), 1000))",
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 1500), 1500))",
18:14:24     INFO -   "await-concurrent-500",
18:14:24     INFO -   "await-concurrent-1000",
18:14:24     INFO -   "await-concurrent-2000",
18:14:24     INFO -   "await-concurrent-1500"
18:14:24     INFO - ], expected [
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 2000), 2000))",
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 500), 500))",
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 1000), 1000))",
18:14:24     INFO -   "await new Promise(\n    r => setTimeout(() => r(\"await-concurrent-\" + 1500), 1500))",
18:14:24     INFO -   "await-concurrent-500",
18:14:24     INFO -   "await-concurrent-1000",
18:14:24     INFO -   "await-concurrent-1500",
18:14:24     INFO -   "await-concurrent-2000"
18:14:24     INFO - ]
18:14:24     INFO - Stack trace:
18:14:24     INFO - chrome://mochikit/content/browser-test.js:test_is:1304
18:14:24     INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/mochitest/browser_jsterm_await.js:performTests:77
18:14:24     INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/mochitest/browser_jsterm_await.js:null:19
18:14:24     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1102
18:14:24     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1093
18:14:24     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:990
18:14:24     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
18:14:24     INFO - Check that a logged promise is still displayed as a promise
Summary: Intermittent TV tier2 devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | The output contains the the expected messages, in the expected order - Got [ → Intermittent tier2 devtools/client/webconsole/test/mochitest/browser_jsterm_await.js | The output contains the the expected messages, in the expected order - Got [
Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
The test is failing because the result of the last
evaluation is received before we expect it. Since we
had a 500ms delay between each promise resolution, it
might happen than the time it takes to execute the
command execedes this delay, making our expected message
order wrong. Increasing the delay to 1s might fix the issue.
Erf, I'm still getting failures https://treeherder.mozilla.org/#/jobs?repo=try&revision=0af2aa334dc4b809a1c6bde154ee9d112595709f.
I think I'm going to move this to a dedicated test an increase the delay between each resolution
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1ef10ec64cb7
Fix intermittent on browser_jsterm_await.js; r=Honza.
https://hg.mozilla.org/mozilla-central/rev/1ef10ec64cb7
Status: ASSIGNED → RESOLVED
Closed: 10 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 64
You need to log in before you can comment on or make changes to this bug.