Intermittent devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_expand.js | Test timed out -

RESOLVED FIXED in Firefox 59

Status

defect
P5
normal
RESOLVED FIXED
2 years ago
7 months ago

People

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

Tracking

(Blocks 1 bug, {intermittent-failure})

unspecified
Firefox 59
Dependency tree / graph

Firefox Tracking Flags

(firefox59 fixed)

Details

(Whiteboard: [stockwell fixed:timing])

Attachments

(1 attachment)

Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
https://wiki.mozilla.org/Bugmasters#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Last Resolved: a year ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=151023396&repo=mozilla-central&lineNumber=10310
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Comment hidden (Intermittent Failures Robot)
This started after bug 1419336 touched the test. Honza, please take a look.
Flags: needinfo?(odvarko)
Comment hidden (Intermittent Failures Robot)
This bug has occurred 42 times in the last 7 days on Windows 7 and 10, Linux and OS X 10 10 platforms, affecting debug, pgo,asan and opt build types. The affected test suites are: debug-mochitest-devtools-chrome-e10 and debug-mochitest-devtools-chrome-7.

Link to a Windows 10 log:https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1398904&startday=2017-12-11&endday=2017-12-17&tree=all
Part of the log:
00:08:31     INFO -  Buffered messages finished
12188
00:08:31    ERROR -  560 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_expand.js | Test timed out -
12189
00:08:32     INFO -  GECKO(7532) | ++DOMWINDOW == 16 (0000021DD8B41C00) [pid = 7532] [serial = 528] [outer = 0000021DD856FA30]
12190
00:08:32     INFO -  GECKO(7532) | --DOCSHELL 0000021DDE26C800 == 5 [pid = 7532] [id = {fb297a81-3704-421c-b3f4-d8fc67492e98}]
12191
00:08:32     INFO -  GECKO(7532) | --DOCSHELL 0000021DDD5F1800 == 4 [pid = 7532] [id = {508def47-6cf5-4c7b-badc-d0a74b655910}]
12192
00:08:32     INFO -  561 INFO Removing tab.
12193
00:08:32     INFO -  562 INFO Waiting for event: 'TabClose' on [object XULElement].
12194
00:08:32     INFO -  563 INFO Got event: 'TabClose' on [object XULElement].
12195
00:08:32     INFO -  564 INFO Tab removed and finished closing
12196
00:08:32     INFO -  GECKO(7532) | MEMORY STAT | vsize 2799MB | vsizeMaxContiguous 131241737MB | residentFast 796MB | heapAllocated 284MB
12197
00:08:32     INFO -  565 INFO TEST-OK | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_expand.js | took 91174ms
12198
00:08:32     INFO -  GECKO(7532) | ++DOCSHELL 0000014400D86800 == 1 [pid = 5968] [id = {75e41666-3a30-4638-a5ed-ecc17760181d}]
12199
00:08:32     INFO -  GECKO(7532) | ++DOMWINDOW == 3 (000001447A5BC850) [pid = 5968] [serial = 119] [outer = 0000000000000000]
12200
00:08:32     INFO -  GECKO(7532) | ++DOMWINDOW == 4 (0000014400D3F000) [pid = 5968] [serial = 120] [outer = 000001447A5BC850]
12201
00:08:32     INFO -  566 INFO checking window state
12202
00:08:32     INFO -  567 INFO TEST-START | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_openinnet.js
12203
00:08:32     INFO -  GECKO(7532) | ++DOCSHELL 000002B736787800 == 2 [pid = 2344] [id = {ca3822be-33fa-4c7b-887a-1041d6028ea7}]
12204
00:08:32     INFO -  GECKO(7532) | ++DOMWINDOW == 3 (000002B7342B7470) [pid = 2344] [serial = 187] [outer = 0000000000000000]
12205
00:08:33     INFO -  GECKO(7532) | ++DOMWINDOW == 4 (000002B73892D800) [pid = 2344] [serial = 188] [outer = 000002B7342B7470]
12206
00:08:33     INFO -  GECKO(7532) | ++DOMWINDOW == 5 (000002B738931800) [pid = 2344] [serial = 189] [outer = 000002B7342B7470]
12207
00:08:33     INFO -  GECKO(7532) | ++DOCSHELL 0000021DD86AB800 == 5 [pid = 7532] [id = {3cc4e36d-ac6b-422f-b2b8-3ce43a9ee1a8}]
12208
00:08:33     INFO -  GECKO(7532) | ++DOMWINDOW == 17 (0000021DD7BF9470) [pid = 7532] [serial = 529] [outer = 0000000000000000]
12209
00:08:33     INFO -  GECKO(7532) | ++DOMWINDOW == 18 (0000021DD8657800) [pid = 7532] [serial = 530] [outer = 0000021DD7BF9470]
12210
00:08:34     INFO -  GECKO(7532) | ++DOMWINDOW == 19 (0000021DD8B42800) [pid = 7532] [serial = 531] [outer = 0000021DD7BF9470]
12211
00:08:34     INFO -  GECKO(7532) | [Parent 7532, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004001: file z:/build/build/src/dom/xul/nsXULPrototypeCache.cpp, line 352
12212
00:08:35     INFO -  GECKO(7532) | ++DOCSHELL 0000021DDBDD0800 == 6 [pid = 7532] [id = {612afab5-5eec-423f-ad87-6c6c65237261}]
12213
00:08:35     INFO -  GECKO(7532) | ++DOMWINDOW == 20 (0000021DD7BF9660) [pid = 7532] [serial = 532] [outer = 0000000000000000]
12214
00:08:35     INFO -  GECKO(7532) | ++DOMWINDOW == 21 (0000021DD8BBD000) [pid = 7532] [serial = 533] [outer = 0000021DD7BF9660]
12215
00:08:35     INFO -  GECKO(7532) | [Parent 7532, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/layout/style/Loader.cpp, line 2398
12216
00:08:35     INFO -  GECKO(7532) | [Parent 7532, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/layout/style/Loader.cpp, line 2090
12217
00:08:39     INFO -  GECKO(7532) | [Parent 7532, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file z:/build/build/src/netwerk/base/nsChannelClassifier.cpp, line 344
12218
00:08:39     INFO -  GECKO(7532) | ++DOMWINDOW == 6 (000002B73940B800) [pid = 2344] [serial = 190] [outer = 000002B7342B7470]
12219
00:08:40     INFO -  GECKO(7532) | --DOMWINDOW == 3 (000001447A5BC470) [pid = 5968] [serial = 117] [outer = 0000000000000000] [url = about:blank]
12220
00:08:40     INFO -  GECKO(7532) | ++DOCSHELL 0000021DD8A94000 == 7 [pid = 7532] [id = {794ee495-7dc4-479b-b132-f571b5772e2a}]
12221
00:08:40     INFO -  GECKO(7532) | ++DOMWINDOW == 22 (0000021DD7BF9E20) [pid = 7532] [serial = 534] [outer = 0000000000000000]
12222
00:08:40     INFO -  GECKO(7532) | ++DOMWINDOW == 23 (0000021DD8E19000) [pid = 7532] [serial = 535] [outer = 0000021DD7BF9E20]
12223
00:08:40     INFO -  GECKO(7532) | --DOCSHELL 000002B736F65800 == 1 [pid = 2344] [id = {3f13df11-ed6d-4592-aa24-3f62fa9db251}]
12224
00:08:41     INFO -  GECKO(7532) | --DOCSHELL 0000025C45E30800 == 0 [pid = 2712] [id = {234736f9-6955-4fe4-9d57-0c59120a63ae}]
12225
00:08:41     INFO -  GECKO(7532) | --DOMWINDOW == 5 (000002B7342B7660) [pid = 2344] [serial = 184] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/webconsole/new-console-output/test/mochitest/test-network-request.html]
12226
00:08:41     INFO -  GECKO(7532) | --DOMWINDOW == 1 (0000025C4B4AFC30) [pid = 2712] [serial = 103] [outer = 0000000000000000] [url = about:blank]
12227
00:08:45     INFO -  GECKO(7532) | [Parent 7532, Main Thread] WARNING: ENSURE_TRUE(weakFrame.IsAlive()) failed: file z:/build/build/src/layout/xul/nsXULPopupManager.cpp, line 1193
12228
00:08:45     INFO -  GECKO(7532) | --DOMWINDOW == 0 (0000025C4C036C00) [pid = 2712] [serial = 104] [outer = 0000000000000000] [url = about:blank]
12229
00:08:47     INFO -  GECKO(7532) | ++DOMWINDOW == 24 (0000021DD9241800) [pid = 7532] [serial = 536] [outer = 0000021DD7BF9470]
12230
00:08:47     INFO -  GECKO(7532) | --DOMWINDOW == 4 (000002B73940BC00) [pid = 2344] [serial = 186] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/webconsole/new-console-output/test/mochitest/test-network-request.html]
12231
00:08:47     INFO -  GECKO(7532) | --DOMWINDOW == 3 (000002B73892D800) [pid = 2344] [serial = 188] [outer = 0000000000000000] [url = about:blank]
12232
00:08:47     INFO -  GECKO(7532) | --DOMWINDOW == 2 (0000014400D3DC00) [pid = 5968] [serial = 118] [outer = 0000000000000000] [url = about:blank]
12233
00:08:47     INFO -  GECKO(7532) | MEMORY STAT | vsize 2802MB | vsizeMaxContiguous 131241737MB | residentFast 840MB | heapAllocated 327MB
12234
00:08:47     INFO -  568 INFO TEST-OK | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_openinnet.js | took 14909ms

:Honza and :bgrins could you please take a look?
Whiteboard: [stockwell needswork]
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
There are 39 failures in the past 7 days.
Platforms: Linux opt, Linux x64 debug/pgo, linux64-stylo-disabled opt/debug, OS X 10.10 opt, Windows 7 debug/opt, windows10-64 debug/opt/pgo and windows10-64-ccov debug.
Recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=154570786&lineNumber=16780
Relevant part of the log:
TEST-INFO | started process screenshot
16766
16:46:26     INFO -  TEST-INFO | screenshot: exit 0
16767
16:46:26     INFO -  Buffered messages logged at 16:44:56
16768
16:46:26     INFO -  691 INFO Entering test bound task
16769
16:46:26     INFO -  692 INFO Adding a new tab with URL: http://example.com/browser/devtools/client/webconsole/new-console-output/test/mochitest/test-network-request.html
16770
16:46:26     INFO -  693 INFO Tab added and finished loading
16771
16:46:26     INFO -  694 INFO Opening the toolbox
16772
16:46:26     INFO -  Buffered messages logged at 16:44:57
16773
16:46:26     INFO -  695 INFO Console message: [JavaScript Warning: "Unknown property ‘user-select’.  Declaration dropped." {file: "resource://devtools/client/shared/components/reps/reps.css" line: 257 column: 13 source: "  user-select: none;"}]
16774
16:46:26     INFO -  Buffered messages logged at 16:44:58
16775
16:46:26     INFO -  696 INFO Toolbox opened and focused
16776
16:46:26     INFO -  Buffered messages logged at 16:45:01
16777
16:46:26     INFO -  697 INFO Matched a message with text: "http://example.com/browser/devtools/client/webconsole/new-console-output/test/mochitest/sjs_slow-response-test-server.sjs", all messages received.
16778
16:46:26     INFO -  698 INFO Network message found.
16779
16:46:26     INFO -  Buffered messages finished
16780
16:46:26    ERROR -  699 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_expand.js | Test timed out -
16781
16:46:26     INFO -  GECKO(4020) | ++DOMWINDOW == 27 (0E19B800) [pid = 4020] [serial = 1007] [outer = 0F860EE0]
16782
16:46:26     INFO -  700 INFO Removing tab.
16783
16:46:26     INFO -  701 INFO Waiting for event: 'TabClose' on [object XULElement].
16784
16:46:26     INFO -  702 INFO Got event: 'TabClose' on [object XULElement].
16785
16:46:26     INFO -  703 INFO Tab removed and finished closing
16786
16:46:26     INFO -  GECKO(4020) | MEMORY STAT | vsize 1185MB | vsizeMaxContiguous 270MB | residentFast 326MB | heapAllocated 96MB
16787
16:46:26     INFO -  704 INFO TEST-OK | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_network_messages_expand.js | took 90413ms
16788
16:46:26     INFO -  GECKO(4020) | ++DOCSHELL 0FCD3800 == 10 [pid = 4020] [id = {a5cd64e6-2a78-4247-80b9-1699c326d4cf}]
16789
16:46:26     INFO -  GECKO(4020) | ++DOMWINDOW == 28 (00AF3820) [pid = 4020] [serial = 1008] [outer = 00000000]
16790
16:46:26     INFO -  GECKO(4020) | ++DOMWINDOW == 29 (0FCD6000) [pid = 4020] [serial = 1009] [outer = 00AF3820]
16791
16:46:26     INFO -  705 INFO checking window state
:gbrins Can you please take a look?
Flags: needinfo?(bgrinstead)
Whiteboard: [stockwell unknown] → [stockwell needswork]
Comment hidden (Intermittent Failures Robot)
(Assignee)

Comment 15

a year ago
It looks like this test is doing a lot of work (including network requests that are intentionally slowed down for testing). Worth checking to see if requesting a longer timeout fixes the problem: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c638d4ad636310ec9ec387a6a02830b6e15d6fee
(Assignee)

Comment 16

a year ago
How many retriggers should I do on a Linux 64 debug run to be confident this is fixed?  I have about 20 green runs on dt6 with the longer timeout for this test requested: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c638d4ad636310ec9ec387a6a02830b6e15d6fee&selectedJob=154830118.
Flags: needinfo?(bgrinstead) → needinfo?(nerli)
Comment hidden (Intermittent Failures Robot)
Looks like is fixed now.
Thanks,
Flags: needinfo?(odvarko)
Flags: needinfo?(nerli)
(Assignee)

Updated

a year ago
Attachment #8941114 - Flags: review?(odvarko) → review?(bgrinstead)
(Assignee)

Comment 20

a year ago
mozreview-review
Comment on attachment 8941114 [details]
Bug 1398904 - Request a longer timeout for browser_webconsole_network_messages_expand.js;

https://reviewboard.mozilla.org/r/211214/#review217258

Going to land this since it is test only and fixes a pretty frequent intermittent
Attachment #8941114 - Flags: review?(bgrinstead) → review+

Comment 21

a year ago
Pushed by bgrinstead@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ac7f70f6635a
Request a longer timeout for browser_webconsole_network_messages_expand.js;r=bgrins
Comment hidden (Intermittent Failures Robot)

Comment 23

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/ac7f70f6635a
Status: REOPENED → RESOLVED
Last Resolved: a year agoa year ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 59
Whiteboard: [stockwell needswork] → [stockwell fixed:timing]
Comment hidden (Intermittent Failures Robot)

Updated

10 months ago
Product: Firefox → DevTools
Assignee: nobody → bgrinstead
You need to log in before you can comment on or make changes to this bug.