Closed Bug 1670570 Opened 5 years ago Closed 5 years ago

Intermittent devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent - Got "1", expected "0"

Categories

(DevTools :: Console, defect, P5)

defect

Tracking

(firefox-esr78 unaffected, firefox81 unaffected, firefox82 unaffected, firefox83 wontfix, firefox84 wontfix, firefox85 wontfix, firefox86 wontfix, firefox87 wontfix, firefox88 fixed, firefox89 fixed)

RESOLVED FIXED
89 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox81 --- unaffected
firefox82 --- unaffected
firefox83 --- wontfix
firefox84 --- wontfix
firefox85 --- wontfix
firefox86 --- wontfix
firefox87 --- wontfix
firefox88 --- fixed
firefox89 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell needswork:owner])

Attachments

(1 file)

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=318338211&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WTdRcwd_T7KQaQJaWiw97A/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WTdRcwd_T7KQaQJaWiw97A/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2020-10-12T09:36:33.964Z] 09:36:33     INFO - TEST-START | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js
[task 2020-10-12T09:36:38.153Z] 09:36:38     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent - 
[task 2020-10-12T09:36:38.154Z] 09:36:38     INFO - Refreshing tab.
[task 2020-10-12T09:36:38.155Z] 09:36:38     INFO - Matched a message with text: "hello", all messages received.
[task 2020-10-12T09:36:38.155Z] 09:36:38     INFO - Tab finished refreshing.
[task 2020-10-12T09:36:38.156Z] 09:36:38     INFO - Buffered messages finished
[task 2020-10-12T09:36:38.157Z] 09:36:38     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent - Got "1", expected "0"
[task 2020-10-12T09:36:38.157Z] 09:36:38     INFO - Stack trace:
[task 2020-10-12T09:36:38.158Z] 09:36:38     INFO - chrome://mochikit/content/browser-test.js:test_is:1332
[task 2020-10-12T09:36:38.158Z] 09:36:38     INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js:refreshTabAndCheckIndent:24
[task 2020-10-12T09:36:38.159Z] 09:36:38     INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js:null:15
[task 2020-10-12T09:36:38.159Z] 09:36:38     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1069
[task 2020-10-12T09:36:38.160Z] 09:36:38     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1109
[task 2020-10-12T09:36:38.160Z] 09:36:38     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:932
[task 2020-10-12T09:36:38.160Z] 09:36:38     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:1037
[task 2020-10-12T09:36:38.161Z] 09:36:38     INFO - Leaving test bound 
[task 2020-10-12T09:36:38.162Z] 09:36:38     INFO - GECKO(3384) | [Parent 3384, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1601
[task 2020-10-12T09:36:39.151Z] 09:36:39     INFO - Removing tab.
[task 2020-10-12T09:36:39.152Z] 09:36:39     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-10-12T09:36:39.172Z] 09:36:39     INFO - Got event: 'TabClose' on [object XULElement].```
Summary: Intermittent TV tier 2 devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent - Got "1", expected "0" → Intermittent devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent - Got "1", expected "0"
Has Regression Range: --- → yes

I'll have a look, there's probably a race condition somewhere

Flags: needinfo?(nchevobbe)

Nicolas, did you have the opportunity to look at this bug? Thanks

Flags: needinfo?(nchevobbe)

There are 33 total failures in the last 7 days on

  • linux1804-64 debug
  • macosx1014-64-qr debug
  • windows10-64 asan and debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=333704141&repo=autoland&lineNumber=37067

[task 2021-03-18T23:06:02.749Z] 23:06:02 INFO - TEST-INFO | started process screencapture
[task 2021-03-18T23:06:02.875Z] 23:06:02 INFO - TEST-INFO | screencapture: exit 0
[task 2021-03-18T23:06:02.875Z] 23:06:02 INFO - Buffered messages logged at 23:06:00
[task 2021-03-18T23:06:02.875Z] 23:06:02 INFO - Entering test bound
[task 2021-03-18T23:06:02.875Z] 23:06:02 INFO - Adding a new tab with URL: data:text/html;charset=utf8,<script>console.group('hello')</script>
[task 2021-03-18T23:06:02.876Z] 23:06:02 INFO - Tab added and finished loading
[task 2021-03-18T23:06:02.876Z] 23:06:02 INFO - Opening the toolbox
[task 2021-03-18T23:06:02.876Z] 23:06:02 INFO - Buffered messages logged at 23:06:01
[task 2021-03-18T23:06:02.876Z] 23:06:02 INFO - Console message: Invalid chrome URI (need path): chrome://devtools/
[task 2021-03-18T23:06:02.877Z] 23:06:02 INFO - Buffered messages logged at 23:06:02
[task 2021-03-18T23:06:02.877Z] 23:06:02 INFO - Toolbox opened and focused
[task 2021-03-18T23:06:02.877Z] 23:06:02 INFO - Refresh tab several times and check for correct message indentation
[task 2021-03-18T23:06:02.877Z] 23:06:02 INFO - Refreshing tab.
[task 2021-03-18T23:06:02.877Z] 23:06:02 INFO - Matched a message with text: "hello", all messages received.
[task 2021-03-18T23:06:02.877Z] 23:06:02 INFO - Tab finished refreshing.
[task 2021-03-18T23:06:02.878Z] 23:06:02 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent -
[task 2021-03-18T23:06:02.878Z] 23:06:02 INFO - Refreshing tab.
[task 2021-03-18T23:06:02.878Z] 23:06:02 INFO - Matched a message with text: "hello", all messages received.
[task 2021-03-18T23:06:02.878Z] 23:06:02 INFO - Tab finished refreshing.
[task 2021-03-18T23:06:02.878Z] 23:06:02 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent -
[task 2021-03-18T23:06:02.878Z] 23:06:02 INFO - Refreshing tab.
[task 2021-03-18T23:06:02.878Z] 23:06:02 INFO - Matched a message with text: "hello", all messages received.
[task 2021-03-18T23:06:02.879Z] 23:06:02 INFO - Tab finished refreshing.
[task 2021-03-18T23:06:02.879Z] 23:06:02 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent -
[task 2021-03-18T23:06:02.879Z] 23:06:02 INFO - Refreshing tab.
[task 2021-03-18T23:06:02.879Z] 23:06:02 INFO - Matched a message with text: "hello", all messages received.
[task 2021-03-18T23:06:02.879Z] 23:06:02 INFO - Tab finished refreshing.
[task 2021-03-18T23:06:02.879Z] 23:06:02 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent -
[task 2021-03-18T23:06:02.879Z] 23:06:02 INFO - Refreshing tab.
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - Matched a message with text: "hello", all messages received.
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - Tab finished refreshing.
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - Buffered messages finished
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The message has the expected indent - Got "1", expected "0"
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - Stack trace:
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - chrome://mochikit/content/browser-test.js:test_is:1359
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js:refreshTabAndCheckIndent:24
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js:null:15
[task 2021-03-18T23:06:02.880Z] 23:06:02 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1089
[task 2021-03-18T23:06:02.881Z] 23:06:02 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1129
[task 2021-03-18T23:06:02.881Z] 23:06:02 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:949
[task 2021-03-18T23:06:02.881Z] 23:06:02 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:1037
[task 2021-03-18T23:06:02.881Z] 23:06:02 INFO - Leaving test bound
[task 2021-03-18T23:06:02.881Z] 23:06:02 INFO - GECKO(1697) | [Parent 1697, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-03-18T23:06:04.225Z] 23:06:04 INFO - GECKO(1697) | [Parent 1697: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 22 (122c1e400) [pid = 1697] [serial = 116] [outer = 0] [url = about:blank]
[task 2021-03-18T23:06:04.225Z] 23:06:04 INFO - GECKO(1697) | [Parent 1697: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 21 (135ce6c00) [pid = 1697] [serial = 110] [outer = 0] [url = about:devtools-toolbox]
[task 2021-03-18T23:06:04.225Z] 23:06:04 INFO - GECKO(1697) | [Parent 1697: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 20 (1296b0000) [pid = 1697] [serial = 114] [outer = 0] [url = about:blank]
[task 2021-03-18T23:06:04.225Z] 23:06:04 INFO - GECKO(1697) | [Parent 1697: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 19 (15df5cc00) [pid = 1697] [serial = 112] [outer = 0] [url = about:blank]
[task 2021-03-18T23:06:04.240Z] 23:06:04 INFO - Removing tab.
[task 2021-03-18T23:06:04.241Z] 23:06:04 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2021-03-18T23:06:04.241Z] 23:06:04 INFO - Got event: 'TabClose' on [object XULElement].
[task 2021-03-18T23:06:04.241Z] 23:06:04 INFO - GECKO(1697) | console.warn: "IGNORED REDUX ACTION:" "AUTOCOMPLETE_CLEAR"
[task 2021-03-18T23:06:04.241Z] 23:06:04 INFO - GECKO(1697) | [Child 1699, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/caps/BasePrincipal.cpp:1349
[task 2021-03-18T23:06:04.242Z] 23:06:04 INFO - GECKO(1697) | [Parent 1697, Main Thread] WARNING: NS_ENSURE_TRUE(uri) failed: file /builds/worker/checkouts/gecko/caps/BasePrincipal.cpp:1327
[task 2021-03-18T23:06:04.242Z] 23:06:04 INFO - GECKO(1697) | [Parent 1697, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:181
[task 2021-03-18T23:06:04.242Z] 23:06:04 INFO - Tab removed and finished closing
[task 2021-03-18T23:06:04.284Z] 23:06:04 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2021-03-18T23:06:04.325Z] 23:06:04 INFO - GECKO(1697) | MEMORY STAT | vsize 8118MB | residentFast 585MB | heapAllocated 168MB
[task 2021-03-18T23:06:04.326Z] 23:06:04 INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_webconsole_close_groups_after_navigation.js | took 3476ms>

Nicholas are you working on this?

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

I'm looking at this today

Flags: needinfo?(nchevobbe)

The test was adding a tab with a page that does a console.group call, and then
was refreshing the page and waiting for the next console.group message to be displayed.
The problem seems to be that we weren't waiting for the initial console.group message,
which might mess up the rest of the test.
We're fixing this in the patch, and adding selector to waitForMessage so we
are sure to get the console.group message (and not another message, as the location
does have the hello world in it, since we're using a data url).

Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
Pushed by nchevobbe@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/c63edf123853 [devtools] Fix intermittent on browser_webconsole_close_groups_after_navigation.js. r=bomsy
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → 89 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: