Closed Bug 1689351 Opened 3 years ago Closed 3 years ago

Intermittent devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | Test timed out -

Categories

(DevTools :: Console, defect, P5)

defect

Tracking

(firefox-esr91 fixed, firefox91 wontfix, firefox92 fixed)

RESOLVED FIXED
92 Branch
Tracking Status
firefox-esr91 --- fixed
firefox91 --- wontfix
firefox92 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=328086826&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SDVC-V7qRwaDlCgs9lr27w/runs/0/artifacts/public/logs/live_backing.log


INFO - TEST-START | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js
[task 2021-01-28T13:12:48.845Z] 13:12:48     INFO - GECKO(10533) | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-01-28T13:12:48.845Z] 13:12:48     INFO - GECKO(10533) | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-01-28T13:13:33.282Z] 13:13:33     INFO - TEST-INFO | started process screentopng
[task 2021-01-28T13:13:33.512Z] 13:13:33     INFO - TEST-INFO | screentopng: exit 0
[task 2021-01-28T13:13:33.512Z] 13:13:33     INFO - Buffered messages logged at 13:12:48
[task 2021-01-28T13:13:33.513Z] 13:13:33     INFO - Entering test bound 
[task 2021-01-28T13:13:33.514Z] 13:13:33     INFO - Console message: [JavaScript Warning: "The Web Console logging API (console.log, console.info, console.warn, console.error) has been disabled by a script on this page."]
[task 2021-01-28T13:13:33.514Z] 13:13:33     INFO - Buffered messages finished
[task 2021-01-28T13:13:33.515Z] 13:13:33     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | Test timed out - 
[task 2021-01-28T13:13:33.516Z] 13:13:33     INFO - Clear the browser console output
[task 2021-01-28T13:13:33.517Z] 13:13:33     INFO - GECKO(10533) | JavaScript error: resource://devtools/shared/protocol/Front.js, line 99: Error: Connection closed, pending request to server3.conn0.contentProcess10614/obj5, type release failed
[task 2021-01-28T13:13:33.518Z] 13:13:33     INFO - GECKO(10533) | Request stack:
[task 2021-01-28T13:13:33.520Z] 13:13:33     INFO - GECKO(10533) | request@resource://devtools/shared/protocol/Front.js:288:14
[task 2021-01-28T13:13:33.521Z] 13:13:33     INFO - GECKO(10533) | generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:46:19
[task 2021-01-28T13:13:33.521Z] 13:13:33     INFO - GECKO(10533) | generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:62:19
[task 2021-01-28T13:13:33.522Z] 13:13:33     INFO - GECKO(10533) | enableActorReleaser/</</releaseActorsEnhancer/<@resource://devtools/client/webconsole/enhancers/actor-releaser.js:46:33
[task 2021-01-28T13:13:33.522Z] 13:13:33     INFO - GECKO(10533) | releaseActorsEnhancer@resource://devtools/client/webconsole/enhancers/actor-releaser.js:36:40
[task 2021-01-28T13:13:33.523Z] 13:13:33     INFO - GECKO(10533) | batchingReducer@resource://devtools/client/webconsole/enhancers/batching.js:21:18
[task 2021-01-28T13:13:33.523Z] 13:13:33     INFO - GECKO(10533) | messagesCacheClearingEnhancer@resource://devtools/client/webconsole/enhancers/message-cache-clearing.js:17:15
[task 2021-01-28T13:13:33.529Z] 13:13:33     INFO - GECKO(10533) | ensureErrorReportingEnhancer@resource://devtools/client/webconsole/enhancers/css-error-reporting.js:21:15
[task 2021-01-28T13:13:33.529Z] 13:13:33     INFO - GECKO(10533) | dispatch@resource://devtools/client/shared/vendor/redux.js:256:22
[task 2021-01-28T13:13:33.530Z] 13:13:33     INFO - GECKO(10533) | eventTelemetryMiddleware/</<@resource://devtools/client/webconsole/middleware/event-telemetry.js:25:21
[task 2021-01-28T13:13:33.531Z] 13:13:33     INFO - GECKO(10533) | historyPersistenceMiddleware/</<@resource://devtools/client/webconsole/middleware/history-persistence.js:37:21
[task 2021-01-28T13:13:33.532Z] 13:13:33     INFO - GECKO(10533) | thunk/</</<@resource://devtools/client/shared/redux/middleware/thunk.js:18:11
[task 2021-01-28T13:13:33.532Z] 13:13:33     INFO - GECKO(10533) | ignore/</<@resource://devtools/client/shared/redux/middleware/ignore.js:31:12
[task 2021-01-28T13:13:33.536Z] 13:13:33     INFO - GECKO(10533) | createPerformanceMarkerMiddleware/</</<@resource://devtools/client/shared/redux/middleware/performance-marker.js:50:28
[task 2021-01-28T13:13:33.537Z] 13:13:33     INFO - GECKO(10533) | dispatchMessagesClear@resource://devtools/client/webconsole/webconsole-wrapper.js:160:11
[task 2021-01-28T13:13:33.538Z] 13:13:33     INFO - GECKO(10533) | clearOutput@resource://devtools/client/webconsole/webconsole-ui.js:247:20
[task 2021-01-28T13:13:33.538Z] 13:13:33     INFO - GECKO(10533) | safeCloseBrowserConsole@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:342:8
[task 2021-01-28T13:13:33.539Z] 13:13:33     INFO - GECKO(10533) | cleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:299:11
[task 2021-01-28T13:13:33.539Z] 13:13:33     INFO - GECKO(10533) | nextTest@chrome://mochikit/content/browser-test.js:571:35
[task 2021-01-28T13:13:33.540Z] 13:13:33     INFO - GECKO(10533) | async*timeoutFn@chrome://mochikit/content/browser-test.js:1214:18
[task 2021-01-28T13:13:33.541Z] 13:13:33     INFO - GECKO(10533) | setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1161:80
[task 2021-01-28T13:13:33.542Z] 13:13:33     INFO - GECKO(10533) | nextTest/<@chrome://mochikit/content/browser-test.js:948:14
[task 2021-01-28T13:13:33.543Z] 13:13:33     INFO - GECKO(10533) | SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1037:23
[task 2021-01-28T13:13:33.553Z] 13:13:33     INFO - Console message: [JavaScript Error: "Error: Connection closed, pending request to server3.conn0.contentProcess10614/obj5, type release failed
INFO - Request stack:
[task 2021-01-28T13:13:33.555Z] 13:13:33     INFO - request@resource://devtools/shared/protocol/Front.js:288:14
[task 2021-01-28T13:13:33.556Z] 13:13:33     INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:46:19
[task 2021-01-28T13:13:33.556Z] 13:13:33     INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:62:19
[task 2021-01-28T13:13:33.556Z] 13:13:33     INFO - enableActorReleaser/</</releaseActorsEnhancer/<@resource://devtools/client/webconsole/enhancers/actor-releaser.js:46:33
[task 2021-01-28T13:13:33.557Z] 13:13:33     INFO - releaseActorsEnhancer@resource://devtools/client/webconsole/enhancers/actor-releaser.js:36:40
[task 2021-01-28T13:13:33.558Z] 13:13:33     INFO - batchingReducer@resource://devtools/client/webconsole/enhancers/batching.js:21:18
[task 2021-01-28T13:13:33.558Z] 13:13:33     INFO - messagesCacheClearingEnhancer@resource://devtools/client/webconsole/enhancers/message-cache-clearing.js:17:15
[task 2021-01-28T13:13:33.559Z] 13:13:33     INFO - ensureErrorReportingEnhancer@resource://devtools/client/webconsole/enhancers/css-error-reporting.js:21:15
[task 2021-01-28T13:13:33.559Z] 13:13:33     INFO - dispatch@resource://devtools/client/shared/vendor/redux.js:256:22
[task 2021-01-28T13:13:33.559Z] 13:13:33     INFO - eventTelemetryMiddleware/</<@resource://devtools/client/webconsole/middleware/event-telemetry.js:25:21
[task 2021-01-28T13:13:33.560Z] 13:13:33     INFO - historyPersistenceMiddleware/</<@resource://devtools/client/webconsole/middleware/history-persistence.js:37:21
[task 2021-01-28T13:13:33.560Z] 13:13:33     INFO - thunk/</</<@resource://devtools/client/shared/redux/middleware/thunk.js:18:11
[task 2021-01-28T13:13:33.560Z] 13:13:33     INFO - ignore/</<@resource://devtools/client/shared/redux/middleware/ignore.js:31:12
[task 2021-01-28T13:13:33.561Z] 13:13:33     INFO - createPerformanceMarkerMiddleware/</</<@resource://devtools/client/shared/redux/middleware/performance-marker.js:50:28
[task 2021-01-28T13:13:33.562Z] 13:13:33     INFO - dispatchMessagesClear@resource://devtools/client/webconsole/webconsole-wrapper.js:160:11
[task 2021-01-28T13:13:33.562Z] 13:13:33     INFO - clearOutput@resource://devtools/client/webconsole/webconsole-ui.js:247:20
[task 2021-01-28T13:13:33.562Z] 13:13:33     INFO - safeCloseBrowserConsole@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:342:8
[task 2021-01-28T13:13:33.563Z] 13:13:33     INFO - cleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:299:11
[task 2021-01-28T13:13:33.563Z] 13:13:33     INFO - nextTest@chrome://mochikit/content/browser-test.js:571:35
[task 2021-01-28T13:13:33.564Z] 13:13:33     INFO - async*timeoutFn@chrome://mochikit/content/browser-test.js:1214:18
[task 2021-01-28T13:13:33.564Z] 13:13:33     INFO - setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1161:80
[task 2021-01-28T13:13:33.564Z] 13:13:33     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:948:14
[task 2021-01-28T13:13:33.564Z] 13:13:33     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1037:23
[task 2021-01-28T13:13:33.565Z] 13:13:33     INFO - " {file: "resource://devtools/shared/protocol/Front.js" line: 99}]
[task 2021-01-28T13:13:33.565Z] 13:13:33     INFO - Browser console cleared
[task 2021-01-28T13:13:33.566Z] 13:13:33     INFO - Wait for all Browser Console targets to be attached
[task 2021-01-28T13:13:33.566Z] 13:13:33     INFO - Waiting 1 seconds.
[task 2021-01-28T13:13:33.567Z] 13:13:33     INFO - Close the Browser Console
[task 2021-01-28T13:13:33.567Z] 13:13:33     INFO - Browser Console closed
[task 2021-01-28T13:13:33.568Z] 13:13:33     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-01-28T13:13:33.583Z] 13:13:33     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | Uncaught exception received from previously timed out test - at resource://devtools/shared/protocol/Front.js:99 - Error: Connection closed, pending request to server3.conn0.watcher25, type watchTargets failed
[task 2021-01-28T13:13:33.583Z] 13:13:33     INFO - 
INFO - Request stack:
[task 2021-01-28T13:13:33.583Z] 13:13:33     INFO - request@resource://devtools/shared/protocol/Front.js:288:14
[task 2021-01-28T13:13:33.584Z] 13:13:33     INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:46:19
[task 2021-01-28T13:13:33.584Z] 13:13:33     INFO - startListening@resource://devtools/shared/resources/target-list.js:313:33
[task 2021-01-28T13:13:33.585Z] 13:13:33     INFO - async*init/this._bcInitializer<@resource://devtools/client/webconsole/browser-console.js:90:29
[task 2021-01-28T13:13:33.585Z] 13:13:33     INFO - async*init@resource://devtools/client/webconsole/browser-console.js:96:7
[task 2021-01-28T13:13:33.585Z] 13:13:33     INFO - openBrowserConsole@resource://devtools/client/webconsole/browser-console-manager.js:67:15
[task 2021-01-28T13:13:33.585Z] 13:13:33     INFO - toggleBrowserConsole/this._browserConsoleInitializing<@resource://devtools/client/webconsole/browser-console-manager.js:107:41
[task 2021-01-28T13:13:33.585Z] 13:13:33     INFO - async*toggleBrowserConsole@resource://devtools/client/webconsole/browser-console-manager.js:109:7
[task 2021-01-28T13:13:33.586Z] 13:13:33     INFO - @chrome://mochitests/content/browser/devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js:16:43
[task 2021-01-28T13:13:33.586Z] 13:13:33     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1088:34
[task 2021-01-28T13:13:33.586Z] 13:13:33     INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1128:11
[task 2021-01-28T13:13:33.587Z] 13:13:33     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:948:14
[task 2021-01-28T13:13:33.587Z] 13:13:33     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1037:23
[task 2021-01-28T13:13:33.587Z] 13:13:33     INFO - 
[task 2021-01-28T13:13:33.588Z] 13:13:33     INFO - Stack trace:
[task 2021-01-28T13:13:33.588Z] 13:13:33     INFO - baseFrontClassDestroy@resource://devtools/shared/protocol/Front.js:99:23
[task 2021-01-28T13:13:33.588Z] 13:13:33     INFO - destroy@resource://devtools/shared/protocol/Front.js:67:10
[task 2021-01-28T13:13:33.589Z] 13:13:33     INFO - destroy@resource://devtools/shared/protocol/Pool.js:196:17
[task 2021-01-28T13:13:33.589Z] 13:13:33     INFO - baseFrontClassDestroy@resource://devtools/shared/protocol/Front.js:103:13
[task 2021-01-28T13:13:33.590Z] 13:13:33     INFO - destroy@resource://devtools/shared/protocol/Front.js:67:10
[task 2021-01-28T13:13:33.590Z] 13:13:33     INFO - destroy@resource://devtools/client/fronts/descriptors/process.js:107:11
[task 2021-01-28T13:13:33.590Z] 13:13:33     INFO - destroy@resource://devtools/shared/protocol/Pool.js:196:17
[task 2021-01-28T13:13:33.591Z] 13:13:33     INFO - baseFrontClassDestroy@resource://devtools/shared/protocol/Front.js:103:13
[task 2021-01-28T13:13:33.591Z] 13:13:33     INFO - purgeRequests@resource://devtools/client/devtools-client.js:690:15
[task 2021-01-28T13:13:33.592Z] 13:13:33     INFO - onClosed@resource://devtools/client/devtools-client.js:605:10
[task 2021-01-28T13:13:33.592Z] 13:13:33     INFO - close@resource://devtools/shared/transport/local-transport.js:170:22
[task 2021-01-28T13:13:33.592Z] 13:13:33     INFO - close@resource://devtools/shared/transport/local-transport.js:165:13
[task 2021-01-28T13:13:33.593Z] 13:13:33     INFO - close@resource://devtools/shared/transport/local-transport.js:165:13
[task 2021-01-28T13:13:33.593Z] 13:13:33     INFO - cleanup@resource://devtools/client/devtools-client.js:123:27
[task 2021-01-28T13:13:33.594Z] 13:13:33     INFO - close/promise<@resource://devtools/client/devtools-client.js:139:7
[task 2021-01-28T13:13:33.594Z] 13:13:33     INFO - close@resource://devtools/client/devtools-client.js:116:21
[task 2021-01-28T13:13:33.595Z] 13:13:33     INFO - closeBrowserConsole@resource://devtools/client/webconsole/browser-console-manager.js:82:32
[task 2021-01-28T13:13:33.596Z] 13:13:33     INFO - GECKO(10533) | console.warn: "IGNORED REDUX ACTION:" "AUTOCOMPLETE_CLEAR"
[task 2021-01-28T13:13:33.596Z] 13:13:33     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | The main process DevToolsServer has no pending connection when the test ends - 
[task 2021-01-28T13:13:33.597Z] 13:13:33     INFO - GECKO(10533) | MEMORY STAT | vsize 3031MB | residentFast 331MB | heapAllocated 106MB
[task 2021-01-28T13:13:33.598Z] 13:13:33     INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | took 45229ms
[task 2021-01-28T13:13:33.599Z] 13:13:33     INFO - checking window state
[task 2021-01-28T13:13:33.599Z] 13:13:33     INFO - TEST-START | devtools/client/webconsole/test/browser/browser_console_clear_cache.js```
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Hi Nicolas, there seems to be a rise in frequent devtools failures on beta since the merge on 12th July. Some of the frequent bugs are:

Could you have a look over what's happening here? Thank you.

Flags: needinfo?(nchevobbe)

not sure what's happening for all the different bugs.
Looking at the screenshot for this specific issue, we're missing a message we should get from Cu.reportError, but the issue is the same on beta and on try.
This probably is related to some timing, as we're using execute just after opening the console and maybe some things are not ready yet.
I'll try to investigate

Flags: needinfo?(nchevobbe)

Focus the browser console before evaluating the expression.

Assignee: nobody → nchevobbe
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/74727280ae7c
[devtools] Fix browser_console_chrome_context_message.js intermittent. r=bomsy.
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 92 Branch

Failure log from mozilla-beta: https://treeherder.mozilla.org/logviewer?job_id=345890140&repo=mozilla-beta&lineNumber=8503

[task 2021-07-21T13:36:18.031Z] 13:36:18     INFO - TEST-START | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js
[task 2021-07-21T13:36:18.943Z] 13:36:18     INFO - GECKO(3910) | must wait for focus
[task 2021-07-21T13:37:03.046Z] 13:37:03     INFO - TEST-INFO | started process screentopng
[task 2021-07-21T13:37:03.333Z] 13:37:03     INFO - TEST-INFO | screentopng: exit 0
[task 2021-07-21T13:37:03.334Z] 13:37:03     INFO - Buffered messages logged at 13:36:18
[task 2021-07-21T13:37:03.335Z] 13:37:03     INFO - Entering test bound 
[task 2021-07-21T13:37:03.335Z] 13:37:03     INFO - Adding a new tab with URL: data:text/html,<script>console.log("hello from content")</script>
[task 2021-07-21T13:37:03.336Z] 13:37:03     INFO - Console message: [JavaScript Warning: "The Web Console logging API (console.log, console.info, console.warn, console.error) has been disabled by a script on this page."]
[task 2021-07-21T13:37:03.336Z] 13:37:03     INFO - Tab added and finished loading
[task 2021-07-21T13:37:03.336Z] 13:37:03     INFO - Opening the toolbox
[task 2021-07-21T13:37:03.336Z] 13:37:03     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html,<script>console.log("hello from content")</script>" line: 0}]
[task 2021-07-21T13:37:03.337Z] 13:37:03     INFO - Buffered messages finished
[task 2021-07-21T13:37:03.340Z] 13:37:03     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | Test timed out - 
[task 2021-07-21T13:37:03.340Z] 13:37:03     INFO - Clear the browser console output
[task 2021-07-21T13:37:03.340Z] 13:37:03     INFO - Browser console cleared
[task 2021-07-21T13:37:03.340Z] 13:37:03     INFO - Wait for all Browser Console targets to be attached
[task 2021-07-21T13:37:03.344Z] 13:37:03     INFO - Waiting 1 seconds.
[task 2021-07-21T13:37:03.344Z] 13:37:03     INFO - Close the Browser Console
[task 2021-07-21T13:37:03.344Z] 13:37:03     INFO - Browser Console closed
[task 2021-07-21T13:37:03.344Z] 13:37:03     INFO - Removing tab.
[task 2021-07-21T13:37:03.345Z] 13:37:03     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2021-07-21T13:37:03.345Z] 13:37:03     INFO - Got event: 'TabClose' on [object XULElement].
[task 2021-07-21T13:37:03.345Z] 13:37:03     INFO - GECKO(3910) | console.warn: "IGNORED REDUX ACTION:" "AUTOCOMPLETE_CLEAR"
[task 2021-07-21T13:37:03.345Z] 13:37:03     INFO - Tab removed and finished closing
[task 2021-07-21T13:37:03.345Z] 13:37:03     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | The main process DevToolsServer has no pending connection when the test ends - 
[task 2021-07-21T13:37:03.345Z] 13:37:03     INFO - GECKO(3910) | MEMORY STAT | vsize 2982MB | residentFast 356MB | heapAllocated 130MB
[task 2021-07-21T13:37:03.346Z] 13:37:03     INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_console_chrome_context_message.js | took 45259ms
[task 2021-07-21T13:37:03.346Z] 13:37:03     INFO - checking window state
[task 2021-07-21T13:37:03.349Z] 13:37:03     INFO - TEST-START | devtools/client/webconsole/test/browser/browser_console_clear_cache.js

This log from a central-as-beta simulation with central already containing the fix. Given this failure didn't affect central anyway, is the fix effective?

Flags: needinfo?(nchevobbe)
Regressions: 1723379
Flags: needinfo?(nchevobbe)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: