Closed Bug 1277657 Opened 8 years ago Closed 5 years ago

Intermittent browser_inplace-editor_autocomplete_02.js | Correct value is autocompleted - Got , expected block | Popup is closed | Test timed out

Categories

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

Product:
DevTools
Component:
Inspector: Rules
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: RyanVM, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

Bug 1277657 - Wait for mozAfterPaint after creating span in inplace-editor tests;
58 bytes, text/x-review-board-request
Details
Fix a race condition in devtools test helper_inline_editor.js. r=jdescottes
998 bytes, patch
jdescottes
: review+
Details | Diff | Splinter Review 
https://treeherder.mozilla.org/logviewer.html#?job_id=188972&repo=ash#L3859

16:24:18     INFO -  1391 INFO TEST-START | devtools/client/shared/test/browser_inplace-editor_autocomplete_02.js
16:24:18     INFO -  TEST-INFO | started process screencapture
16:24:19     INFO -  TEST-INFO | screencapture: exit 0
16:24:19     INFO -  1392 INFO checking window state
16:24:19     INFO -  1393 INFO Entering test bound
16:24:19     INFO -  1394 INFO Adding a new tab with URL: data:text/html;charset=utf-8,inplace editor CSS value autocomplete
16:24:19     INFO -  1395 INFO Waiting for event: 'load' on [object XULElement].
16:24:19     INFO -  1396 INFO Got event: 'load' on [object XULElement].
16:24:19     INFO -  1397 INFO Tab added and finished loading
16:24:19     INFO -  1398 INFO Creating a new span element
16:24:19     INFO -  1399 INFO Creating an inplace-editor field
16:24:19     INFO -  1400 INFO Clicking on the inplace-editor field to turn to edit mode
16:24:19     INFO -  1401 INFO Starting to test for css property completion
16:24:19     INFO -  1402 INFO Pressing key b
16:24:19     INFO -  1403 INFO Expecting block
16:24:19     INFO -  1404 INFO Waiting for after-suggest event on the editor
16:24:19     INFO -  1405 INFO Synthesizing key b
16:24:19     INFO -  1406 INFO Checking the state
16:24:19     INFO -  1407 INFO TEST-UNEXPECTED-FAIL | devtools/client/shared/test/browser_inplace-editor_autocomplete_02.js | Correct value is autocompleted - Got , expected block
16:24:19     INFO -  Stack trace:
16:24:19     INFO -  chrome://mochikit/content/browser-test.js:test_is:967
16:24:19     INFO -  chrome://mochitests/content/browser/devtools/client/shared/test/helper_inplace_editor.js:testCompletion:89
16:24:19     INFO -  resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:TaskImpl.prototype._run:310
16:24:19     INFO -  resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:Handler.prototype.process:937
16:24:19     INFO -  resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:this.PromiseWalker.walkerLoop:816
16:24:19     INFO -  Not taking screenshot here: see the one that was previously logged
16:24:19     INFO -  1408 INFO TEST-UNEXPECTED-FAIL | devtools/client/shared/test/browser_inplace-editor_autocomplete_02.js | Popup is closed -
16:24:19     INFO -  Stack trace:
16:24:19     INFO -  chrome://mochitests/content/browser/devtools/client/shared/test/helper_inplace_editor.js:testCompletion:92
16:24:19     INFO -  resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:TaskImpl.prototype._run:310
16:24:19     INFO -  resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:Handler.prototype.process:937
16:24:19     INFO -  resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:this.PromiseWalker.walkerLoop:816
16:24:19     INFO -  1409 INFO Pressing key VK_BACK_SPACE
16:24:19     INFO -  1410 INFO Expecting b
16:24:19     INFO -  1411 INFO Adding event listener for right|back_space|escape keys
16:24:19     INFO -  1412 INFO Waiting for event: 'keypress' on [object HTMLInputElement].
16:24:19     INFO -  1413 INFO Synthesizing key VK_BACK_SPACE
16:24:55     INFO -  1414 INFO Console message: [JavaScript Error: "1464823495920	Toolkit.GMP	ERROR	GMPInstallManager.simpleCheckAndInstall Could not check for addons: Error: got node name: html, expected: updates (resource://gre/modules/addons/ProductAddonChecker.jsm:153:11) JS Stack trace: parseXML@ProductAddonChecker.jsm:153:11 < promise callback*ProductAddonChecker.getProductAddonList@ProductAddonChecker.jsm:320:12 < GMPInstallManager.prototype.checkForAddons@GMPInstallManager.jsm:107:5 < GMPInstallManager.prototype.simpleCheckAndInstall<@GMPInstallManager.jsm:204:29 < gBrowserInit._delayedStartup/<@browser.js:1330:7 < setTimeout handler*gBrowserInit._delayedStartup@browser.js:1326:5 < EventListener.handleEvent*gBrowserInit.onLoad@browser.js:1023:5 < onload@browser.xul:1:1" {file: "resource://gre/modules/Log.jsm" line: 753}]
16:24:55     INFO -  App_append@resource://gre/modules/Log.jsm:753:9
16:24:55     INFO -  Logger.prototype.log@resource://gre/modules/Log.jsm:389:7
16:24:55     INFO -  LoggerRepository.prototype.getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:504:44
16:24:55     INFO -  Logger.prototype.error@resource://gre/modules/Log.jsm:397:5
16:24:55     INFO -  GMPInstallManager.prototype.simpleCheckAndInstall<@resource://gre/modules/GMPInstallManager.jsm:285:7
16:24:55     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:320:40
16:24:55     INFO -  Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:940:21
16:24:55     INFO -  this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:816:7
16:24:55     INFO -  Promise*this.PromiseWalker.scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:747:11
16:24:55     INFO -  this.PromiseWalker.schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:779:7
16:24:55     INFO -  this.PromiseWalker.completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:714:7
16:24:55     INFO -  GMPInstallManager.prototype.checkForAddons/<@resource://gre/modules/GMPInstallManager.jsm:116:7
16:24:55     INFO -  promise callback*GMPInstallManager.prototype.checkForAddons@resource://gre/modules/GMPInstallManager.jsm:107:5
16:24:55     INFO -  GMPInstallManager.prototype.simpleCheckAndInstall<@resource://gre/modules/GMPInstallManager.jsm:204:29
16:24:55     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:319:40
16:24:55     INFO -  TaskImpl@resource://gre/modules/Task.jsm:280:3
16:24:55     INFO -  createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
16:24:55     INFO -  gBrowserInit._delayedStartup/<@chrome://browser/content/browser.js:1330:7
16:24:55     INFO -  setTimeout handler*gBrowserInit._delayedStartup@chrome://browser/content/browser.js:1326:5
16:24:55     INFO -  EventListener.handleEvent*gBrowserInit.onLoad@chrome://browser/content/browser.js:1023:5
16:24:55     INFO -  onload@chrome://browser/content/browser.xul:1:1
16:25:48     INFO -  Not taking screenshot here: see the one that was previously logged
16:25:48     INFO -  1415 INFO TEST-UNEXPECTED-FAIL | devtools/client/shared/test/browser_inplace-editor_autocomplete_02.js | Test timed out -
16:25:48     INFO -  1416 INFO Removing tab.
16:25:48     INFO -  1417 INFO Waiting for event: 'TabClose' on [object XULElement].
16:25:48     INFO -  1418 INFO Got event: 'TabClose' on [object XULElement].
16:25:48     INFO -  1419 INFO Tab removed and finished closing
16:25:48     INFO -  MEMORY STAT | vsize 11713MB | residentFast 487MB | heapAllocated 82MB
16:25:48     INFO -  1420 INFO TEST-OK | devtools/client/shared/test/browser_inplace-editor_autocomplete_02.js | took 90093ms
Flags: needinfo?(jdescottes)
Could reproduce with --run-until-failure . Taking the bug, sorry about that!
Assignee: nobody → jdescottes
Status: NEW → ASSIGNED
Flags: needinfo?(jdescottes)
Apparently all the browser_inplace-editor* tests in devtools/client/shared/test/ were prone to fail.

Waiting for a MozAfterPaint event after adding the test SPAN to the document seems to fix the issue.
Without this, the first synthesized key event seems to miss the focused element. This seems similar to Bug 1240509.

Neil: What is your opinion about those tests [1] ? Is waiting for mozAfterPaint [2] a proper workaround here, while waiting for Bug 1240509, or is it just randomly fixing another race condition?

[1] https://dxr.mozilla.org/mozilla-central/source/devtools/client/shared/test/browser_inplace-editor-01.js
[2] as I did here: https://hg.mozilla.org/try/rev/4989939a60fb15704e4b6ab99c2a47b8f954ca5d
Flags: needinfo?(enndeakin)
This isn't similar to 1240509. For 1240509, we should be waiting for the tab to open as the last patch in that bug does; it doesn't wait for painting anymore.

The editor tests here likely do want to want for a paint, or more correctly, for an editor to be properly initialized before using them.
Flags: needinfo?(enndeakin)
I take it that waiting for a MozAfterPaint event is reasonable here. Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f438ed3af283
Comment on attachment 8760246 [details]
Bug 1277657 - Wait for mozAfterPaint after creating span in inplace-editor tests;

Getting try failures after rebase, removing the flag until they are fixed.
Attachment #8760246 - Flags: review?(mratcliffe)
Component: Developer Tools → Developer Tools: CSS Rules Inspector
Inspector bug triage (filter on CLIMBING SHOES).
Priority: -- → P2
See Also: → 1277441
I'm stealing this bug.  There is a race condition that my changes in bug 1363829 cause to trigger much more frequently.

This code in helper_inline_editor.js seems to be the problem:

  info("Synthesizing key " + key);
  EventUtils.synthesizeKey(key, {}, editor.input.defaultView);

  yield onSuggest;
  yield onVisibilityChange;
  yield waitForTick();

I don't think there are any guarantees that the processing will complete within one event loop turn after the popup-opened event.  This is working today because setTimeout(f, 0) is kind of slow and can actually take a few event loop turns.  Bug 1363829 is making it faster causing this to perma-fail.

I'm going to change this to waitForTime(5) instead.
Assignee: jdescottes → bkelly
Blocks: 1363829
Comment on attachment 8869438 [details] [diff] [review]
Fix a race condition in devtools test helper_inline_editor.js. r=jdescottes

Julian, I think this reduces a race condition in this test.  See comment 8 for more of an explanation.
Attachment #8869438 - Flags: review?(jdescottes)
Sorry, comment 10 has the explanation.
Thanks for the patch Ben, I does fix the symptom.

The actual issue is that we fire two "after-suggest" events when typing a char. I'm investigating this for a bit. If I can find an easy proper fix, I'll try it with your patch from Bug 1363829. Otherwise we can land your patch to unblock you (let me know if this is pressing).
Yea, I would like to land bug 1363829 early next week if I can.
Comment on attachment 8869438 [details] [diff] [review]
Fix a race condition in devtools test helper_inline_editor.js. r=jdescottes

Review of attachment 8869438 [details] [diff] [review]:
-----------------------------------------------------------------

Ok let's go with this for now. 
This race condition is a mess and I'm not confident I can fix it purely with a test change.

Let's just leave-open.
Attachment #8869438 - Flags: review?(jdescottes) → review+
For the record, here's the issue. For inplace editors of type CONTENT_TYPES.CSS_VALUE, we trigger an autocompletion during the creation of the inplace editor :

http://searchfox.org/mozilla-central/rev/02cae69058d41e2c6b635edccbec91a6ca2cb57f/devtools/client/shared/inplace-editor.js#287-289

This *might* trigger an after-suggest event from the editor (even though there are many possible early bail-outs). But, the CONTENT_TYPES.CSS_VALUE needs a mock for fetching CSS properties which is only created in the start function of the test. 

http://searchfox.org/mozilla-central/rev/02cae69058d41e2c6b635edccbec91a6ca2cb57f/devtools/client/shared/test/browser_inplace-editor_autocomplete_02.js#73

My initial idea was to simply wait for an after-suggest after creating the inplace editor in helper_inplace_editor.js::createInplaceEditorAndClick. But as explained above, it's actually only useful for one type of inplace editor, and if they're not mocked properly, the autocompletion will actually throw before firing the expected event. 

Here is a patch that could fix the issue and attempts to get rid of the waitForTick/Time
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b2a0eee7207b0a3cd3c0dea1342516bb256f2bdd
Pushed by bkelly@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/91f8c767d03c
Fix a race condition in devtools test helper_inline_editor.js. r=jdescottes
Handing this back to Julian to fix the underlying issue.
Assignee: bkelly → jdescottes
Product: Firefox → DevTools
Assignee: jdescottes → nobody
Status: ASSIGNED → NEW
status-firefox49: affected → ---
The leave-open keyword is there and there is no activity for 6 months.
:gl, maybe it's time to close this bug?
Flags: needinfo?(gl)
Forwarding this ni to Julian on the fate of this bug.
Flags: needinfo?(gl) → needinfo?(jdescottes)
No failure in a year
Status: NEW → RESOLVED
Closed: 5 years ago
Flags: needinfo?(jdescottes)
Keywords: leave-open
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: