Closed Bug 950003 Opened 12 years ago Closed 11 years ago

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

Categories

(Mozilla QA Graveyard :: Mozmill Tests, defect, P3)

defect

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: andrei, Assigned: andrei)

References

()

Details

(Whiteboard: [mozmill-test-failure])

Attachments

(1 file, 1 obsolete file)

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)
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
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
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.
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.
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?
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?
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.
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+
> 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.
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)
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
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
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.
I can't reproduce this with the latest mozmill version.
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Resolution: --- → WORKSFORME
Product: Mozilla QA → Mozilla QA Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: