1806419 - Intermittent devtools/client/inspector/rules/test/browser_rules_color_scheme_simulation_bfcache.js | single tracking bug

Status: RESOLVED FIXED

(DevTools :: Inspector: Rules, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=400098835&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/cDGxlW6VRHq7gTKuYZtPIA/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/cDGxlW6VRHq7gTKuYZtPIA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2022-12-19T13:49:15.818Z] 13:49:15     INFO - TEST-PASS | devtools/client/inspector/rules/test/browser_rules_color_scheme_simulation_bfcache.js | color scheme simulation is disabled - 
[task 2022-12-19T13:49:15.818Z] 13:49:15     INFO - Buffered messages finished
[task 2022-12-19T13:49:15.819Z] 13:49:15     INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/rules/test/browser_rules_color_scheme_simulation_bfcache.js | A promise chain failed to handle a rejection: Connection closed, pending request to server0.conn0.windowGlobal21474836484/domwalker24, type getEmbedderElement failed
[task 2022-12-19T13:49:15.819Z] 13:49:15     INFO - 
[task 2022-12-19T13:49:15.819Z] 13:49:15     INFO - Request stack:
[task 2022-12-19T13:49:15.819Z] 13:49:15     INFO - request@resource://devtools/shared/protocol/Front.js:300:14
[task 2022-12-19T13:49:15.825Z] 13:49:15     INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:47:19
[task 2022-12-19T13:49:15.825Z] 13:49:15     INFO - reparentRemoteFrame@resource://devtools/client/fronts/walker.js:409:26
[task 2022-12-19T13:49:15.825Z] 13:49:15     INFO - async*_getWalker@resource://devtools/client/fronts/inspector.js:98:23
[task 2022-12-19T13:49:15.825Z] 13:49:15     INFO - async*initialize@resource://devtools/client/fronts/inspector.js:80:12
[task 2022-12-19T13:49:15.825Z] 13:49:15     INFO - async*manage@resource://devtools/shared/protocol/Front.js:146:19
[task 2022-12-19T13:49:15.825Z] 13:49:15     INFO - getFront@resource://devtools/shared/protocol/types.js:562:18
[task 2022-12-19T13:49:15.825Z] 13:49:15     INFO - getFront@resource://devtools/client/fronts/targets/target-mixin.js:343:15
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - _onTargetAvailable@resource://devtools/client/inspector/shared/walker-event-listener.js:63:46
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - _emit@resource://devtools/shared/event-emitter.js:242:32
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - emitAsync@resource://devtools/shared/event-emitter.js:190:25
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - emitAsync@resource://devtools/shared/event-emitter.js:334:25
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - _onTargetAvailable@resource://devtools/shared/commands/target/target-command.js:245:33
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - Async*_emit@resource://devtools/shared/event-emitter.js:242:32
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:186:18
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:330:18
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - _onTargetAvailable@resource://devtools/client/fronts/watcher.js:60:10
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - _emit@resource://devtools/shared/event-emitter.js:242:32
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:186:18
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:330:18
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - onPacket@resource://devtools/shared/protocol/Front.js:349:13
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - onPacket@resource://devtools/client/devtools-client.js:488:13
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - send/<@resource://devtools/shared/transport/local-transport.js:67:25
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:103:22
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - DevToolsUtils.executeSoon*exports.executeSoon@resource://devtools/shared/DevToolsUtils.js:52:21
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - send@resource://devtools/shared/transport/local-transport.js:55:21
[task 2022-12-19T13:49:15.826Z] 13:49:15     INFO - send@resource://devtools/server/devtools-server-connection.js:103:20
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - _sendEvent@resource://devtools/shared/protocol/Actor.js:72:15
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - initialize/<@resource://devtools/shared/protocol/Actor.js:46:16
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - _emit@resource://devtools/shared/event-emitter.js:242:32
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:186:18
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:330:18
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - notifyTargetAvailable@resource://devtools/server/actors/watcher.js:296:12
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - connectFromContent@resource://devtools/server/connectors/js-window-actor/DevToolsFrameParent.sys.mjs:154:13
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - receiveMessage@resource://devtools/server/connectors/js-window-actor/DevToolsFrameParent.sys.mjs:229:21
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - JSActor query*_createTargetActor@resource://devtools/server/connectors/js-window-actor/DevToolsFrameChild.sys.mjs:276:10
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - instantiate@resource://devtools/server/connectors/js-window-actor/DevToolsFrameChild.sys.mjs:157:14
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - handleEvent@resource://devtools/server/connectors/js-window-actor/DevToolsFrameChild.sys.mjs:557:12
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO -  - stack: baseFrontClassDestroy@resource://devtools/shared/protocol/Front.js:106:23
[task 2022-12-19T13:49:15.827Z] 13:49:15     INFO - destroy@resource://devtools/shared/protocol/Front.js:74:10
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/shared/protocol/Pool.js:211:17
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - baseFrontClassDestroy@resource://devtools/shared/protocol/Front.js:110:13
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/shared/protocol/Front.js:74:10
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/client/fronts/inspector.js:138:11
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - _destroyTarget@resource://devtools/client/fronts/targets/target-mixin.js:620:17
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - async*destroy@resource://devtools/client/fronts/targets/target-mixin.js:595:12
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/client/fronts/targets/window-global.js:159:27
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/shared/protocol/Pool.js:211:17
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - baseFrontClassDestroy@resource://devtools/shared/protocol/Front.js:110:13
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/shared/protocol/Front.js:74:10
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/shared/protocol/Pool.js:211:17
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - baseFrontClassDestroy@resource://devtools/shared/protocol/Front.js:110:13
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/shared/protocol/Front.js:74:10
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/client/fronts/descriptors/descriptor-mixin.js:55:19
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/client/fronts/descriptors/tab.js:101:11
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - _emit@resource://devtools/shared/event-emitter.js:242:32
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:186:18
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - emit@resource://devtools/shared/event-emitter.js:330:18
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/client/fronts/descriptors/tab.js:96:12
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - destroy@resource://devtools/shared/commands/index.js:88:31
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - _destroyToolbox/onceDestroyed</<@resource://devtools/client/framework/toolbox.js:4183:34
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - promise callback*_destroyToolbox/onceDestroyed<@resource://devtools/client/framework/toolbox.js:4144:12
[task 2022-12-19T13:49:15.828Z] 13:49:15     INFO - _destroyToolbox@resource://devtools/client/framework/toolbox.js:4140:27
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - destroy@resource://devtools/client/framework/toolbox.js:3989:10
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - testBfCacheNavigationAfterClosingDevTools@chrome://mochitests/content/browser/devtools/client/inspector/rules/test/browser_rules_color_scheme_simulation_bfcache.js:64:17
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - Async*handleTask@chrome://mochikit/content/browser-test.js:1037:26
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - _runTaskBasedTest@chrome://mochikit/content/browser-test.js:1109:18
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1244:14
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:1020:14
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1036:13
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - Rejection date: Mon Dec 19 2022 13:49:15 GMT+0000 (Greenwich Mean Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.sys.mjs :: assertNoUncaughtRejections :: line 266
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - Stack trace:
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - resource://testing-common/PromiseTestUtils.sys.mjs:assertNoUncaughtRejections:266
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - chrome://mochikit/content/browser-test.js:handleTask:1065
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1109
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1244
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1020
[task 2022-12-19T13:49:15.829Z] 13:49:15     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1036
[task 2022-12-19T13:49:15.830Z] 13:49:15     INFO - Leaving test bound testBfCacheNavigationAfterClosingDevTools
[task 2022-12-19T13:49:15.830Z] 13:49:15     INFO - Removing tab.
[task 2022-12-19T13:49:15.831Z] 13:49:15     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2022-12-19T13:49:15.831Z] 13:49:15     INFO - Got event: 'TabClose' on [object XULElement].
[task 2022-12-19T13:49:15.832Z] 13:49:15     INFO - Tab removed and finished closing
[task 2022-12-19T13:49:15.832Z] 13:49:15     INFO - Removing tab.
[task 2022-12-19T13:49:15.832Z] 13:49:15     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2022-12-19T13:49:15.833Z] 13:49:15     INFO - Got event: 'TabClose' on [object XULElement].
[task 2022-12-19T13:49:15.833Z] 13:49:15     INFO - Tab removed and finished closing
[task 2022-12-19T13:49:15.834Z] 13:49:15     INFO - TEST-PASS | devtools/client/inspector/rules/test/browser_rules_color_scheme_simulation_bfcache.js | The main process DevToolsServer has no pending connection when the test ends - 

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

:jdescottes, since you are the author of the regressor, bug 1805997, could you take a look?

For more information, please visit auto_nag documentation.

Comment 2

[Julian Descottes [:jdescottes]]

So the issue is with the walker-event-listener which reacts to onTargetAvailable, but which is not blocking any of the reload events we usually monitor https://searchfox.org/mozilla-central/rev/abcee8d2c97a5c8a1fbeaf84607ea427be72497a/devtools/client/inspector/shared/walker-event-listener.js#62-67

Several inspector-related helpers rely on it: the markupview, highlighters-overlay and style-change-tracker. So we have potentially 3 instances of this WalkerEventListener attempting to react to a new target while we are closing the toolbox. In this particular case, the test page contains an iframe and the issue comes from processing this iframe target in the WalkerEventListener.

We could either try/catch in the WalkerEventListener to avoid failures, or maybe expose a helper on target-commands in order to wait for specific targets to have been processed ... I'm not sure if we could (or should) make it a part of the "switched-target" event, ie that all frame targets owned by a toplevel target must have been processed by target command before we emit "switched-target". This sounds potentially complicated and error prone.

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1805997

Comment 4

[Julian Descottes [:jdescottes]]

Attachment: Bug 1806419 - [devtools] Add test helper to wait for a specific target and use it in bfcache color simulation test

See detailed comment on the bug for the investigation

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2b385a5f0881
[devtools] Add test helper to wait for a specific target and use it in bfcache color simulation test r=nchevobbe

Comment 6

[Marian-Vasile Laza]

Backed out changeset 2b385a5f0881 (Bug 1806419) for causing devtool failures on browser_rules_color_scheme_simulation_bfcache.js.
Backout link
Push with failures <--> dt3
Failure Log

Comment 7

[Julian Descottes [:jdescottes]]

Ah right, the no-eft version needs a different handling...

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3b0771dfb3f6
[devtools] Add test helper to wait for a specific target and use it in bfcache color simulation test r=nchevobbe

Comment 9

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/3b0771dfb3f6

Comment 10

[Intermittent Failures Robot]

21 failures in 2999 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 17
• try: 2
• mozilla-central: 2

Platform and build breakdown:

• windows10-32-2004-qr: 2
  • opt: 2
• windows10-64-2004-qr: 7
  • opt: 7
• linux1804-64-qr: 4
  • opt: 4
• linux1804-64-shippable-qr: 2
  • opt: 2
• windows10-64-2004-asan-qr: 2
  • opt: 2
• linux1804-64-asan-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1806419&startday=2022-12-19&endday=2022-12-25&tree=all