1517530 - Intermittent devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js | Test timed out -

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

Comment 1

[Cosmin Sabou [:CosminS]]

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.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 2
* autoland: 3
* mozilla-central: 2

Platform breakdown:
* windows7-32: 7

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

Comment 3

[Julian Descottes [:jdescottes] (PTO 20 oct -> 25 oct)]

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.

Comment 4

[Cosmin Sabou [:CosminS]]

Julian, thanks for the input on this and yeah it looks like this starts with the push just before yours, sorry about that. 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&fromchange=a29627aa1ef5977bff1e93dcd150a274cfe79e15&group_state=expanded&selectedJob=220312735

This has toned down and on the 7th (1 failure) and 8th there are almost no failures so maybe working on another bug fixed this. Let's revisit if the failure rate increases.

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-central: 2

Platform breakdown:

• windows7-32: 3

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform breakdown:

• windows7-32: 2

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

Comment 7

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 8

[Daniel Varga [:dvarga]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=236274214&repo=mozilla-inbound&lineNumber=4695

01:40:06 INFO - Buffered messages logged at 01:39:21
01:40:06 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
01:40:06 INFO - Buffered messages finished
01:40:06 INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js | Test timed out -
01:40:06 INFO - Removing tab.
01:40:06 INFO - Waiting for event: 'TabClose' on [object XULElement].
01:40:06 INFO - Got event: 'TabClose' on [object XULElement].
01:40:06 INFO - Tab removed and finished closing
01:40:06 INFO - GECKO(3540) | MEMORY STAT | vsize 1517MB | vsizeMaxContiguous 122MB | residentFast 472MB | heapAllocated 81MB
01:40:06 INFO - TEST-OK | devtools/client/inspector/rules/test/browser_rules_user-agent-styles.js | took 180221ms
01:40:06 INFO - checking window state
01:40:06 INFO - TEST-START | devtools/client/inspector/rules/test/browser_rules_user-property-reset.js
01:40:06 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "UPDATE_GRIDS"
01:40:07 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "CLEAR_FLEXBOX"
01:40:07 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "CLEAR_FLEXBOX"
01:40:07 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "UPDATE_OFFSET_PARENT"
01:40:07 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "UPDATE_LAYOUT"
01:40:07 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "UPDATE_OFFSET_PARENT"
01:40:07 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "UPDATE_LAYOUT"
01:40:07 INFO - GECKO(3540) | console.log: "[DISPATCH] action type:" "CLEAR_FLEXBOX"
01:40:07 INFO - Not taking screenshot here: see the one that was previously logged
01:40:07 INFO - Buffered messages logged at 01:40:06
01:40:07 INFO - Entering test bound
01:40:07 INFO - Adding a new tab with URL: data:text/html;charset=utf-8,%0A%20%20%3Cp%20id%3D'id1'%20style%3D'width%3A200px%3B'%3Eelement%201%3C%2Fp%3E%0A%20%20%3Cp%20id%3D'id2'%20style%3D'width%3A100px%3B'%3Eelement%202%3C%2Fp%3E%0A
01:40:07 INFO - Tab added and finished loading
01:40:07 INFO - Loading the helper frame script chrome://mochitests/content/browser/devtools/client/inspector/rules/test/doc_frame_script.js
01:40:07 INFO - Opening the inspector
01:40:07 INFO - Opening the toolbox
01:40:07 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 245}]
01:40:07 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 245}]
01:40:07 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 245}]
01:40:07 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 245}]
01:40:07 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 245}]
01:40:07 INFO - Buffered messages logged at 01:40:07
01:40:07 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 245}]
01:40:07 INFO - Toolbox opened and focused

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-inbound: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1517530&startday=2019-03-25&endday=2019-03-31&tree=all

Comment 10

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 11

[Stefan Hindli [:stefan_hindli]]

New failure: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&selectedJob=245054083

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-inbound: 1

Platform breakdown:

• windows7-32-shippable: 1

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

Comment 13

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 14

[Cristina Coroiu [:ccoroiu]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=303559022&repo=mozilla-beta&lineNumber=6308

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• windows7-32-devedition: 1

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

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4

Platform breakdown:

• windows7-32-shippable: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1517530&startday=2020-05-25&endday=2020-05-31&tree=all

Comment 17

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

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