Test failure 'Notification popup visibility state has been changed' in /restartTests/testAddons_installMultipleExtensions/test1.js

RESOLVED WORKSFORME

Status

Mozilla QA
Mozmill Tests
P3
normal
RESOLVED WORKSFORME
5 years ago
4 years ago

People

(Reporter: Andrei Eftimie, Assigned: Andrei Eftimie)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [mozmill-test-failure], URL)

Attachments

(1 attachment, 1 obsolete attachment)

(Assignee)

Description

5 years ago
Module:    testInstallMultipleExtensions
Test:      /restartTests/testAddons_installMultipleExtensions/test1.js    
Failure:   Notification popup visibility state has been changed
Branches:  default (possibly all)
Platforms: Windows

This fails on a testrun with mozmill 2.x on Windows.
Does not fail when running the tests directly with mozmill.

Sample report:
http://mozmill-crowd.blargon7.com/#/functional/report/ca1869364f98dd0de71202e01e2131b8
I don't want to wait longer to get this fixed. So taking.
Assignee: nobody → hskupin
Status: NEW → ASSIGNED
I have seen this failure once this morning but I cannot reproduce it anymore now on Windows 7. Andrei, are you still able to?
Flags: needinfo?(andrei.eftimie)
(Assignee)

Comment 3

5 years ago
Yes:
http://mozmill-crowd.blargon7.com/#/functional/report/ca1869364f98dd0de71202e01e8cfed7

This only fails in a testrun, so it might again something we do not properly clean up.
On Windows 8.
Flags: needinfo?(andrei.eftimie)
Ok, so please take and fix it.
Assignee: hskupin → andrei.eftimie
Priority: -- → P1
(Assignee)

Comment 5

5 years ago
This is really strange.

I can only reproduce the failure when I run the testrun without specifying a local mozmill-tests repository.

So this fails:
> testrun_functional --report=http://mozmill-crowd.blargon7.com/db/ /c/Mozilla/Nightly/en-US/firefox/firefox.exe

But this doesn't fail:
> testrun_functional --repository=. --report=http://mozmill-crowd.blargon7.com/db/ /c/Mozilla/Nightly/en-US/firefox/firefox.exe

Where the repository is just-cloned from http://hg.mozilla.org/qa/mozmill-tests
(Assignee)

Comment 6

5 years ago
Found out why this is crashing.

Firefox is losing focus on that particular test.
If I manually click on the Firefox window at the right time, the test passes.

I also see the following log message:
> ProcessPriorityManager - InitProcessPriorityManager bailing due to prefs.
I have no idea if this is relevant at all.
(Assignee)

Comment 7

5 years ago
I can manually reproduce the exact same failure by running the affected tests directly with mozmill, and focusing another window (lets say the terminal where I am triggering the test from) just after the Firefox window opens.

I can reproduce this again on OSX, but I have to repeatedly (lots of clicking on another window) try losing Firefox the focus.

====

While running with a local repository I see the Firefox window (for the testAddons_installMultipleExtensions tests) starting in the background.

With the remote mozmill-tests repository the Firefox window is in the foreground.

I have no idea why these would be different.

====

Also to note that I see Firefox opening - apparently - random between top-most foreground window and in the terminal's background. Most tasks seem to work even if Firefox is not the top-most window.

Maybe the windows terminal is hijacking focus. And in this particular instance window.focus() is not enough.
(Assignee)

Comment 8

5 years ago
Well this is not directly related to the terminal as even with the terminal minimized Firefox still opens _sometimes_ (maybe 50% of the time) as not a top-most window, but behind 1 window I have open.

It doesn't which window that is.
(In reply to Andrei Eftimie from comment #6)
> Found out why this is crashing.

We have crashes? I wasn't aware of that. Please be more specific about that.

Otherwise do you have any further updates?
(Assignee)

Comment 10

5 years ago
Crash was not the word I should have used. "Failing"
Hi, I investigated this today and this is what I found:

* If I reduced the memory and the CPU of the VM it reproduced with a local repository intermittently.
* To reproduce the failure we can just run this directory and right after the test starts focus another application.

As a workaround if we do an controller.window.focus(); just before the assertion it will pass, even though the FF won't be brought in front.
As a conclusion of this, the FF loses focus. and the notification intend to appear but it won't.
If we add a sleep of few seconds and then focus the window, the notification will open right away.
So why do we loose focus? Which application has the focus? And how does this affect the focus test mode which gets enabled by Mozmill? Which versions of Firefox are affected?
(Assignee)

Comment 13

5 years ago
I've tried disabling focusmanager.testmode with the same results.
I've tried older Firefox versions with the same results.
This is fails even with mozmill 2.0.1

And some more tidbits:
https://github.com/mozilla/mozmill/blob/88e8bd691bd70bec4bc752af9ebb61dfaac2f50a/mozmill/mozmill/extension/resource/driver/mozmill.js#L159-L167

We *never* reach newBrowserController(). browserWindow always returns a chromeWindow object
I would have expected when we start a testrun and after we restart Firefox that we would get a new window with OpenBrowserWindow, but that appears not to be the case. Not sure if relevant.

We always run this.window.focus(); here: https://github.com/mozilla/mozmill/blob/e89223e10a8f5a5e7a73d5d4ac66e9ffb779aece/mozmill/mozmill/extension/resource/driver/controller.js#L253
But this doesn't appear to have any effect for this particular failure.

== 

I see Firefox behaving in the same way (Window flickering as it is in the background) but is still has that 'virtual' focus since other actions work fine and other tests are passing correctly.
Some notifications are only shown when Firefox is really in the foreground. So it might be an enhancement we need for the focusmanager test mode. For now we might have to set the focus explicitly.
(Assignee)

Comment 15

5 years ago
Created attachment 8349402 [details] [diff] [review]
0001-Bug-950003-Blured-the-hiddenDOMWindow-used-in-assert.patch

This apparently fixes the issue for me.

While trying to see where we lose focus, and making additional calls to window.focus() I noticed that we fail in a waitFor loop, and that we have a hiddenDOMWindow there.

I tried focusing the hiddenDOMWindow, and that would make _every_ occurrence to fail in a very similar way (and always opening Firefox in the background).
So it might be that this hidden window steals focus.

I'm a bit hindered in testing its effectiveness right now due to constant disconnects (see bug 951628).

But I do have a passing testrun:
http://mozmill-crowd.blargon7.com/#/functional/report/65853485b33d6c38cddef8e3363cb2ed
(There is a failure there, but it is not related, Firefox hung up, but the testrun resumed after a long waiting time)
Attachment #8349402 - Flags: feedback?(hskupin)
Attachment #8349402 - Flags: feedback?(dave.hunt)
Attachment #8349402 - Flags: feedback?(cosmin.malutan)
Comment on attachment 8349402 [details] [diff] [review]
0001-Bug-950003-Blured-the-hiddenDOMWindow-used-in-assert.patch

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

Looks good, and it fixes the problem. 
Great catch!
Attachment #8349402 - Flags: feedback?(cosmin.malutan) → feedback+
Comment on attachment 8349402 [details] [diff] [review]
0001-Bug-950003-Blured-the-hiddenDOMWindow-used-in-assert.patch

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

::: mozmill/mozmill/extension/resource/modules/assertions.js
@@ +587,5 @@
>        }
>      }
>  
>      var hwindow = Services.appShell.hiddenDOMWindow;
> +    hwindow.blur();

Which platforms are affected by this? Is it only Mac or Windows and Linux too? Not sure why the hidden window can steal the focus. Is it somewhat getting re-created? Can you see it in the logs when you enable all window listeners log output in mozmill? We might also want to ask Neil Deakin if he has an idea why that could happen.

We can go with that for now as a workaround but a bug should be filed to get this fixed. IMO refocusing should not happen in this case. Also make a comment for it in the code.
Attachment #8349402 - Flags: feedback?(hskupin)
Attachment #8349402 - Flags: feedback?(dave.hunt)
Attachment #8349402 - Flags: feedback+
(Assignee)

Comment 18

5 years ago
> Which platforms are affected by this? Is it only Mac or Windows and Linux
> too?
Only Windows appears to be affected.

> Not sure why the hidden window can steal the focus. Is it somewhat
> getting re-created? Can you see it in the logs when you enable all window
> listeners log output in mozmill?

I'll enable more logging to try identifying the real issue.
(Assignee)

Comment 19

5 years ago
Created attachment 8350004 [details] [diff] [review]
0001-Bug-950003-Blured-the-hiddenDOMWindow-used-in-assert.patch

Added a comment referencing this bug.

I'll post a bit later what useful information logging gives (if any)
Attachment #8349402 - Attachment is obsolete: true
Attachment #8350004 - Flags: review?(hskupin)
Attachment #8350004 - Flags: review?(dave.hunt)
(Assignee)

Comment 20

5 years ago
I hope this comment isn't too long.
I've left out parts which are the same in both cases [...]

Fail:
> *** 'beforeunload' event: id=8, baseURI=about:newtab
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{94eec12c-13f8-4790-a706-5414adc400a3}","valid":true},"id_load_handled":{"name":"","number":"{94eec12c-13f8-4790-a706-5414adc400a3}","valid":true}}}
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{9f60dd67-d308-49d6-98c1-b42f642dfc74}","valid":true},"id_load_handled":{"name":"","number":"{94eec12c-13f8-4790-a706-5414adc400a3}","valid":true}}}
> *** Page status updated: id=8, loaded=false, uuid={9f60dd67-d308-49d6-98c1-b42f642dfc74}
> ** Page has been finished loading: id=8, status=false, uuid={9f60dd67-d308-49d6-98c1-b42f642dfc74}
> TEST-START | restartTests\testAddons_installMultipleExtensions\test1.js | testInstallMultipleExtensions
> [...]
> *** Page status updated: id=16, loaded=false, uuid={040da6b1-42bb-45a8-92fb-a928f25faec8}
> *** 'outer-window-destroyed' observer notification: id=16
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3683cf57-c99b-4081-bfaa-a2ce85c907ad}","valid":true},"id_load_handled":{"name":"","number":"{3683cf57-c99b-4081-bfaa-a2ce85c907ad}","valid":true}}}
> ERROR | Test Failure | {
>   "exception": {
>     "message": "Notification popup visibility state has been changed",
>     "lineNumber": 27,
>     "name": "AssertionError",
>     "fileName": "resource://mozmill/modules/errors.js"
>   }
> }
> TEST-UNEXPECTED-FAIL | restartTests\testAddons_installMultipleExtensions\test1.js | testInstallMultipleExtensions
> TEST-START | restartTests\testAddons_installMultipleExtensions\test1.js | teardownModule
> TEST-END | restartTests\testAddons_installMultipleExtensions\test1.js | finished in 7395ms


Pass:
> TEST-START | restartTests\testAddons_installMultipleExtensions\test1.js | testInstallMultipleExtensions
> *** 'beforeunload' event: id=8, baseURI=about:newtab
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{6626f3c1-5a50-4aa2-97ac-13e41d9eb202}","valid":true},"id_load_handled":{"name":"","number":"{6626f3c1-5a50-4aa2-97ac-13e41d9eb202}","valid":true}}}
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{289a01a0-1774-436b-a053-dee65d22b906}","valid":true},"id_load_handled":{"name":"","number":"{6626f3c1-5a50-4aa2-97ac-13e41d9eb202}","valid":true}}}
> *** Page status updated: id=8, loaded=false, uuid={289a01a0-1774-436b-a053-dee65d22b906}
> ** Page has been finished loading: id=8, status=false, uuid={289a01a0-1774-436b-a053-dee65d22b906}
> [...]
> *** Page status updated: id=16, loaded=false, uuid={02845a75-6d76-499a-b5cc-0d5e19bde458}
> *** 'outer-window-destroyed' observer notification: id=16
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true},"id_load_handled":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true}}}
> *** 'beforeunload' event: id=8, baseURI=http://localhost:43336/addons/install.html?addon=extensions/empty.xpi
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true},"id_load_handled":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true}}}
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{f028dfcf-19f6-49eb-9d36-5efa7e071ae4}","valid":true},"id_load_handled":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true}}}
> *** Page status updated: id=8, loaded=false, uuid={f028dfcf-19f6-49eb-9d36-5efa7e071ae4}
> ** Page has been finished loading: id=8, status=false, uuid={f028dfcf-19f6-49eb-9d36-5efa7e071ae4}
> *** 'pagehide' event: id=8, baseURI=http://localhost:43336/addons/install.html?addon=extensions/empty.xpi
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{f028dfcf-19f6-49eb-9d36-5efa7e071ae4}","valid":true},"id_load_handled":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true}}}
> * current map: {"3":{"loaded":true},"8":{"loaded":false,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true}}}
> *** Page status updated: id=8, loaded=false, uuid={3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}
> *** 'DOMContentLoaded' event: id=8, baseURI=http://localhost:43336/addons/install.html?addon=extensions/icons.xpi
> *** 'pageshow' event: id=8, baseURI=http://localhost:43336/addons/install.html?addon=extensions/icons.xpi
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{22a5fb08-1ca0-4647-b882-e9cc7bf8a1f1}","valid":true}}}
> *** Page status updated: id=8, loaded=true, uuid={3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}}}
> ** Page has been finished loading: id=8, status=true, uuid={3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}
> *** 'load' event: id=25, baseURI=chrome://mozapps/content/xpinstall/xpinstallConfirm.xul
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}},"25":{"loaded":true}}
> *** 'pageshow' event: id=25, baseURI=chrome://mozapps/content/xpinstall/xpinstallConfirm.xul
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}},"25":{"loaded":true}}
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}},"25":{"loaded":true,"id_load_in_transition":{"name":"","number":"{9d3f10bc-8fec-4365-a0bc-c13728b21133}","valid":true}}}
> *** Page status updated: id=25, loaded=true, uuid={9d3f10bc-8fec-4365-a0bc-c13728b21133}
> *** 'beforeunload' event: id=25, baseURI=chrome://mozapps/content/xpinstall/xpinstallConfirm.xul
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}},"25":{"loaded":false,"id_load_in_transition":{"name":"","number":"{9d3f10bc-8fec-4365-a0bc-c13728b21133}","valid":true}}}
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}},"25":{"loaded":false,"id_load_in_transition":{"name":"","number":"{d6c16e59-fd11-4502-974b-4fad751fe22c}","valid":true}}}
> *** Page status updated: id=25, loaded=false, uuid={d6c16e59-fd11-4502-974b-4fad751fe22c}
> *** 'pagehide' event: id=25, baseURI=chrome://mozapps/content/xpinstall/xpinstallConfirm.xul
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}},"25":{"loaded":false,"id_load_in_transition":{"name":"","number":"{d6c16e59-fd11-4502-974b-4fad751fe22c}","valid":true}}}
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}},"25":{"loaded":false,"id_load_in_transition":{"name":"","number":"{4618c76f-c7ee-4b66-b7c9-0e8c6e8fa07d}","valid":true}}}
> *** Page status updated: id=25, loaded=false, uuid={4618c76f-c7ee-4b66-b7c9-0e8c6e8fa07d}
> *** 'outer-window-destroyed' observer notification: id=25
> * current map: {"3":{"loaded":true},"8":{"loaded":true,"id_load_in_transition":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true},"id_load_handled":{"name":"","number":"{3037d2b5-fd33-42b4-a171-b5ef41b9d6a2}","valid":true}}}
> TEST-PASS | restartTests\testAddons_installMultipleExtensions\test1.js | testInstallMultipleExtensions
> TEST-START | restartTests\testAddons_installMultipleExtensions\test1.js | teardownModule
> TEST-END | restartTests\testAddons_installMultipleExtensions\test1.js | finished in 4272ms
Depends on: 952125
Comment on attachment 8350004 [details] [diff] [review]
0001-Bug-950003-Blured-the-hiddenDOMWindow-used-in-assert.patch

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

We haven't seen this bug at all on our machines connected to the temporary CI today. So I'm not that inclined to take it for 2.0.3. It would need a better fix. The one attached here is not something I would like to land given that the assertion module has absolutely nothing to do with focus handling.
Attachment #8350004 - Flags: review?(hskupin)
Attachment #8350004 - Flags: review?(dave.hunt)
Attachment #8350004 - Flags: review-
Priority: P1 → P3
(Assignee)

Comment 23

5 years ago
Yes, I see it *every time* on a local Windows 8 VM.
It is good news that we don't see it in CI testruns at all.

There might be some environmental variables at play here.
(Assignee)

Comment 24

4 years ago
I can't reproduce this with the latest mozmill version.
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.