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

Status: RESOLVED FIXED

(DevTools :: Console, defect, P5)

Description

[Treeherder Bug Filer]

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

Comment 1

[Intermittent Failures Robot]

12 failures in 2773 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 1
* try: 1
* mozilla-central: 10

Platform breakdown:
* windows7-32-msvc: 1
* windows7-32: 1
* windows10-64-ccov: 8
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1493837&startday=2018-09-24&endday=2018-09-30&tree=all

Comment 2

[Intermittent Failures Robot]

29 failures in 2708 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 29

Platform breakdown:
* windows10-64-ccov: 29

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1493837&startday=2018-10-01&endday=2018-10-07&tree=all

Comment 3

[Intermittent Failures Robot]

31 failures in 2740 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* mozilla-central: 30
* mozilla-inbound: 1

Platform breakdown:
* linux64: 1
* linux64-ccov: 6
* windows10-64-msvc: 1
* windows10-64-ccov: 22
* windows7-32-msvc: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1493837&startday=2018-10-08&endday=2018-10-14&tree=all

Comment 4

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1493837 - Fix intermittent on browser_jsterm_await.js; r=Honza.

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.

Comment 5

[Nicolas Chevobbe [:nchevobbe]]

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

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1ef10ec64cb7
Fix intermittent on browser_jsterm_await.js; r=Honza.

Comment 7

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/1ef10ec64cb7

Comment 8

[Intermittent Failures Robot]

7 failures in 2759 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 2
* mozilla-central: 5

Platform breakdown:
* windows10-64: 2
* osx-10-10: 1
* windows10-64-ccov: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1493837&startday=2018-10-15&endday=2018-10-21&tree=all