Closed Bug 1381706 Opened 7 years ago Closed 6 years ago

The browser_change_app_handler.js intermittently fails on Window

Categories

(Core :: XUL, defect, P3)

55 Branch
defect

Tracking

()

RESOLVED FIXED
mozilla63
Tracking Status
firefox57 --- wontfix
firefox58 --- wontfix
firefox59 --- wontfix
firefox61 --- wontfix
firefox62 --- wontfix
firefox63 --- fixed

People

(Reporter: evanxd, Assigned: Paolo)

References

Details

Attachments

(1 file)

Because working on Bug 1365133, we found out the browser_change_app_handler.js[6] will be intermittently failed by some unknown reasons (maybe some timing changes change somethings) after Bug 1365133 is landed.

In the previous investigation, we found it might be related with (gecko) platform issues. The main point is the try[1] log[2] is conflicted with the screenshot[3] captured when the test fails. The below is the test code I added to log[4].
```
let list = await waitForCondition(() => {
  let children = win.document.getAnonymousNodes(ourItem);
  if (children) {
    for (let i = 0; i < children.length; i++) {
      info("loop1: ourItem innerHTML: ");
      info(children[i].innerHTML);
    }
  } else {
    info("loop1: nothing");
  }
  return win.document.getAnonymousElementByAttribute(ourItem, "class", "actionsMenu");
});
```

The log[2] said there is no any content in the `richlistitem[type='text/x-test-handler']` richlistitem, it printed
> 20:57:34     INFO - loop1: nothing
> 20:57:34     INFO - loop1: nothing
> 20:57:34     INFO - loop1: nothing
> ...
> ...
It means that the test cannot get any anonymous nodes by `getAnonymousNodes` method. But the screenshot[3] just showed the richlistitem after test failed. The richlistitem should not be shown in the screenshot if richlistitem is an empty element. It should just show a white(or black) block there. So somehow maybe the `document.getAnonymousNodes` call at the runtime of running the test just cannot work (or something wrong with it) to get the content of the richlistitem element after doing the xulbinding in the test[5]. So the problem here for platform (gecko) could be why `document.getAnonymousNodes` cannot get anything from the richlistitem even the UI is rendered (the screenshot shows that). 

We should re-enable the test after we figure out the root cause.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8fc961ac4ae0f3ddb0eb7a65e73192edca98501b&selectedJob=114224880
[2]: https://archive.mozilla.org/pub/firefox/try-builds/itoyxd@gmail.com-8fc961ac4ae0f3ddb0eb7a65e73192edca98501b/try-win32/try_win7_vm_test-mochitest-browser-chrome-1-bm140-tests1-windows-build1113.txt.gz
[3]: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/d9800c72458ae5570606d18695a6062704bbaee55c4949478e3a50196bb8e177ea4a02e32ddef092427ef823f764b6a9a4ed79917da2e876b9578111d61ee137
[4]: https://hg.mozilla.org/try/rev/ceba9aa757b3
[5]: http://searchfox.org/mozilla-central/source/browser/components/preferences/in-content-new/tests/browser_change_app_handler.js#27
[6]: http://searchfox.org/mozilla-central/source/browser/components/preferences/in-content-new/tests/browser_change_app_handler.js
Check the original finding and discussion at https://bugzilla.mozilla.org/show_bug.cgi?id=1365133#c245.
See Also: → 1365133
Hi Boris,

What do you think of Comment 0?

Looks like somehow at the situation mentioned at Comment 0, we cannot get the anonymous nodes of the richlistitem (xul element) by a `document.getAnonymousNodes` call.
Flags: needinfo?(bzbarsky)
So looking at the logs linked above, it looks like this:

   let ourItemChildren = win.document.getAnonymousNodes(ourItem);

returns a one-element list, right?  That is, I see this bit in the log:

20:57:34     INFO - before1: ourItem innerHTML: 
20:57:34     INFO - <xul:hbox xmlns:xul="http://www.mozilla.org/keymaster/gatekeeper/there.is.only.xul"

etc.  But then the call inside the waitForCondition bit:

  let children = win.document.getAnonymousNodes(ourItem);

returns null.  Is that what you're seeing too?
So I tried to reproduce this failure locally (on Mac), but no luck so far.

It might be worth it to add logging to check whether the two getAnonymousNodes calls actually end up happening with the same document and same element...  I did look at the implementation of getAnonymousNodes, but it's pretty simple; I don't see how it could conceivably screw up.
Flags: needinfo?(bzbarsky)
Blocks: 1382059
Blocks: 1382057
(In reply to Boris Zbarsky [:bz] from comment #3)
> So looking at the logs linked above, it looks like this:
> 
>    let ourItemChildren = win.document.getAnonymousNodes(ourItem);
> 
> returns a one-element list, right?  That is, I see this bit in the log:
> 
> 20:57:34     INFO - before1: ourItem innerHTML: 
> 20:57:34     INFO - <xul:hbox
> xmlns:xul="http://www.mozilla.org/keymaster/gatekeeper/there.is.only.xul"
> 
> etc.  But then the call inside the waitForCondition bit:
> 
>   let children = win.document.getAnonymousNodes(ourItem);
> 
> returns null.  Is that what you're seeing too?

Yes, that is what we're looking at.

(In reply to Boris Zbarsky [:bz] from comment #4)
> So I tried to reproduce this failure locally (on Mac), but no luck so far.
> 
> It might be worth it to add logging to check whether the two
> getAnonymousNodes calls actually end up happening with the same document and
> same element...  
I did a experiment for this. The result is yes, that is same document and same element. (I'll explain more details about the experiment in the below.)

> I did look at the implementation of getAnonymousNodes, but
> it's pretty simple; I don't see how it could conceivably screw up.
Maybe we have other issues except `getAnonymousNodes` to cause this bug.

What I did in the experiment is adding logs[1] to check the `richlistitem` content and ensure we check the same document and same element as we handle in the preferences code. In the try[4], I still found out that the `richlistitem` content (in the log[2]) is conflicted with the timeout screenshot[3]. The `richlistitem` content is empty in the log[1], but the screenshot[3] still shows the correct content we expect in the test.

The log said that `richlistitem` content is empty:
> 23:33:12     INFO - loop1: ourItem.type: undefined
> 23:33:12     INFO - loop1: nothing
> 23:33:13     INFO - loop1: ourItem.type: undefined
> 23:33:13     INFO - loop1: nothing
> 23:33:13     INFO - loop1: ourItem.type: undefined
> 23:33:13     INFO - loop1: nothing
...

After the investigation, it seems more like a platform issue. What do you think?

[1]: https://hg.mozilla.org/try/rev/57d92cbee249
[2]: https://archive.mozilla.org/pub/firefox/try-builds/itoyxd@gmail.com-d96456733cbe3cd9730e329ae9638794641a234e/try-win32/try_win7_vm_test-mochitest-e10s-browser-chrome-1-bm140-tests1-windows-build1504.txt.gz
[3]: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/1c1d7778755804e0a059525f8a30adf0037185329a9562e44cc6fb5b5fbec0b7729269fa8de2e19e81a8092fe6720b789c0ad86c3a0eedebbfbc7b29fd951354
[4]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d96456733cbe3cd9730e329ae9638794641a234e&selectedJob=116819297
Flags: needinfo?(bzbarsky)
Summary: The browser_change_app_handler.js intermittently fails on Window 7 VM. → The browser_change_app_handler.js intermittently fails on Window
Component: Preferences → XUL
Product: Firefox → Core
> and ensure we check the same document and same element as we handle in the preferences code.

The try push there is not checking what I was talking about.

I'm talking about these two lines:

>+  let feedItemChildren = win.document.getAnonymousNodes(feedItem);

and

>+    let children = win.document.getAnonymousNodes(feedItem);

and checking whether "win.document" is the same exact object on both those lines and if it is whether "feedItem" is the same exact object in both those cases.

If it is, then the next thing to check is whether the parent chain of feedItem is the same on both lines (object identity, that is).

> Maybe we have other issues except `getAnonymousNodes` to cause this bug.

Sure.  It's possible the test is removing the "feedItem" element from the DOM between the first call and the second call.  It's possible that it's changing the -moz-binding style on it.  It's possible that it's adopting it into a different document.  It's possible (but less likely than the three things I just suggested!) that Gecko is randomly removing the XBL binding from the element for no reason whatsoever.

A good start might be investigating whether between those two lines the XBL binding is removed from feedItem and if so why (that is, what the JS and C++ stacks are to the removal).
Flags: needinfo?(bzbarsky)
Hi bz,

Thank you for the opinions and ideas.

One more question here, what do you think of the conflict issue of the screenshot and log mentioned at Comment 5. Do you think that might be a issue we need to figure out?

> What I did in the experiment is adding logs[1] to check the `richlistitem` content and ensure we check the same document and same element as we handle in the preferences code. In the try[4], I still found out that the `richlistitem` content (in the log[2]) is conflicted with the timeout screenshot[3]. The `richlistitem` content is empty in the log[1], but the screenshot[3] still shows the correct content we expect in the test.

Very appreciate.
Flags: needinfo?(bzbarsky)
My best hypothesis about the screenshot-vs-log thing is that we're in a transient state where we tear down the binding and haven't recreated it yet at the point when the code in the log runs.  Then we recreate the binding before you have a chance to take a screenshot.

In particular, note that getAnonymousNodes does no flushing of any sort and will not synchronously instantiate bindings.  So if you call it right after something just caused an async binding change, you will get "incorrect" answers.
Flags: needinfo?(bzbarsky)
Priority: -- → P3
This started occurring frequently in bug 1472555, but is easily fixed now that bug 1459556 landed.
Blocks: 1472555
Depends on: 1459556
Comment on attachment 8992944 [details]
Bug 1381706 - Don't wait for XBL construction in the handler applications list tests.

https://reviewboard.mozilla.org/r/257792/#review264750
Attachment #8992944 - Flags: review?(bgrinstead) → review+
Pushed by paolo.mozmail@amadzone.org:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f1aadf806cfd
Don't wait for XBL construction in the handler applications list tests. r=bgrins
https://hg.mozilla.org/mozilla-central/rev/f1aadf806cfd
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: