1428014 - Intermittent devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js | A promise chain failed to handle a rejection: 'prototype' active request packet to 'server1.conn43.child1/obj39'

Status: RESOLVED FIXED

(DevTools :: Console, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: ebalazs [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=154057727&repo=autoland

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

Comment 1

[Intermittent Failures Robot]

18 failures in 119 pushes (0.151 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 7
* autoland: 7
* mozilla-central: 3
* try: 1

Platform breakdown:
* linux64: 6
* windows10-64: 4
* linux64-stylo-disabled: 4
* osx-10-10: 2
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428014&startday=2018-01-05&endday=2018-01-05&tree=all

Comment 2

[Noemi Erli[:noemi_erli]]

There are 39 failures since this ticket was created (2 days).
Platforms: Linux opt, LinuxX64 most of them debug; but also one opt, asan and pgo, linux64-ccov opt, linux64-stylo-disabled debug,OS X 10.10 opt/ debug, Windows 7 opt/ debug, windows10-64 debug and windows10-64-ccov debug.
Recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=154539350
Relevant part of the log:
 INFO -  451 INFO TEST-START | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js
16083
12:30:21     INFO -  GECKO(5344) | ++DOCSHELL 0000026F1C904000 == 2 [pid = 6796] [id = {17965eb3-a9b7-4539-a686-bdd9711b61a6}]
16084
12:30:21     INFO -  GECKO(5344) | ++DOMWINDOW == 3 (0000026F19FC7850) [pid = 6796] [serial = 69] [outer = 0000000000000000]
16085
12:30:21     INFO -  GECKO(5344) | ++DOMWINDOW == 4 (0000026F1CE37C00) [pid = 6796] [serial = 70] [outer = 0000026F19FC7850]
16086
12:30:21     INFO -  GECKO(5344) | ++DOMWINDOW == 5 (0000026F1EF0D800) [pid = 6796] [serial = 71] [outer = 0000026F19FC7850]
16087
12:30:21     INFO -  GECKO(5344) | --DOCSHELL 000001DB35131000 == 0 [pid = 3848] [id = {6af98334-04dc-49b7-a73a-9607620b1311}]
16088
12:30:21     INFO -  GECKO(5344) | --DOMWINDOW == 4 (000001DB35A1C800) [pid = 3848] [serial = 95] [outer = 0000000000000000] [url = about:blank]
16089
12:30:21     INFO -  GECKO(5344) | --DOMWINDOW == 3 (000001DB36A33C00) [pid = 3848] [serial = 96] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/webconsole/new-console-output/test/mochitest/test-click-function-to-source.html]
16090
12:30:21     INFO -  GECKO(5344) | --DOMWINDOW == 2 (000001DB35A11000) [pid = 3848] [serial = 98] [outer = 0000000000000000] [url = about:blank]
16091
12:30:22     INFO -  GECKO(5344) | ++DOCSHELL 000002974AF7E000 == 16 [pid = 5344] [id = {932edc31-341f-41f8-84bb-9c7b6d60c055}]
16092
12:30:22     INFO -  GECKO(5344) | ++DOMWINDOW == 59 (00000297502BC080) [pid = 5344] [serial = 285] [outer = 0000000000000000]
16093
12:30:22     INFO -  GECKO(5344) | ++DOMWINDOW == 60 (000002974B419000) [pid = 5344] [serial = 286] [outer = 00000297502BC080]
16094
12:30:22     INFO -  GECKO(5344) | ++DOMWINDOW == 61 (000002974B76D000) [pid = 5344] [serial = 287] [outer = 00000297502BC080]
16095
12:30:22     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004001: file z:/build/build/src/dom/xul/nsXULPrototypeCache.cpp, line 352
16096
12:30:23     INFO -  GECKO(5344) | ++DOCSHELL 00000297502A3800 == 17 [pid = 5344] [id = {d1959a0e-5e9f-4c3b-8a8a-6d6e832cba9d}]
16097
12:30:23     INFO -  GECKO(5344) | ++DOMWINDOW == 62 (00000297502BC840) [pid = 5344] [serial = 288] [outer = 0000000000000000]
16098
12:30:23     INFO -  GECKO(5344) | ++DOMWINDOW == 63 (000002975DA5E800) [pid = 5344] [serial = 289] [outer = 00000297502BC840]
16099
12:30:24     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/layout/style/Loader.cpp, line 2398
16100
12:30:24     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/layout/style/Loader.cpp, line 2090
16101
12:30:24     INFO -  GECKO(5344) | --DOMWINDOW == 1 (000001DB32CB5470) [pid = 3848] [serial = 97] [outer = 0000000000000000] [url = data:text/html;charset=utf8,Clickable%20URLS]
16102
12:30:24     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: Forced to copy ObserverTable due to nested notifications: file z:/build/build/src/image/ProgressTracker.h, line 87
16103
12:30:25     INFO -  GECKO(5344) | --DOMWINDOW == 5 (0000020FD372E400) [pid = 5332] [serial = 50] [outer = 0000000000000000] [url = about:blank]
16104
12:30:25     INFO -  GECKO(5344) | --DOCSHELL 0000020FCBB5A000 == 1 [pid = 5332] [id = {f7c0dbbc-c80e-4ee5-837b-ba6bbd497190}]
16105
12:30:27     INFO -  GECKO(5344) | --DOMWINDOW == 4 (0000020FD372E800) [pid = 5332] [serial = 52] [outer = 0000000000000000] [url = about:blank]
16106
12:30:27     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: ENSURE_TRUE(weakFrame.IsAlive()) failed: file z:/build/build/src/layout/xul/nsXULPopupManager.cpp, line 1178
16107
12:30:28     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: ENSURE_TRUE(weakFrame.IsAlive()) failed: file z:/build/build/src/layout/xul/nsXULPopupManager.cpp, line 1178
16108
12:30:28     INFO -  GECKO(5344) | --DOMWINDOW == 0 (000001DB35A1EC00) [pid = 3848] [serial = 99] [outer = 0000000000000000] [url = data:text/html;charset=utf8,Clickable%20URLS]
16109
12:30:29     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: ENSURE_TRUE(weakFrame.IsAlive()) failed: file z:/build/build/src/layout/xul/nsXULPopupManager.cpp, line 1178
16110
12:30:30     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: ENSURE_TRUE(weakFrame.IsAlive()) failed: file z:/build/build/src/layout/xul/nsXULPopupManager.cpp, line 1178
16111
12:30:30     INFO -  GECKO(5344) | --DOCSHELL 0000026F14A4F000 == 1 [pid = 6796] [id = {fab095ec-e0a0-4997-9b92-7fd8a93fd0c9}]
16112
12:30:30     INFO -  GECKO(5344) | --DOMWINDOW == 4 (0000026F19FC7470) [pid = 6796] [serial = 67] [outer = 0000000000000000] [url = about:blank]
16113
12:30:30     INFO -  GECKO(5344) | [Parent 5344, Main Thread] WARNING: ENSURE_TRUE(weakFrame.IsAlive()) failed: file z:/build/build/src/layout/xul/nsXULPopupManager.cpp, line 1178
16114
12:30:31     INFO -  GECKO(5344) | ++DOMWINDOW == 64 (000002975DA64400) [pid = 5344] [serial = 290] [outer = 00000297502BC080]
16115
12:30:31     INFO -  TEST-INFO | started process screenshot
16116
12:30:31     INFO -  TEST-INFO | screenshot: exit 0
16117
12:30:31     INFO -  Buffered messages logged at 12:30:21
16118
12:30:31     INFO -  452 INFO Entering test bound
16119
12:30:31     INFO -  453 INFO Adding a new tab with URL: data:text/html;charset=utf8,
16120
12:30:31     INFO -  454 INFO Tab added and finished loading
16121
12:30:31     INFO -  455 INFO Opening the toolbox
16122
12:30:31     INFO -  Buffered messages logged at 12:30:24
16123
12:30:31     INFO -  456 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;"}]
16124
12:30:31     INFO -  Buffered messages logged at 12:30:26
16125
12:30:31     INFO -  457 INFO Toolbox opened and focused
16126
12:30:31     INFO -  Buffered messages logged at 12:30:27
16127
12:30:31     INFO -  458 INFO Matched a message with text: "Object", all messages received.
16128
12:30:31     INFO -  459 INFO Waiting for event: 'popuphidden' on [object XULElement].
16129
12:30:31     INFO -  460 INFO Got event: 'popuphidden' on [object XULElement].
16130
12:30:31     INFO -  461 INFO Click the clear console button
16131
12:30:31     INFO -  462 INFO TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js | Sidebar hidden after clear console button clicked -
16132
12:30:31     INFO -  463 INFO Matched a message with text: "Object", all messages received.
16133
12:30:31     INFO -  Buffered messages logged at 12:30:28
16134
12:30:31     INFO -  464 INFO Waiting for event: 'popuphidden' on [object XULElement].
16135
12:30:31     INFO -  465 INFO Got event: 'popuphidden' on [object XULElement].
16136
12:30:31     INFO -  466 INFO Send a console.clear()
16137
12:30:31     INFO -  467 INFO Matched a message with text: "Console was cleared", all messages received.
16138
12:30:31     INFO -  468 INFO TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js | Sidebar hidden after console.clear() -
16139
12:30:31     INFO -  469 INFO Matched a message with text: "Object", all messages received.
16140
12:30:31     INFO -  Buffered messages logged at 12:30:29
16141
12:30:31     INFO -  470 INFO Waiting for event: 'popuphidden' on [object XULElement].
16142
12:30:31     INFO -  471 INFO Got event: 'popuphidden' on [object XULElement].
16143
12:30:31     INFO -  472 INFO Send ctrl-l to clear console
16144
12:30:31     INFO -  473 INFO Synthesizing key shortcut: Ctrl+Shift+L
16145
12:30:31     INFO -  474 INFO TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js | Sidebar hidden after ctrl-l -
16146
12:30:31     INFO -  475 INFO Matched a message with text: "Object", all messages received.
16147
12:30:31     INFO -  Buffered messages logged at 12:30:30
16148
12:30:31     INFO -  476 INFO Waiting for event: 'popuphidden' on [object XULElement].
16149
12:30:31     INFO -  477 INFO Got event: 'popuphidden' on [object XULElement].
16150
12:30:31     INFO -  478 INFO Click the close button
16151
12:30:31     INFO -  479 INFO TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js | Sidebar hidden after clicking on close button -
16152
12:30:31     INFO -  480 INFO Matched a message with text: "Object", all messages received.
16153
12:30:31     INFO -  481 INFO Waiting for event: 'popuphidden' on [object XULElement].
16154
12:30:31     INFO -  482 INFO Got event: 'popuphidden' on [object XULElement].
16155
12:30:31     INFO -  483 INFO Send escape to hide sidebar
16156
12:30:31     INFO -  484 INFO TEST-PASS | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js | Sidebar hidden after sending esc -
16157
12:30:31     INFO -  485 INFO Leaving test bound
16158
12:30:31     INFO -  Buffered messages logged at 12:30:31
16159
12:30:31     INFO -  486 INFO Removing tab.
16160
12:30:31     INFO -  487 INFO Waiting for event: 'TabClose' on [object XULElement].
16161
12:30:31     INFO -  488 INFO Got event: 'TabClose' on [object XULElement].
16162
12:30:31     INFO -  489 INFO Tab removed and finished closing
16163
12:30:31     INFO -  Buffered messages finished
16164
12:30:31    ERROR -  490 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_close_sidebar.js | A promise chain failed to handle a rejection: 'prototype' pending request packet to 'server1.conn43.child1/obj39' can't be sent as the connection just closed. - stack: null
16165
12:30:31     INFO -  Rejection date: Sat Jan 06 2018 12:30:31 GMT+0000 (Coordinated Universal Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 253
16166
12:30:31     INFO -  Stack trace:
16167
12:30:31     INFO -      resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:253
16168
12:30:31     INFO -      chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:703
16169
12:30:31     INFO -      testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1361:11
16170
12:30:31     INFO -      run@chrome://mochikit/content/browser-test.js:1298:9

Comment 3

[Intermittent Failures Robot]

51 failures in 462 pushes (0.11 failures/push) were associated with this bug in the last 7 days. 

This is the #13 most frequent failure this week.  

** 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: 20
* autoland: 15
* mozilla-inbound: 13
* try: 3

Platform breakdown:
* linux64: 19
* linux64-stylo-disabled: 9
* windows10-64: 6
* linux64-ccov: 5
* windows7-32: 4
* windows10-64-ccov: 3
* osx-10-10: 3
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428014&startday=2018-01-01&endday=2018-01-07&tree=all

Comment 4

[Nicolas Chevobbe [:nchevobbe]]

I think we get this because we end the test while the request to load the properties of the object in the sidebar is not finished.
We can wait for this request to be done before closing the sidebar

Comment 5

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1428014 - Fix intermittent on browser_webconsole_close_sidebar.js; .

The test was failing because it still had pending request to the server while shutting
down the toolbox. This request was probably the one to retrieve the properties of the
object we put in the sidebar.
By waiting the object properties to be fully loaded when opening the sidebar, we should
make the intermittent go away.

Review commit: https://reviewboard.mozilla.org/r/210892/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/210892/

Comment 6

[Brian Grinstead [:bgrins]]

Comment on attachment 8940642 [details]
Bug 1428014 - Fix intermittent on browser_webconsole_close_sidebar.js; .

https://reviewboard.mozilla.org/r/210892/#review216778

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a9c97c2aa4b9
Fix intermittent on browser_webconsole_close_sidebar.js; r=bgrins.

Comment 8

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/a9c97c2aa4b9

Comment 10

[Intermittent Failures Robot]

17 failures in 788 pushes (0.022 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 8
* mozilla-inbound: 4
* try: 3
* mozilla-central: 2

Platform breakdown:
* linux64-stylo-disabled: 7
* linux64: 6
* windows7-32: 1
* windows10-64-ccov: 1
* windows10-64: 1
* linux64-ccov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428014&startday=2018-01-08&endday=2018-01-14&tree=all

Comment 11

[Intermittent Failures Robot]

1 failures in 735 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 1

Platform breakdown:
* windows10-64-ccov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1428014&startday=2018-01-29&endday=2018-02-04&tree=all