1475979 - Intermittent devtools/client/inspector/fonts/test/browser_fontinspector_editor-font-size-conversion.js | A promise chain failed to handle a rejection: Error: Connection closed, pending request to server1.conn2.child1/domstylerule79 type setRuleText failed

Status: RESOLVED FIXED

(DevTools :: Inspector, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: shindli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=188348096&repo=mozilla-inbound

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

[task 2018-07-16T13:07:25.516Z] 13:07:25     INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/fonts/test/browser_fontinspector_editor-font-size-conversion.js | A promise chain failed to handle a rejection: Error: Connection closed, pending request to server1.conn2.child1/domstylerule79, type setRuleText failed

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

reproduce with test-verify:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=linux%20-bf&tochange=bb9cb191c067fad734ece7f89708de01fb66b341&fromchange=37bd009f11f4e05b02a6219a01616331a315efd0

appears to have been a pre-existing problem.

Comment 2

[Intermittent Failures Robot]

19 failures in 123 pushes (0.154 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 12
* autoland: 4
* mozilla-central: 3

Platform breakdown:
* linux64: 19

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1475979&startday=2018-07-17&endday=2018-07-17&tree=trunk

Comment 3

[Patrick Brosset <:pbro>]

Reading the test failure logs at the moment. Here is what I can understand, hopefully that's helpful:

- The setRuleText failure happens because it's an async call to the devtools server, and while we're waiting, the test ends and the toolbox is destroyed. So the corresponding promise is left hanging, which fails the test. This happens all the time.
- This particular one did not happen before recent changes on the font editor panel because the rule-view tests (which rely heavily on this feature too) go through a lot of trouble to wait for everything to be settled before ending. But in these new font editor tests, there's probably a few cases where async changes happen that we don't wait for.
- So I think we need to address the immediate failure by putting in the right try/catches or whatever else is needed in the code to handle the error. But also, we need to clean the font test up a little bit so we know exactly when the editor refreshes, when events flow, and when things are really done.
- To fix the immediate problem, I think we need to add a return value to the setPropertyValue method in the Rule class in /devtools/client/inspector/rules/models/rule.js
Indeed, this method calls applyProperties which, itself, returns a promise, but setPropertyValue never does anything with that promise. I think it should just return it to its caller.
It's caller happens to be the setValue method in the TextProperty class. So getting the promise here would make it possible to add a .catch handler, and inside it, check if the rule-view has been destroyed already, and if so bail out silently.
I'm not 100% sure it's possible to check that from the TextProperty model class though. If not, then we should just bubble the error up one more level, by making setValue also return the promise. This way, we'd get access to the promise in the font-editor's syncChanges method (we could then add an await statement in front of it, and use the already existing try/catch to do the handling and checking if the font editor was already destroyed).

Comment 4

[Natalia Csoregi [:nataliaCs]]

There has been a total of 32 failures since the bug was filed:
- 29 failures on linux64 debug
- 1 failure on linux64-ccov debug
- 1 failure on osx-10-10 debug
- 1 failure on windows10-64 asan.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=188724312&repo=autoland&lineNumber=2191

[task 2018-07-18T11:20:03.930Z] 11:20:03     INFO - TEST-UNEXPECTED-FAIL | devtools/client/inspector/fonts/test/browser_fontinspector_editor-font-size-conversion.js | A promise chain failed to handle a rejection: Error: Connection closed, pending request to server1.conn2.child1/domstylerule79, type setRuleText failed
[task 2018-07-18T11:20:03.931Z] 11:20:03     INFO - 
[task 2018-07-18T11:20:03.932Z] 11:20:03     INFO - Request stack:
[task 2018-07-18T11:20:03.934Z] 11:20:03     INFO - request@resource://devtools/shared/base-loader.js -> resource://devtools/shared/protocol.js:1346:14
[task 2018-07-18T11:20:03.935Z] 11:20:03     INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/base-loader.js -> resource://devtools/shared/protocol.js:1500:14
[task 2018-07-18T11:20:03.936Z] 11:20:03     INFO - StyleRuleFront<.setRuleText<@resource://devtools/shared/base-loader.js -> resource://devtools/shared/fronts/styles.js:294:12
[task 2018-07-18T11:20:03.937Z] 11:20:03     INFO - apply/<@resource://devtools/shared/base-loader.js -> resource://devtools/shared/css/parsing-utils.js:1120:14
[task 2018-07-18T11:20:03.939Z] 11:20:03     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:928:23
[task 2018-07-18T11:20:03.940Z] 11:20:03     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:812:7
[task 2018-07-18T11:20:03.941Z] 11:20:03     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:745:11
[task 2018-07-18T11:20:03.943Z] 11:20:03     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:776:7
[task 2018-07-18T11:20:03.944Z] 11:20:03     INFO - Promise.prototype.then@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:461:5
[task 2018-07-18T11:20:03.945Z] 11:20:03     INFO - applyProperties@resource://devtools/shared/base-loader.js -> resource://devtools/client/inspector/rules/models/rule.js:282:9
[task 2018-07-18T11:20:03.946Z] 11:20:03     INFO - setPropertyValue@resource://devtools/shared/base-loader.js -> resource://devtools/client/inspector/rules/models/rule.js:343:5
[task 2018-07-18T11:20:03.948Z] 11:20:03     INFO - setValue@resource://devtools/shared/base-loader.js -> resource://devtools/client/inspector/rules/models/text-property.js:125:5
[task 2018-07-18T11:20:03.949Z] 11:20:03     INFO - syncChanges@resource://devtools/shared/base-loader.js -> resource://devtools/client/inspector/fonts/fonts.js:622:9
[task 2018-07-18T11:20:03.950Z] 11:20:03     INFO - exports.debounce/</timer<@resource://devtools/shared/base-loader.js -> resource://devtools/shared/debounce.js:30:7
[task 2018-07-18T11:20:03.951Z] 11:20:03     INFO - notify@resource://gre/modules/Timer.jsm:44:7
[task 2018-07-18T11:20:03.953Z] 11:20:03     INFO -  - stack: destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/protocol.js:1289:23
[task 2018-07-18T11:20:03.954Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/fronts/styles.js:114:5
[task 2018-07-18T11:20:03.955Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/protocol.js:928:9
[task 2018-07-18T11:20:03.956Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/protocol.js:1291:5
[task 2018-07-18T11:20:03.958Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/fronts/styles.js:39:5
[task 2018-07-18T11:20:03.959Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/protocol.js:928:9
[task 2018-07-18T11:20:03.960Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/protocol.js:1291:5
[task 2018-07-18T11:20:03.962Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/shared/fronts/inspector.js:472:5
[task 2018-07-18T11:20:03.963Z] 11:20:03     INFO - destroyInspector/this._destroyingInspector<@resource://devtools/shared/base-loader.js -> resource://devtools/client/framework/toolbox.js:2798:13
[task 2018-07-18T11:20:03.964Z] 11:20:03     INFO - Async*destroyInspector@resource://devtools/shared/base-loader.js -> resource://devtools/client/framework/toolbox.js:2782:40
[task 2018-07-18T11:20:03.966Z] 11:20:03     INFO - destroy@resource://devtools/shared/base-loader.js -> resource://devtools/client/framework/toolbox.js:2925:22
[task 2018-07-18T11:20:03.967Z] 11:20:03     INFO - closeToolbox@resource://devtools/shared/base-loader.js -> resource://devtools/client/framework/devtools.js:590:11
[task 2018-07-18T11:20:03.968Z] 11:20:03     INFO - async*closeTabAndToolbox@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:456:11
[task 2018-07-18T11:20:03.970Z] 11:20:03     INFO - async*cleanup@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:139:11
[task 2018-07-18T11:20:03.971Z] 11:20:03     INFO - async*nextTest@chrome://mochikit/content/browser-test.js:704:30
[task 2018-07-18T11:20:03.972Z] 11:20:03     INFO - async*testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1397:11
[task 2018-07-18T11:20:03.974Z] 11:20:03     INFO - run@chrome://mochikit/content/browser-test.js:1334:9
[task 2018-07-18T11:20:03.975Z] 11:20:03     INFO - Rejection date: Wed Jul 18 2018 11:20:01 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
[task 2018-07-18T11:20:03.976Z] 11:20:03     INFO - Stack trace:
[task 2018-07-18T11:20:03.978Z] 11:20:03     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
[task 2018-07-18T11:20:03.979Z] 11:20:03     INFO - chrome://mochikit/content/browser-test.js:nextTest:745
[task 2018-07-18T11:20:03.980Z] 11:20:03     INFO - chrome://mochikit/content/browser-test.js:testScope/test_finish/<:1397
[task 2018-07-18T11:20:03.984Z] 11:20:03     INFO - chrome://mochikit/content/browser-test.js:run:1334
[task 2018-07-18T11:20:03.986Z] 11:20:03     INFO - Console message: [JavaScript Error: "A promise chain failed to handle a rejection. Did you forget to '.catch', or did you forget to 'return'?
[task 2018-07-18T11:20:03.987Z] 11:20:03     INFO - See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
[task 2018-07-18T11:20:03.988Z] 11:20:03     INFO - 
[task 2018-07-18T11:20:03.989Z] 11:20:03     INFO - Date: Wed Jul 18 2018 11:20:01 GMT+0000 (UTC)
[task 2018-07-18T11:20:03.991Z] 11:20:03     INFO - Full Message: Error: Connection closed, pending request to server1.conn2.child1/domstylerule79, type setRuleText failed

Comment 5

[Intermittent Failures Robot]

32 failures in 653 pushes (0.049 failures/push) were associated with this bug in the last 7 days. 

This is the #33 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-inbound: 18
* autoland: 9
* mozilla-central: 4
* try: 1

Platform breakdown:
* linux64: 30
* windows10-64: 1
* linux64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1475979&startday=2018-07-16&endday=2018-07-22&tree=trunk

Comment 6

[Cristina Coroiu [:ccoroiu]]

:gl could you please take a look?

Comment 7

[Razvan Caliman [:rcaliman]]

:ccoroiu

I disabled the failing test in Bug 1476535. Then, I replaced its contents and re-enabled it in Bug 1477261 which landed yesterday. 


https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-07-16&endday=2018-07-22&tree=trunk&bug=1475979

The chart in the link above seems to confirm the failures have stopped after disabling the test. Am I reading it wrong?

Comment 8

[meck93]

We are trying to build a tool to automatically classify intermittent failures, which would provide a starting point for fixing the bug, reducing the manual work for the developers.
We are collecting some feedback on the results, to see if they’re good enough and where we need to improve.
    
For this bug, the tool says that the intermittent failure is most likely a:
Concurrency Issue: This includes tests in which failures occur due to thread management issues (different threads or their outcomes depending on an implicit ordering), race conditions and/or deadlocks, and issues related to an asynchronous waits (e.g. a process trying to access an external resource or continuing before the external resource is available).


Once you’re done investigating and/or fixing the bug, could you tell me:
- Did the tool correctly recognize the type of intermittent failure?
- Did the information from the tool help your analysis, the bug fixing process, or anything in the process? (please also let us know how the tool was useful and/or what would improve the tool's usefulness for you)

Comment 9

[Razvan Caliman [:rcaliman]]

The cause of this intermittent failure was addressed in Bug 1475782. No new failures since that landed. Can we close this bug?

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1

Platform breakdown:
* linux64: 1

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