1601318 - Intermittent devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js | Test timed out -

Status: RESOLVED INCOMPLETE

(DevTools :: about:debugging, defect, P5)

Description

[Treeherder Bug Filer]

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

---

task 2019-12-04T14:55:12.463Z] 14:55:12 INFO - TEST-PASS | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js | Tooltip should be hidden -
[task 2019-12-04T14:55:12.463Z] 14:55:12 INFO - Close about:devtools-toolbox page
[task 2019-12-04T14:55:12.463Z] 14:55:12 INFO - Wait for removeTab
[task 2019-12-04T14:55:12.463Z] 14:55:12 INFO - Removing tab.
[task 2019-12-04T14:55:12.464Z] 14:55:12 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2019-12-04T14:55:12.464Z] 14:55:12 INFO - Got event: 'TabClose' on [object XULElement].
[task 2019-12-04T14:55:12.464Z] 14:55:12 INFO - Tab removed and finished closing
[task 2019-12-04T14:55:12.464Z] 14:55:12 INFO - Wait for toolbox destroyed
[task 2019-12-04T14:55:12.464Z] 14:55:12 INFO - Buffered messages logged at 14:51:00
[task 2019-12-04T14:55:12.465Z] 14:55:12 INFO - Wait until aboutdebugging is selected
[task 2019-12-04T14:55:12.465Z] 14:55:12 INFO - Wait until about:devtools-toolbox is removed from debug targets
[task 2019-12-04T14:55:12.465Z] 14:55:12 INFO - Buffered messages logged at 14:52:12
[task 2019-12-04T14:55:12.473Z] 14:55:12 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2019-12-04T14:55:12.473Z] 14:55:12 INFO - Buffered messages logged at 14:53:42
[task 2019-12-04T14:55:12.473Z] 14:55:12 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2019-12-04T14:55:12.474Z] 14:55:12 INFO - Buffered messages finished
[task 2019-12-04T14:55:12.474Z] 14:55:12 INFO - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js | Test timed out -
[task 2019-12-04T14:55:12.475Z] 14:55:12 INFO - Removing tab.
[task 2019-12-04T14:55:12.475Z] 14:55:12 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2019-12-04T14:55:12.475Z] 14:55:12 INFO - Got event: 'TabClose' on [object XULElement].
[task 2019-12-04T14:55:12.475Z] 14:55:12 INFO - Tab removed and finished closing
[task 2019-12-04T14:55:12.476Z] 14:55:12 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-12-04T14:55:12.476Z] 14:55:12 INFO - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js | The main process DebuggerServer has no pending connection when the test ends -
[task 2019-12-04T14:55:12.476Z] 14:55:12 INFO - Stack trace:
[task 2019-12-04T14:55:12.476Z] 14:55:12 INFO - chrome://mochikit/content/browser-test.js:test_ok:1299
[task 2019-12-04T14:55:12.476Z] 14:55:12 INFO - chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:cleanup:170
[task 2019-12-04T14:55:12.476Z] 14:55:12 INFO - chrome://mochikit/content/browser-test.js:nextTest:577
[task 2019-12-04T14:55:12.476Z] 14:55:12 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1190
[task 2019-12-04T14:55:12.477Z] 14:55:12 INFO - setTimeout handlerchrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest_setTimeoutShim:686
[task 2019-12-04T14:55:12.477Z] 14:55:12 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1158
[task 2019-12-04T14:55:12.477Z] 14:55:12 INFO - setTimeout handlerchrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest_setTimeoutShim:686
[task 2019-12-04T14:55:12.477Z] 14:55:12 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1158
[task 2019-12-04T14:55:12.477Z] 14:55:12 INFO - setTimeout handlerchrome://mochikit/content/browser-test.js:Tester_execTest:1137
[task 2019-12-04T14:55:12.477Z] 14:55:12 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:932
[task 2019-12-04T14:55:12.477Z] 14:55:12 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-12-04T14:55:12.478Z] 14:55:12 INFO - GECKO(1257) | console.error: "[ACTION FAILED] REQUEST_TABS_FAILURE: Connection closed, pending request to root, type listTabs failed\n\nRequest stack:\nrequest@resource://devtools/shared/protocol/Front.js:214:14\ngenerateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:49:19\nlistTabs@resource://devtools/shared/fronts/root.js:334:44\nlistTabs@resource://devtools/client/aboutdebugging/src/modules/client-wrapper.js:129:33\nrequestTabs/<@resource://devtools/client/aboutdebugging/src/actions/debug-targets.js:209:31\nthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\ndispatch@resource://devtools/client/shared/vendor/redux.js:755:18\nonTabsUpdated@resource://devtools/client/aboutdebugging/src/middleware/debug-target-listener.js:19:11\nemit@resource://devtools/shared/event-emitter.js:190:24\nemit@resource://devtools/shared/event-emitter.js:271:18\nonPacket@resource://devtools/shared/protocol/Front.js:252:13\nonPacket@resource://devtools/shared/client/debugger-client.js:511:13\nsend/<@resource://devtools/shared/transport/local-transport.js:70:25\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nDevToolsUtils.executeSoonexports.executeSoon@resource://devtools/shared/DevToolsUtils.js:62:21\nsend@resource://devtools/shared/transport/local-transport.js:58:21\nsend@resource://devtools/server/debugger-server-connection.js:89:20\nonTabListChanged@resource://devtools/server/actors/root.js:392:15\nBrowserTabList.prototype._notifyListChanged@resource://devtools/server/actors/webbrowser.js:458:10\nBrowserTabList.prototype.handleEvent<@resource://devtools/server/actors/webbrowser.js:671:12\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nupdateCurrentBrowser@chrome://browser/content/tabbrowser.js:1194:16\n_setupEventListeners/<@chrome://browser/content/tabbrowser.js:5090:16\nset selectedIndex@chrome://global/content/elements/tabbox.js:208:14\nset selectedPanel@chrome://global/content/elements/tabbox.js:227:7\nset selectedIndex@chrome://global/content/elements/tabbox.js:559:11\nset selectedItem@chrome://global/content/elements/tabbox.js:579:35\n_selectNewTab@chrome://global/content/elements/tabbox.js:749:7\non_mousedown@chrome://global/content/elements/tabbox.js:345:28\non_mousedown@chrome://browser/content/tabbrowser-tab.js:361:15\nhandleEvent@chrome://global/content/customElements.js:468:27\nsynthesizeMouseAtPoint@chrome://mochikit/content/tests/SimpleTest/EventUtils.js:469:13\nsynthesizeMouse@chrome://mochikit/content/tests/SimpleTest/EventUtils.js:406:10\ncheckTooltipVisibility@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js:87:14\nasync*@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js:61:9\nAsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1069:34\nTester_execTest@chrome://mochikit/content/browser-test.js:1104:11\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-04T14:55:12.479Z] 14:55:12 INFO - GECKO(1257) | console.error: "destroy@resource://devtools/shared/protocol/Front.js:68:23\ncleanup@resource://devtools/shared/protocol/Pool.js:171:10\nonClosed@resource://devtools/shared/client/debugger-client.js:647:12\nclose@resource://devtools/shared/transport/local-transport.js:171:20\nclose@resource://devtools/shared/transport/local-transport.js:167:13\nclose@resource://devtools/server/debugger-server-connection.js:84:23\ncleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:178:12\nasyncnextTest@chrome://mochikit/content/browser-test.js:577:35\nasynctimeoutFn@chrome://mochikit/content/browser-test.js:1190:18\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerTester_execTest@chrome://mochikit/content/browser-test.js:1137:80\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-04T14:55:12.483Z] 14:55:12 INFO - GECKO(1257) | console.error: "[ACTION FAILED] REQUEST_TABS_FAILURE: Connection closed, pending request to root, type listTabs failed\n\nRequest stack:\nrequest@resource://devtools/shared/protocol/Front.js:214:14\ngenerateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:49:19\nlistTabs@resource://devtools/shared/fronts/root.js:334:44\nlistTabs@resource://devtools/client/aboutdebugging/src/modules/client-wrapper.js:129:33\nrequestTabs/<@resource://devtools/client/aboutdebugging/src/actions/debug-targets.js:209:31\nthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\ndispatch@resource://devtools/client/shared/vendor/redux.js:755:18\nonTabsUpdated@resource://devtools/client/aboutdebugging/src/middleware/debug-target-listener.js:19:11\nemit@resource://devtools/shared/event-emitter.js:190:24\nemit@resource://devtools/shared/event-emitter.js:271:18\nonPacket@resource://devtools/shared/protocol/Front.js:252:13\nonPacket@resource://devtools/shared/client/debugger-client.js:511:13\nsend/<@resource://devtools/shared/transport/local-transport.js:70:25\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nDevToolsUtils.executeSoonexports.executeSoon@resource://devtools/shared/DevToolsUtils.js:62:21\nsend@resource://devtools/shared/transport/local-transport.js:58:21\nsend@resource://devtools/server/debugger-server-connection.js:89:20\nonTabListChanged@resource://devtools/server/actors/root.js:392:15\nBrowserTabList.prototype._notifyListChanged@resource://devtools/server/actors/webbrowser.js:458:10\nBrowserTabList.prototype._handleActorClose@resource://devtools/server/actors/webbrowser.js:482:8\nBrowserTabList.prototype.handleEvent<@resource://devtools/server/actors/webbrowser.js:678:14\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\n_beginRemoveTab@chrome://browser/content/tabbrowser.js:3398:12\nremoveTab@chrome://browser/content/tabbrowser.js:3188:15\nremoveTab@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:234:12\ncloseAboutDevtoolsToolbox@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/head.js:135:9\nasync@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js:67:9\nAsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1069:34\nTester_execTest@chrome://mochikit/content/browser-test.js:1104:11\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-04T14:55:12.483Z] 14:55:12 INFO - GECKO(1257) | console.error: "destroy@resource://devtools/shared/protocol/Front.js:68:23\ncleanup@resource://devtools/shared/protocol/Pool.js:171:10\nonClosed@resource://devtools/shared/client/debugger-client.js:647:12\nclose@resource://devtools/shared/transport/local-transport.js:171:20\nclose@resource://devtools/shared/transport/local-transport.js:167:13\nclose@resource://devtools/server/debugger-server-connection.js:84:23\ncleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:178:12\nasyncnextTest@chrome://mochikit/content/browser-test.js:577:35\nasynctimeoutFn@chrome://mochikit/content/browser-test.js:1190:18\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerTester_execTest@chrome://mochikit/content/browser-test.js:1137:80\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-04T14:55:12.484Z] 14:55:12 INFO - GECKO(1257) | console.error: "[ACTION FAILED] REQUEST_TABS_FAILURE: Connection closed, pending request to root, type listTabs failed\n\nRequest stack:\nrequest@resource://devtools/shared/protocol/Front.js:214:14\ngenerateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:49:19\nlistTabs@resource://devtools/shared/fronts/root.js:334:44\nlistTabs@resource://devtools/client/aboutdebugging/src/modules/client-wrapper.js:129:33\nrequestTabs/<@resource://devtools/client/aboutdebugging/src/actions/debug-targets.js:209:31\nthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\ndispatch@resource://devtools/client/shared/vendor/redux.js:755:18\nonTabsUpdated@resource://devtools/client/aboutdebugging/src/middleware/debug-target-listener.js:19:11\nemit@resource://devtools/shared/event-emitter.js:190:24\nemit@resource://devtools/shared/event-emitter.js:271:18\nonPacket@resource://devtools/shared/protocol/Front.js:252:13\nonPacket@resource://devtools/shared/client/debugger-client.js:511:13\nsend/<@resource://devtools/shared/transport/local-transport.js:70:25\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nDevToolsUtils.executeSoonexports.executeSoon@resource://devtools/shared/DevToolsUtils.js:62:21\nsend@resource://devtools/shared/transport/local-transport.js:58:21\nsend@resource://devtools/server/debugger-server-connection.js:89:20\nonTabListChanged@resource://devtools/server/actors/root.js:392:15\nBrowserTabList.prototype._notifyListChanged@resource://devtools/server/actors/webbrowser.js:458:10\nBrowserTabList.prototype.handleEvent<@resource://devtools/server/actors/webbrowser.js:671:12\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nupdateCurrentBrowser@chrome://browser/content/tabbrowser.js:1194:16\n_setupEventListeners/<@chrome://browser/content/tabbrowser.js:5090:16\nset selectedIndex@chrome://global/content/elements/tabbox.js:208:14\nset selectedPanel@chrome://global/content/elements/tabbox.js:227:7\nset selectedIndex@chrome://global/content/elements/tabbox.js:559:11\nset selectedItem@chrome://global/content/elements/tabbox.js:579:35\nset selectedTab@chrome://global/content/elements/tabbox.js:98:11\nset selectedTab@chrome://browser/content/tabbrowser.js:316:7\n_blurTab@chrome://browser/content/tabbrowser.js:3646:31\n_beginRemoveTab@chrome://browser/content/tabbrowser.js:3304:12\nremoveTab@chrome://browser/content/tabbrowser.js:3188:15\nremoveTab@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:234:12\ncloseTabAndToolbox@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:522:9\ncleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:160:11\nnextTest@chrome://mochikit/content/browser-test.js:577:35\nasynctimeoutFn@chrome://mochikit/content/browser-test.js:1190:18\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerTester_execTest@chrome://mochikit/content/browser-test.js:1137:80\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-04T14:55:12.486Z] 14:55:12 INFO - GECKO(1257) | console.error: "destroy@resource://devtools/shared/protocol/Front.js:68:23\ncleanup@resource://devtools/shared/protocol/Pool.js:171:10\nonClosed@resource://devtools/shared/client/debugger-client.js:647:12\nclose@resource://devtools/shared/transport/local-transport.js:171:20\nclose@resource://devtools/shared/transport/local-transport.js:167:13\nclose@resource://devtools/server/debugger-server-connection.js:84:23\ncleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:178:12\nasyncnextTest@chrome://mochikit/content/browser-test.js:577:35\nasynctimeoutFn@chrome://mochikit/content/browser-test.js:1190:18\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerSimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:686:43\ntimeoutFn@chrome://mochikit/content/browser-test.js:1158:52\nsetTimeout handlerTester_execTest@chrome://mochikit/content/browser-test.js:1137:80\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-04T14:55:12.493Z] 14:55:12 INFO - GECKO(1257) | MEMORY STAT | vsize 20975986MB | residentFast 2232MB

Comment 1

[Julian Descottes [:jdescottes]]

Hi Cristina, I think that's Bug 1534871. Looks like my fix still didn't address the issue :/ Should we reopen the other bug to preserve the history?

Comment 2

[Julian Descottes [:jdescottes]]

At least with the additional timeouts we are now sure that the test is timing out during the cleanup phase, when closing the about:devtools-toolbox tab.

From https://searchfox.org/mozilla-central/rev/ea63a0888d406fae720cf24f4727d87569a8cab5/devtools/client/aboutdebugging/test/browser/head.js#120-152

async function closeAboutDevtoolsToolbox(
  aboutDebuggingDocument,
  devtoolsTab,
  win
) {
  // Wait for all requests to settle on the opened about:devtools toolbox.
  const devtoolsBrowser = devtoolsTab.linkedBrowser;
  const devtoolsWindow = devtoolsBrowser.contentWindow;
  const toolbox = getToolbox(devtoolsWindow);
  await toolbox.target.client.waitForRequestsToSettle();

  info("Close about:devtools-toolbox page");
  const onToolboxDestroyed = gDevTools.once("toolbox-destroyed");

  info("Wait for removeTab");
  await removeTab(devtoolsTab);

  info("Wait for toolbox destroyed");
  await onToolboxDestroyed;

  // Changing the tab will also trigger a request to list tabs, so wait until the selected
  // tab has changed to wait for requests to settle.
  info("Wait until aboutdebugging is selected");
  await waitUntil(() => gBrowser.selectedTab !== devtoolsTab);

  // Wait for removing about:devtools-toolbox tab info from about:debugging.
  info("Wait until about:devtools-toolbox is removed from debug targets");
  await waitUntil(
    () => !findDebugTargetByText("Toolbox - ", aboutDebuggingDocument)
  );

  await waitForRequestsToSettle(win.AboutDebugging.store);
}

The last log we see is Wait until about:devtools-toolbox is removed from debug targets and waitForRequestsToSettle is not logging anything so we can't know if we reach it. However since waitForRequestsToSettle has a 500ms cap, so it should never hang.

If this is correct, it means that the previous waitUntil is never satisfied:

  await waitUntil(
    () => !findDebugTargetByText("Toolbox - ", aboutDebuggingDocument)
  );

Looking at the screenshot, there might be something suspicious. This test involves at most three tabs:

[new tab] [about:debugging] [about:devtools-toolbox]

During most of the test, the third tab is selected ("about:devtools-toolbox"). At the end we close it, and we will perform a few final asserts on the "about:debugging" tab. At that point in the test, I expect about:debugging to become the selected tab. However in the screenshot, we see that "new tab" is selected. Maybe this prevents the about:debugging document from being updated correctly?

I am trying to get more info on try, but so far I haven't reproduced this on my previous try pushes.

Comment 3

[Julian Descottes [:jdescottes]]

Some more info. Even when reselecting the good tab, we still get the timeout: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=279984683&repo=try&lineNumber=1956

But now we see the about:debugging tab in the screenshot, and we can see that indeed it still thinks that about:devtools-toolbox is open.

But there are some other interesting logs:

[task 2019-12-06T10:30:08.842Z] 10:30:08     INFO - GECKO(1284) | console.error: "[ACTION FAILED] REQUEST_TABS_FAILURE: Connection closed, pending request to root, type listTabs failed\n\nRequest stack:\nrequest@resource://devtools/shared/protocol/Front.js:214:14\ngenerateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:49:19\nlistTabs@resource://devtools/shared/fronts/root.js:334:44\nlistTabs@resource://devtools/client/aboutdebugging/src/modules/client-wrapper.js:129:33\nrequestTabs/<@resource://devtools/client/aboutdebugging/src/actions/debug-targets.js:209:31\nthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\ndispatch@resource://devtools/client/shared/vendor/redux.js:755:18\nonTabsUpdated@resource://devtools/client/aboutdebugging/src/middleware/debug-target-listener.js:19:11\nemit@resource://devtools/shared/event-emitter.js:190:24\nemit@resource://devtools/shared/event-emitter.js:271:18\nonPacket@resource://devtools/shared/protocol/Front.js:252:13\nonPacket@resource://devtools/shared/client/debugger-client.js:511:13\nsend/<@resource://devtools/shared/transport/local-transport.js:70:25\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nDevToolsUtils.executeSoon*exports.executeSoon@resource://devtools/shared/DevToolsUtils.js:62:21\nsend@resource://devtools/shared/transport/local-transport.js:58:21\nsend@resource://devtools/server/debugger-server-connection.js:89:20\nonTabListChanged@resource://devtools/server/actors/root.js:392:15\nBrowserTabList.prototype._notifyListChanged@resource://devtools/server/actors/webbrowser.js:458:10\nBrowserTabList.prototype.handleEvent<@resource://devtools/server/actors/webbrowser.js:671:12\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nupdateCurrentBrowser@chrome://browser/content/tabbrowser.js:1194:16\n_setupEventListeners/<@chrome://browser/content/tabbrowser.js:5090:16\nset selectedIndex@chrome://global/content/elements/tabbox.js:208:14\nset selectedPanel@chrome://global/content/elements/tabbox.js:227:7\nset selectedIndex@chrome://global/content/elements/tabbox.js:559:11\nset selectedItem@chrome://global/content/elements/tabbox.js:579:35\n_selectNewTab@chrome://global/content/elements/tabbox.js:749:7\non_mousedown@chrome://global/content/elements/tabbox.js:345:28\non_mousedown@chrome://browser/content/tabbrowser-tab.js:361:15\nhandleEvent@chrome://global/content/customElements.js:468:27\nsynthesizeMouseAtPoint@chrome://mochikit/content/tests/SimpleTest/EventUtils.js:469:13\nsynthesizeMouse@chrome://mochikit/content/tests/SimpleTest/EventUtils.js:406:10\ncheckTooltipVisibility@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js:84:14\nasync*@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js:58:9\nAsync*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1069:34\nTester_execTest@chrome://mochikit/content/browser-test.js:1104:11\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-06T10:30:08.844Z] 10:30:08     INFO - GECKO(1284) | console.error: "destroy@resource://devtools/shared/protocol/Front.js:68:23\ncleanup@resource://devtools/shared/protocol/Pool.js:171:10\nonClosed@resource://devtools/shared/client/debugger-client.js:647:12\nclose@resource://devtools/shared/transport/local-transport.js:171:20\nclose@resource://devtools/shared/transport/local-transport.js:167:13\nclose@resource://devtools/shared/transport/local-transport.js:167:13\ncleanup@resource://devtools/shared/client/debugger-client.js:138:27\nclose/promise<@resource://devtools/shared/client/debugger-client.js:154:7\nclose@resource://devtools/shared/client/debugger-client.js:131:21\nclose@resource://devtools/client/aboutdebugging/src/modules/client-wrapper.js:163:24\ndisconnectRuntime/<@resource://devtools/client/aboutdebugging/src/actions/runtimes.js:244:27\nasync*thunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\ndispatch@resource://devtools/client/shared/vendor/redux.js:755:18\nunwatchRuntime/<@resource://devtools/client/aboutdebugging/src/actions/runtimes.js:355:15\nthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\nbindActionCreator/<@resource://devtools/client/shared/vendor/redux.js:644:12\ndestroy@resource://devtools/client/aboutdebugging/aboutdebugging.js:147:26\n@resource://devtools/client/aboutdebugging/aboutdebugging.js:184:20\n_endRemoveTab@chrome://browser/content/tabbrowser.js:3568:15\nremoveTab@chrome://browser/content/tabbrowser.js:3219:14\nremoveTab@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:234:12\ncloseTabAndToolbox@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:522:9\ncleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:160:11\nnextTest@chrome://mochikit/content/browser-test.js:577:35\nasync*timeoutFn@chrome://mochikit/content/browser-test.js:1190:18\nsetTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1137:80\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-06T10:30:08.848Z] 10:30:08     INFO - GECKO(1284) | console.error: "[ACTION FAILED] REQUEST_TABS_FAILURE: Connection closed, pending request to root, type listTabs failed\n\nRequest stack:\nrequest@resource://devtools/shared/protocol/Front.js:214:14\ngenerateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:49:19\nlistTabs@resource://devtools/shared/fronts/root.js:334:44\nlistTabs@resource://devtools/client/aboutdebugging/src/modules/client-wrapper.js:129:33\nrequestTabs/<@resource://devtools/client/aboutdebugging/src/actions/debug-targets.js:209:31\nthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\ndispatch@resource://devtools/client/shared/vendor/redux.js:755:18\nonTabsUpdated@resource://devtools/client/aboutdebugging/src/middleware/debug-target-listener.js:19:11\nemit@resource://devtools/shared/event-emitter.js:190:24\nemit@resource://devtools/shared/event-emitter.js:271:18\nonPacket@resource://devtools/shared/protocol/Front.js:252:13\nonPacket@resource://devtools/shared/client/debugger-client.js:511:13\nsend/<@resource://devtools/shared/transport/local-transport.js:70:25\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\nDevToolsUtils.executeSoon*exports.executeSoon@resource://devtools/shared/DevToolsUtils.js:62:21\nsend@resource://devtools/shared/transport/local-transport.js:58:21\nsend@resource://devtools/server/debugger-server-connection.js:89:20\nonTabListChanged@resource://devtools/server/actors/root.js:392:15\nBrowserTabList.prototype._notifyListChanged@resource://devtools/server/actors/webbrowser.js:458:10\nBrowserTabList.prototype._handleActorClose@resource://devtools/server/actors/webbrowser.js:482:8\nBrowserTabList.prototype.handleEvent<@resource://devtools/server/actors/webbrowser.js:678:14\nexports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\n_beginRemoveTab@chrome://browser/content/tabbrowser.js:3398:12\nremoveTab@chrome://browser/content/tabbrowser.js:3188:15\nremoveTab@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:234:12\ncloseAboutDevtoolsToolbox@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/head.js:136:9\nasync*@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js:64:9\nAsync*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1069:34\nTester_execTest@chrome://mochikit/content/browser-test.js:1104:11\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"
[task 2019-12-06T10:30:08.848Z] 10:30:08     INFO - GECKO(1284) | console.error: "destroy@resource://devtools/shared/protocol/Front.js:68:23\ncleanup@resource://devtools/shared/protocol/Pool.js:171:10\nonClosed@resource://devtools/shared/client/debugger-client.js:647:12\nclose@resource://devtools/shared/transport/local-transport.js:171:20\nclose@resource://devtools/shared/transport/local-transport.js:167:13\nclose@resource://devtools/shared/transport/local-transport.js:167:13\ncleanup@resource://devtools/shared/client/debugger-client.js:138:27\nclose/promise<@resource://devtools/shared/client/debugger-client.js:154:7\nclose@resource://devtools/shared/client/debugger-client.js:131:21\nclose@resource://devtools/client/aboutdebugging/src/modules/client-wrapper.js:163:24\ndisconnectRuntime/<@resource://devtools/client/aboutdebugging/src/actions/runtimes.js:244:27\nasync*thunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\ndispatch@resource://devtools/client/shared/vendor/redux.js:755:18\nunwatchRuntime/<@resource://devtools/client/aboutdebugging/src/actions/runtimes.js:355:15\nthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9\nbindActionCreator/<@resource://devtools/client/shared/vendor/redux.js:644:12\ndestroy@resource://devtools/client/aboutdebugging/aboutdebugging.js:147:26\n@resource://devtools/client/aboutdebugging/aboutdebugging.js:184:20\n_endRemoveTab@chrome://browser/content/tabbrowser.js:3568:15\nremoveTab@chrome://browser/content/tabbrowser.js:3219:14\nremoveTab@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:234:12\ncloseTabAndToolbox@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:522:9\ncleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:160:11\nnextTest@chrome://mochikit/content/browser-test.js:577:35\nasync*timeoutFn@chrome://mochikit/content/browser-test.js:1190:18\nsetTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1137:80\nnextTest/<@chrome://mochikit/content/browser-test.js:932:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67\n"

Basically we have two pending listTabs requests. One from a tab destroy (closing about:devtools-toolbox) and one from a selected tab change (re-selecting the about:debugging tab). That means the issue is that listTabs requests are blocked for some reason. I don't see additional errors that could explain this, but the listTabs implementation is a bit fragile. We should add logs on the server to see if anything comes up.

Comment 4

[Julian Descottes [:jdescottes]]

(clearing the ni? we can keep this bug anyway since I started investigating)

Comment 5

[Andrei Ciure[:aciure]]

Retriggered:

https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=279548294&searchStr=Linux%2Cx64%2Casan%2CMochitests%2Ctest-linux64-asan%2Fopt-mochitest-devtools-chrome-e10s-3%2CM%28dt3%29&tochange=55171ff3d0f3b271dbac9f4defec583a84fce192&fromchange=4c5f5aad4fd76c7c4040f24d88f7b7695332c540

It started failing with Bug 1509804.

Comment 6

[Julian Descottes [:jdescottes]]

(In reply to Andrei Ciure[:andrei_ciure] from comment #5)

Retriggered:

https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=279548294&searchStr=Linux%2Cx64%2Casan%2CMochitests%2Ctest-linux64-asan%2Fopt-mochitest-devtools-chrome-e10s-3%2CM%28dt3%29&tochange=55171ff3d0f3b271dbac9f4defec583a84fce192&fromchange=4c5f5aad4fd76c7c4040f24d88f7b7695332c540

It started failing with Bug 1509804.

Before Bug 1509804, the test was not running in dt3. So it's probably not related.

(and if you want to dig deeper, this has occurred relatively frequently on ASAN linux builds starting with https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=276873169&revision=c1d83dcf63762028c6601f34d3e83466fe2ceca9 but the failures used to be reported on Bug 1534871)

Comment 7

[Cristina Coroiu [:ccoroiu]]

The retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Linux%2Cx64%2Casan%2CMochitests%2Ctest-linux64-asan%2Fopt-mochitest-devtools-chrome-e10s-3%2CM%28dt3%29&tochange=5789d8f7d7bff75fbee2014dbdb3dc92bea74624&fromchange=0342c32685da735fbe16bc907d170228bb96a6a1&selectedJob=280104848
indicates that from this push:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2Cx64%2Casan%2Cmochitests%2Ctest-linux64-asan%2Fopt-mochitest-devtools-chrome-e10s-3%2Cm%28dt3%29&revision=76944c9ad43cb03e7016bae7f0882aa0b569e9c4
started to frequently fail.

Julien, could bug 1509804 cause this? But looking here https://hg.mozilla.org/integration/autoland/log?rev=%2Fbrowser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js should be from Bug 1534871, as you are saying, even the retriggers are green on older pushes.

Comment 8

[Julian Descottes [:jdescottes]]

could bug 1509804 cause this?

I don't think so.

Before Bug 1509804, the test was not running in dt3. So dt3 retriggers are not enough to know if there is a connection here. The patches in Bug 1509804 did shuffle the chunks (I added a new test), and while sometimes it can trigger intermittents, in this case I don't believe it. It is an older intermittent, that used to be incorrectly flagged on Bug 1534871.

The first recorded failure for a timeout in browser_aboutdebugging_devtoolstoolbox_tooltip_markupview.js is https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=276873169&revision=c1d83dcf63762028c6601f34d3e83466fe2ceca9 . This is a push from Nov 18th, and Bug 1509804 landed on the 4th of Dec. This means Bug 1509804 is not what started the failures here. At that time the test failing was in dt2, and this was flagged on Bug 1534871.

Comment 9

[Julian Descottes [:jdescottes]]

Started some dt2 retriggers at https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Linux%2Cx64%2Casan%2Cdt2&tochange=c1d83dcf63762028c6601f34d3e83466fe2ceca9&fromchange=a52581ac4a9dd02c9ae085f428db1e1579a60513&selectedJob=280162637

Comment 10

[Intermittent Failures Robot]

26 failures in 5144 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 23
• try: 2
• mozilla-central: 1

Platform breakdown:

• linux64: 26

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2019-12-02&endday=2019-12-08&tree=all

Comment 11

[Cristina Coroiu [:ccoroiu]]

Continued with dt2 retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2Cx64%2Casan%2Cdt2&fromchange=61ebc1a22544fa44ac2a4f9a2f120488a5f1d614&tochange=e6e016592c81510432cdaf2d159f363dd4b9eb45&selectedJob=280255836

Looking at https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-11-09&endday=2019-12-09&tree=trunk&bug=1534871 the first failure was on 2019-11-14, but on linux debug and failing on dt1:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Linux%2Cx64%2Cdebug%2CMochitests%2Ctest-linux64%2Fdebug-mochitest-devtools-chrome-e10s-1%2CM%28dt1%29&tochange=6a2d40014464a2bb1489921bd152d229e273d14d&fromchange=d791bfa31f08ec478b2ef6ca4f89b3a8849d723b&selectedJob=280273918

Comment 12

[Intermittent Failures Robot]

19 failures in 4867 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11
• mozilla-release: 1
• try: 4
• mozilla-central: 3

Platform breakdown:

• linux64: 19

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2019-12-09&endday=2019-12-15&tree=all

Comment 13

[Intermittent Failures Robot]

8 failures in 4582 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 4
• mozilla-central: 1
• mozilla-beta: 3

Platform breakdown:

• linux64: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2019-12-16&endday=2019-12-22&tree=all

Comment 14

[Intermittent Failures Robot]

3 failures in 1365 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 2
• autoland: 1

Platform breakdown:

• linux64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2019-12-23&endday=2019-12-29&tree=all

Comment 15

[Intermittent Failures Robot]

6 failures in 1862 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• mozilla-central: 2
• try: 1

Platform breakdown:

• linux64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2019-12-30&endday=2020-01-05&tree=all

Comment 16

[Intermittent Failures Robot]

10 failures in 4472 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 8
• try: 2

Platform breakdown:

• linux64: 5
• linux1804-64-qr: 3
• linux1804-64-shippable-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-01-06&endday=2020-01-12&tree=all

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1
• mozilla-central: 2

Platform breakdown:

• linux64: 1
• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-01-13&endday=2020-01-19&tree=all

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

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

Platform breakdown:

• linux1804-64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-01-20&endday=2020-01-26&tree=all

Comment 19

[Intermittent Failures Robot]

4 failures in 2190 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4

Platform breakdown:

• linux1804-64: 2
• linux1804-64-asan: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-01-27&endday=2020-02-02&tree=all

Comment 20

[Intermittent Failures Robot]

6 failures in 3364 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 3
• autoland: 3

Platform breakdown:

• linux1804-64: 2
• linux1804-64-asan: 3
• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-02-03&endday=2020-02-09&tree=all

Comment 21

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 6

Platform breakdown:

• linux1804-64-asan: 4
• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-02-10&endday=2020-02-16&tree=all

Comment 22

[Intermittent Failures Robot]

8 failures in 4045 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 5
• mozilla-central: 1
• try: 2

Platform breakdown:

• linux1804-64-asan: 4
• linux1804-64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-02-17&endday=2020-02-23&tree=all

Comment 23

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 2
• autoland: 1

Platform breakdown:

• linux1804-64: 2
• linux1804-64-asan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1601318&startday=2020-02-24&endday=2020-03-01&tree=all

Comment 24

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.