Treeherder Bug Filer Reporter
	Description • 6 years ago
treeherder

Filed by: dluca [at] mozilla.com

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

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

 INFO - TEST-PASS | devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js | Has UA rules - 
16:28:01     INFO - Selecting the node for 'input[type=number]'
16:28:01     INFO - Buffered messages logged at 16:25:46
16:28:01     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 3
16:28:01     INFO - Buffered messages logged at 16:26:18
16:28:01     INFO - Console message: [JavaScript Error: "getScreenshot(http://example.com/browser/devtools/client/inspector/rules/test/doc_urls_clickable.html) failed: TypeError: NetworkError when attempting to fetch resource." {file: "resource://activity-stream/lib/Screenshots.jsm" line: 45}]
16:28:01     INFO - getScreenshotForURL@resource://activity-stream/lib/Screenshots.jsm:45:7
16:28:01     INFO - async*maybeCacheScreenshot@resource://activity-stream/lib/Screenshots.jsm:98:32
16:28:01     INFO - async*_fetchScreenshot@resource://activity-stream/lib/TopSitesFeed.jsm:439:11
16:28:01     INFO - async*_fetchIcon@resource://activity-stream/lib/TopSitesFeed.jsm:427:11
16:28:01     INFO - async*getLinksWithDefaults@resource://activity-stream/lib/TopSitesFeed.jsm:329:11
16:28:01     INFO - async*refresh@resource://activity-stream/lib/TopSitesFeed.jsm:352:25
16:28:01     INFO - async*onAction@resource://activity-stream/lib/TopSitesFeed.jsm:652:9
16:28:01     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
16:28:01     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:54
16:28:01     INFO - init/this.intervalId<@resource://activity-stream/lib/SystemTickFeed.jsm:16:41
16:28:01     INFO - notify@resource://gre/modules/Timer.jsm:42:7
16:28:01     INFO - 
16:28:01     INFO - Console message: [JavaScript Error: "Unknown collection "main/tippytop"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 261}]
16:28:01     INFO - sync@resource://services-settings/RemoteSettingsClient.jsm:261:13
16:28:01     INFO - async*get@resource://services-settings/RemoteSettingsClient.jsm:230:17
16:28:01     INFO - async*getSite@resource://activity-stream/lib/FaviconFeed.jsm:156:25
16:28:01     INFO - async*fetchIcon@resource://activity-stream/lib/FaviconFeed.jsm:130:24
16:28:01     INFO - async*onAction@resource://activity-stream/lib/FaviconFeed.jsm:180:9
16:28:01     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
16:28:01     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:54
16:28:01     INFO - _requestRichIcon@resource://activity-stream/lib/TopSitesFeed.jsm:460:5
16:28:01     INFO - _fetchIcon@resource://activity-stream/lib/TopSitesFeed.jsm:424:5
16:28:01     INFO - async*getLinksWithDefaults@resource://activity-stream/lib/TopSitesFeed.jsm:329:11
16:28:01     INFO - async*refresh@resource://activity-stream/lib/TopSitesFeed.jsm:352:25
16:28:01     INFO - async*onAction@resource://activity-stream/lib/TopSitesFeed.jsm:652:9
16:28:01     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
16:28:01     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:54
16:28:01     INFO - init/this.intervalId<@resource://activity-stream/lib/SystemTickFeed.jsm:16:41
16:28:01     INFO - notify@resource://gre/modules/Timer.jsm:42:7
16:28:01     INFO - 
16:28:01     INFO - Buffered messages logged at 16:26:31
16:28:01     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 2
16:28:01     INFO - Buffered messages logged at 16:27:16
16:28:01     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
16:28:01     INFO - Buffered messages finished
16:28:01     INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js | Test timed out - 
16:28:01     INFO - Not taking screenshot here: see the one that was previously logged
16:28:01     INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js | Uncaught exception received from previously timed out test - at resource://devtools/shared/protocol.js:1320 - Error: Connection closed, pending request to server1.conn216.child1/domwalker26, type querySelector failed
16:28:01     INFO - 
16:28:01     INFO - Request stack:
16:28:01     INFO - request@resource://devtools/shared/protocol.js:1407:14
16:28:01     INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol.js:1531:14
16:28:01     INFO - querySelector@resource://devtools/shared/fronts/inspector.js:161:12
16:28:01     INFO - getNodeFront@chrome://mochitests/content/browser/devtools/client/inspector/test/shared-head.js:232:10
16:28:01     INFO - selectNode@chrome://mochitests/content/browser/devtools/client/inspector/test/shared-head.js:247:27
16:28:01     INFO - async*userAgentStylesVisible@chrome://mochitests/content/browser/devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js:109:11
16:28:01     INFO - async*@chrome://mochitests/content/browser/devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js:70:9
16:28:01     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34
16:28:01     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1097:16
16:28:01     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:995:9
16:28:01     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59
16:28:01     INFO - 
16:28:01     INFO - Stack trace:
16:28:01     INFO - destroy@resource://devtools/shared/protocol.js:1320:23
16:28:01     INFO - destroy@resource://devtools/shared/fronts/inspector.js:60:5
16:28:01     INFO - destroy@resource://devtools/shared/protocol.js:947:9
16:28:01     INFO - destroy@resource://devtools/shared/protocol.js:1322:5
16:28:01     INFO - destroy@resource://devtools/shared/fronts/inspector.js:492:5
16:28:01     INFO - destroyInspector/this._destroyingInspector<@resource://devtools/client/framework/toolbox.js:2799:13
16:28:01     INFO - Async*destroyInspector@resource://devtools/client/framework/toolbox.js:2788:40
16:28:01     INFO - _destroyToolbox@resource://devtools/client/framework/toolbox.js:2906:22
16:28:01     INFO - async*destroy@resource://devtools/client/framework/toolbox.js:2836:23
16:28:01     INFO - closeToolbox@resource://devtools/client/framework/devtools.js:594:11
16:28:01     INFO - async*closeTabAndToolbox@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:453:11
16:28:01     INFO - async*cleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:137:11
16:28:01     INFO - async*nextTest@chrome://mochikit/content/browser-test.js:705:30
16:28:01     INFO - async*timeoutFn@chrome://mochikit/content/browser-test.js:1203:9
16:28:01     INFO - setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:684:12
16:28:01     INFO - timeoutFn@chrome://mochikit/content/browser-test.js:1181:13
16:28:01     INFO - setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:684:12
16:28:01     INFO - timeoutFn@chrome://mochikit/content/browser-test.js:1181:13
16:28:01     INFO - setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:684:12
16:28:01     INFO - timeoutFn@chrome://mochikit/content/browser-test.js:1181:13
16:28:01     INFO - setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1165:9
16:28:01     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:995:9
16:28:01     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59
16:28:05     INFO - Removing tab.
16:28:05     INFO - Waiting for event: 'TabClose' on [object XULElement].
16:28:05     INFO - Got event: 'TabClose' on [object XULElement].
16:28:05     INFO - Tab removed and finished closing
16:28:05     INFO - GECKO(1096) | MEMORY STAT | vsize 1801MB | vsizeMaxContiguous 52MB | residentFast 892MB | heapAllocated 375MB
16:28:05     INFO - TEST-OK | devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js | took 183719ms
16:28:05     INFO - checking window state
16:28:05     INFO - TEST-START | devtools/client/inspector/rules/test/browser_rules_user-property-reset.js

	Cosmin Sabou [:CosminS]
	Comment 1 • 6 years ago

This seems to have started when Bug 1516408 landed here: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed&searchStr=windows%2C7%2Cpgo%2Cmochitests%2Cwith%2Ce10s%2Ctest-windows7-32-pgo%2Fopt-mochitest-devtools-chrome-e10s-8%2Cm-e10s%28dt8%29&tochange=13d9e2a48dbb3cc3d4e8a58a918a1cef129156d3&group_state=expanded&fromchange=a29627aa1ef5977bff1e93dcd150a274cfe79e15&selectedJob=220246392

Julian, could you please take a look over this? Thank you.

	Julian Descottes [:jdescottes]
	Comment 3 • 6 years ago

It's unlikely that my patches had impact there. I did some more retriggers on the previous changeset and it seems to already happen there: 

https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed&searchStr=windows%2C7%2Cpgo%2Cmochitests%2Cwith%2Ce10s%2Ctest-windows7-32-pgo%2Fopt-mochitest-devtools-chrome-e10s-8%2Cm-e10s%28dt8%29&tochange=13d9e2a48dbb3cc3d4e8a58a918a1cef129156d3&group_state=expanded&fromchange=a29627aa1ef5977bff1e93dcd150a274cfe79e15&selectedJob=220312734

The test is repeated for a variety of DOM elements and doesn't always fail for the same element. However it always seems to fail while waiting for a call to getApplied:

  let entries = await inspector.pageStyle.getApplied(
    inspector.selection.nodeFront,
    {
      inherited: true,
      matchedSelectors: true,
      filter: filter,
    }
  );

(https://searchfox.org/mozilla-central/rev/f8de61826903996f6bdf41b11a2844dd59ac144f/devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js#154) 

When the test times out, the logs report that this getApplied request failed. But they also report that a getUsedFontFaces failed:

 console.error: "Could not get the list of font families" (new Error("Connection closed, pending request to server1.conn216.child1/pagestyle28, type getUsedFontFaces failed

This other request comes from the creation of the text-property-editor:

  this.rule.elementStyle.getUsedFontFamilies().then(families => {
    // ...
  }).catch(e => console.error("Could not get the list of font families", e));

(https://searchfox.org/mozilla-central/rev/f8de61826903996f6bdf41b11a2844dd59ac144f/devtools/client/inspector/rules/views/text-property-editor.js#436)

And this happens when we selected the node in the test, right before calling getApplied:

  await selectNode(data.selector, inspector);
  await compareAppliedStylesWithUI(inspector, view);

(https://searchfox.org/mozilla-central/rev/f8de61826903996f6bdf41b11a2844dd59ac144f/devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js#141)

The inspector is not waiting for this server-side call before firing the "inspector-updated" event which we are expected for after selecting a node in tests. So both requests getUsedFontFaces and getApplied are probably fired in parallel.  

I have no idea why the requests fail at the moment, not even sure if the fact that they are both triggered at the same time is related to the issue.