Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

RESOLVED FIXED in Firefox 56

Status

P2
normal
RESOLVED FIXED
a year ago
2 months ago

People

(Reporter: bsilverberg, Assigned: bsilverberg)

Tracking

unspecified
mozilla56

Firefox Tracking Flags

(firefox56 fixed)

Details

(Whiteboard: triaged)

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment)

(Assignee)

Description

a year ago
This test was disabled due to it being a common intermittent, but it's really not a good thing to have one of our tests disabled, so we should devote some time to trying to figure this out and get the test re-enabled.

I will take a look and see if I can reproduce the failure or come up with an idea of what might be causing it, and if I cannot I will seek help from a teammate.

All of the details of the intermittent are available in Bug #1308068, but I will copy some information Joel provided about the failures into this bug so it's all in one place.

This is from https://bugzilla.mozilla.org/show_bug.cgi?id=1308068#c2:

May 24th this started up and is on track to have 60+ failures this coming week:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1308068&startday=2017-05-01&endday=2017-05-30&tree=all

This remains on osx-debug as the primary failure pattern.

Here is a recent log:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=103166387&lineNumber=30353

and related screenshot:
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/e9422707c7e01f0c7b19583b1efd6915b36be76f1f7963506e558b048d5b9f3911d4a53fc9b510c298159db2dd149aff0a35db84dd6081fcdec8b546eff1ddce

and here is related information from the above mentioned log file:
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | onFocusChanged fired once for the given window - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | windowId is an integer - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | Last focused window has the correct id - Expected: 1871, Actual: 1871 - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | Got focus change event for the correct window ID. - 
14:19:01     INFO - Close browser window 2
14:19:01     INFO - onRemoved: windowId=1879
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | windowId is an integer - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | windows.events - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | Got removed event for the correct window ID. - 
14:19:01     INFO - Close browser window 1
14:19:01     INFO - onRemoved: windowId=1871
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | windowId is an integer - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | windows.events - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | Got removed event for the correct window ID. - 
14:19:01     INFO - onFocusChange: windowId=-1 lastWindowId=1871
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | onFocusChanged fired once for the given window - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | windowId is an integer - 
14:19:01     INFO - onFocusChange: windowId=3 lastWindowId=-1
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | onFocusChanged fired once for the given window - 
14:19:01     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | windowId is an integer - 
14:19:01     INFO - TEST-INFO | started process screencapture
14:19:02     INFO - TEST-INFO | screencapture: exit 0
14:19:02     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | Last focused window has the correct id - Expected: -1, Actual: 3 - 
14:19:02     INFO - Stack trace:
14:19:02     INFO -     @moz-extension://9d435674-8f8a-4543-95d6-2af53c9a6429/%7B669ece7f-3467-d244-a1cf-cf410900d4b3%7D.js:30:7
14:19:02     INFO -     
14:19:02     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | Got focus change event for the correct window ID. - 
14:19:02     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | test result correct - 
14:19:02     INFO - Console message: Ignoring response to aborted listener for 1411-0
14:19:02     INFO - Console message: Ignoring response to aborted listener for 1412-0
14:19:02     INFO - Leaving test bound testWindowsEvents
14:19:02     INFO - GECKO(1810) | MEMORY STAT | vsize 5089MB | residentFast 1016MB | heapAllocated 331MB
14:19:02     INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_windows_events.js | took 3910ms
(Assignee)

Comment 1

a year ago
Looking at the previous failures, I can see that, when the test fails, we receive an onFocusChanged event with a windowId of browser.windows.WINDOW_ID_NONE when either the second window is closed or when the current window is re-focused after the second window has been closed. The logs do not tell us which of those two is the case.

I notice that there is already code in the test to ignore this extra onFocusChanged event when the test is run on Linux, so I wonder whether this is also happening sometimes on Mac and therefore should be ignored there as well. I am adding a patch that does that, which I suspect will fix the intermittent, but I'm not sure if this is the correct fix.

Does ignoring those firings of onFocusChanged in the test make sense, or is there a bug that needs to be fixed to prevent onFocusChanged from firing those events with a windowId of browser.windows.WINDOW_ID_NONE? If the former is true, then this patch should be sufficient.
Comment hidden (mozreview-request)
(Assignee)

Comment 3

a year ago
Can you please take a look and give me your opinion on the above, zombie?
Flags: needinfo?(tomica)
(Assignee)

Comment 4

a year ago
As a test I did submit this to try and re-triggered the tests that include this test about 20 times [1]. I'm not seeing any failures thus far.

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=e41df1b05730e4d711a3656c5356f00bde89e36e
I'm pretty sure this is a "good enough" fix for the intermittent.  The root of the problem is what I described in bug 1290057 comment 3:

> when switching between two Firefox windows, in the blur event callback, 
> neither of them has focus, so we end up sending a superfluous WINDOW_ID_NONE event

Which I tried to work around by waiting one event loop tick [1], which is not great, but works most of the time.  It's also depends on platform-specific event timings (and doesn't work on linux at all, just like in Chrome [2]).

So it's very likely that is what's happening on slower OSX debug builds: that tick isn't enough for the next event to happen and the other Firefox window to gain focus before we read `Services.focus.activeWindow`.

But looking at that test right now, I believe it could be improved, so I'll comment that in reviewboard.

1) http://searchfox.org/mozilla-central/source/browser/components/extensions/ext-windows.js#47-49
2) https://developer.chrome.com/extensions/windows#event-onFocusChanged
Flags: needinfo?(tomica)

Comment 6

a year ago
mozreview-review
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review154814

::: browser/components/extensions/test/browser/browser_ext_windows_events.js:23
(Diff revision 1)
> -      if (windowId === browser.windows.WINDOW_ID_NONE && os === "linux") {
> -        browser.test.log("Ignoring a superfluous WINDOW_ID_NONE (blur) event on Linux");
> +      if (windowId === browser.windows.WINDOW_ID_NONE && ["linux", "mac"].includes(os)) {
> +        browser.test.log("Ignoring a superfluous WINDOW_ID_NONE (blur) event on Linux and Mac");
>          return;
>        }

This is not great, as it could be ignoring any number of events with `windowId === -1`.  We should be more explicit, and (optionally) skip exactly one such event.

::: browser/components/extensions/test/browser/browser_ext_windows_events.js:35
(Diff revision 1)
>        let window = await browser.windows.getLastFocused();
>  
>        browser.test.assertEq(windowId, window.id,
>                              "Last focused window has the correct id");

I believe this check is wrong, or at least out of place here.

In the event callback, this is *asynchronously* asking for the "last focused window", and comparing that to the `windowId` received from the event (that happened in the past).  There is no guarantee that some other window didn't get focus in the mean time (or "NO WINDOW" as is the problem here).

I think this code should just send both window ids to the outside, where this check should be performed whenever the message is received (but see next comment).

::: browser/components/extensions/test/browser/browser_ext_windows_events.js:80
(Diff revision 1)
>    // This shouldn't be necessary, but tests intermittently fail, so let's give
>    // it a try.
>    win1.focus();
>  
>    let winId = await extension.awaitMessage(`window-focus-changed`);
>    is(winId, win1Id, "Got focus change event for the correct window ID.");

This is where we can explicitly ignore *one* event in case the `windowId` returned was -1.  Something simple like this should work:

    let winId = await extension.awaitMessage(`window-focus-changed`);
    if (winId === -1) {
      winId = await extension.awaitMessage(`window-focus-changed`);
    }
    is(winId, win1Id, "Got focus change event for the correct window ID.");
    ...
Comment hidden (mozreview-request)
(Assignee)

Comment 8

a year ago
mozreview-review-reply
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review154814

> I believe this check is wrong, or at least out of place here.
> 
> In the event callback, this is *asynchronously* asking for the "last focused window", and comparing that to the `windowId` received from the event (that happened in the past).  There is no guarantee that some other window didn't get focus in the mean time (or "NO WINDOW" as is the problem here).
> 
> I think this code should just send both window ids to the outside, where this check should be performed whenever the message is received (but see next comment).

I understand the problem you are describing, but I don't see how sending both window ids to the outside will help as we're still calculating them here. I must not be understanding this suggestion. I made the other fix to the test, but if this is still something you think needs to be addressed please let me know.

Comment 9

a year ago
mozreview-review-reply
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review154814

> I understand the problem you are describing, but I don't see how sending both window ids to the outside will help as we're still calculating them here. I must not be understanding this suggestion. I made the other fix to the test, but if this is still something you think needs to be addressed please let me know.

The difference is that the outer code "knows more", or has enough information to determine when it expects that check to hold.

The best that the current code can do is blindly "ignore any time you get -1", which is semantically wrong, and would not fail if we are sending multiple events in a row with windowId of -1.

The outer code has state, and knows when it can expect (an optional, exactly one) event with windowId of -1, and skip this check in that case.

Comment 10

a year ago
mozreview-review
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review157410

I don't think this is good without the second change I suggested.  I believe this will fail on linux, and intermittently on other platform (you can probably confirm that by removing the workaround Promise at [1]).  

1) http://searchfox.org/mozilla-central/source/browser/components/extensions/ext-windows.js#47-49
Attachment #8878572 - Flags: review?(tomica)
Comment hidden (mozreview-request)
(Assignee)

Comment 12

a year ago
mozreview-review-reply
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review157410

Thanks Tom. I have now fixed that issue.

Comment 13

a year ago
mozreview-review
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review157784

::: browser/components/extensions/test/browser/browser_ext_windows_events.js:54
(Diff revision 3)
>    });
>  
>    await extension.startup();
> -  await extension.awaitMessage("ready");
> +  const WINDOW_ID_NONE = await extension.awaitMessage("ready");
> +
> +  async function checkFocusChanged() {

nit: this is not only "checking", but also awaiting the event message(s), so perhaps a name that better reflects that?
Attachment #8878572 - Flags: review?(tomica) → review+
Comment hidden (mozreview-request)

Comment 15

a year ago
mozreview-review
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review157832

::: browser/components/extensions/test/browser/browser_ext_windows_events.js:32
(Diff revision 4)
>        browser.test.assertTrue(Number.isInteger(windowId),
>                                "windowId is an integer");
>  
>        let window = await browser.windows.getLastFocused();
>  
> -      browser.test.assertEq(windowId, window.id,
> +      browser.test.sendMessage(`window-focus-changed`, {winId: window.id, lastWindowId});

I'm confused here, these names appear reversed to me.  That is, `lastWindowId` is actually the id being passed to this listener and `winId` is the id of the last focused window.

::: browser/components/extensions/test/browser/browser_ext_windows_events.js:55
(Diff revision 4)
>  
>    await extension.startup();
> -  await extension.awaitMessage("ready");
> +  const WINDOW_ID_NONE = await extension.awaitMessage("ready");
> +
> +  async function awaitFocusChanged() {
> +    let windowInfo = await extension.awaitMessage(`window-focus-changed`);

Please just use regular double quotes here (and a few lines below)

::: browser/components/extensions/test/browser/browser_ext_windows_events.js:56
(Diff revision 4)
>    await extension.startup();
> -  await extension.awaitMessage("ready");
> +  const WINDOW_ID_NONE = await extension.awaitMessage("ready");
> +
> +  async function awaitFocusChanged() {
> +    let windowInfo = await extension.awaitMessage(`window-focus-changed`);
> +    if (windowInfo.winId === WINDOW_ID_NONE) {

Is this right?  `winId` is actually the result of `browser.windows.getLastFocused()`.  Checking `winId` seems logically right, but as mentioned in a previous comment, `winId` is actually something different here...
Attachment #8878572 - Flags: review?(aswan) → review-
Comment hidden (mozreview-request)

Comment 17

a year ago
mozreview-review
Comment on attachment 8878572 [details]
Bug 1373011 - Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js

https://reviewboard.mozilla.org/r/149898/#review158064
Attachment #8878572 - Flags: review?(aswan) → review+

Comment 18

a year ago
Pushed by bsilverberg@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8b52dd2ced93
Re-enable browser/components/extensions/test/browser/browser_ext_windows_events.js, r=aswan,zombie

Comment 19

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/8b52dd2ced93
Status: NEW → RESOLVED
Last Resolved: a year ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56

Updated

2 months ago
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.