Closed Bug 944355 Opened 11 years ago Closed 9 years ago

Test failure "Window has been found" in "testUpdateNotAppliedAndDownloadComplete" (testFallbackUpdate/testUpdate.js)

Categories

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

Product:
Mozilla QA Graveyard
Component:
Mozmill Tests
Platform:
x86_64
Windows XP
Type:
defect

Tracking

(firefox29 wontfix, firefox30 wontfix, firefox31 wontfix, firefox32 affected, firefox33 affected, firefox34 affected, firefox-esr24 wontfix, firefox-esr31 affected)

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox29 --- wontfix
firefox30 --- wontfix
firefox31 --- wontfix
firefox32 --- affected
firefox33 --- affected
firefox34 --- affected
firefox-esr24 --- wontfix
firefox-esr31 --- affected

People

(Reporter: mario.garbi, Assigned: AndreeaMatei)

References

(
URL
)

Details

(Keywords: intermittent-failure, Whiteboard: [mozmill-test-failure][sprint][fixed by bug 599290])

Attachments

(1 file)

Jenkins console Log
14.68 KB, text/plain
Details 
Happened today with Mozmill 2.0 on Win 6.1.7601 (x86_64) with Firefox 27.0a2
http://mozmill-daily.blargon7.com/#/update/report/b99421c0f132c68dec1548288a407d97
What's the console output for this job? The dashboard details are not that helpful because of missing information. Please be really more verbose when you create bugs.
Flags: needinfo?(mario.garbi)
Attached file Jenkins console Log — 
Sorry, I will try to be more explicit next time. I will attach the console log to this bug and here is a code snippet of the part that failed:

04:09:00 TEST-START | test3.js | testFallbackUpdate_ErrorPatching
04:09:05 ERROR | Test Failure | {
04:09:05   "exception": {
04:09:05     "message": "Window has been found.", 
04:09:05     "lineNumber": 27, 
04:09:05     "name": "AssertionError", 
04:09:05     "fileName": "resource://mozmill/modules/errors.js"
04:09:05   }
Flags: needinfo?(mario.garbi)
We have only seen this one time yesterday and I cannot reproduce it locally.
Priority: -- → P4
This failed again with Aurora 29.0a2 on Holly branch on Windows xp mm-win-xp-32-3
I connected on the affected node and it reproduced 2 times of 2.

http://mozmill-crowd.blargon7.com/#/update/report/e35f22a68fec3f6d144713f9ab6cd691
http://mozmill-daily.blargon7.com/#/update/report/e35f22a68fec3f6d144713f9ab6976c6
Couldn't reproduce locally.
Will investigate on the affected machine.
Ehh, how did I miss this one when I filed the dupe...
This failed again with Aurora en-US on windows xp x86(mm-win-xp-32-4):
http://mozmill-daily.blargon7.com/#/update/report/6062fdddb60e88657bc78ec1f4297425

I tried to reproduce this right away, and it failed 3 times out of three, we fail in handling the window, as if you watch the tests running is clear that the window is there.
From what I've seen here the window appears _behind_ the main Firefox window when this happens.

Could it some focus issue?
This still fails, I tried to add a sleep after forcing the update to fallback in test2, also I added a timeout in handelWindow method in utils.js, but it seems now that the window never get's opened.
About which window we are talking about? The error window that the update was not successful? If that is true, which version has Firefox? Hat it been upgraded? If yes, our code to trigger a fallback is sometimes broken. Also it shouldn't matter where the window gets opened. It happens a lot in the background. So I don't think that is responsible for the failure.
Failed on windows 8.1 x64 too with Aurora en-US
http://mozmill-daily.blargon7.com/#/update/report/6062fdddb60e88657bc78ec1f46462dc
status-firefox29: --- → affected
OS: Windows 7 → All
Priority: P4 → P3
Failed again with Nightly en-US (20140322030204) on Windows XP 32 (mm-win-xp-32-4)
http://mozmill-daily.blargon7.com/#/update/report/97976110c92e838016d17f7fb217d5be
This affects esr24 too.
Failed with Firefox 24.5.0esrpre on windows 7 x64 (mm-win-7-64-1).
http://mozmill-daily.blargon7.com/#/update/report/44e0169acb64b68a44c1ad880b7f8bf8
status-firefox-esr24: --- → affected
Bumping to P2 since I've seen this fail on a daily (well, whenever we run update tests) basis.
status-firefox29: affected → wontfix
status-firefox32: --- → affected
Priority: P3 → P2
This is still failing, lets say "regularly":
Example: http://mozmill-daily.blargon7.com/#/update/report/2561af7d8c83a450772e8c4380154ae1

Still only XP seems to be affected.
status-firefox33: --- → affected
Here test1.js hasn't been executed. Does that apply to all those failures? If yes its the known mozmill problem.
(In reply to Henrik Skupin (:whimboo) from comment #23)
> Here test1.js hasn't been executed. Does that apply to all those failures?
> If yes its the known mozmill problem.

Its different, test1 is not reported in the dashboard because that's used just to set up some things. In investigating bug 972912 I came across this, and a workaround might be to set up a assert.ok() in these empty tests (I think we have a total of 2 or 3)
Ah I see. That's fine then. Maybe it would be good to rework the update tests now and make it a single test file. That might help us here, and for the upcoming changes on OS X.
+1 for a single test file.
This failed during Aurora update testing: "/testFallbackUpdate/test3.js 	testFallbackUpdate_ErrorPatching 	    Window has been found"

http://mozmill-daily.blargon7.com/#/update/report/12a8568e34c97b929089c7a61f97195b
status-firefox34: --- → affected
It seems this happens more often lately.
I remember being able to reproduce it first started failing. It was not a priority back then as it failed really rarely on production CI nodes.

I'll check if I can still reproduce the issue.
Flags: needinfo?(andrei.eftimie)
I couldn't reproduce this locally  I ran the update tests with the last affected build for 20 times but nothing.
Very important here is to check the application update log! There might be something which causes problems. Otherwise we should update the summary to reflect the new structure of the update tests. Something else which might be happening here, is that we might not correctly update the update status file. Perhaps we should add another assertion in the appropriate method to check that the change has been correctly written to disk.
(In reply to Henrik Skupin (:whimboo) from comment #33)
> Very important here is to check the application update log! There might be
> something which causes problems. Otherwise we should update the summary to
> reflect the new structure of the update tests. Something else which might be
> happening here, is that we might not correctly update the update status
> file. Perhaps we should add another assertion in the appropriate method to
> check that the change has been correctly written to disk.

While any of the above _might_ be the cause here, I strongly suspect there's another cause.

I remember we saw this fail the first time while when we switched to mozmill 2.0 last year.
And AFAIR I used to be able to reproduce this locally in Win VM (I can't remember the repro rate or any specific details).

The details were that when this failed, the old Software Update window would appear _behind_ the main Firefox window. I don't see how these are related, but as said in comment 31 I will try to see if I can still reproduce the issue, maybe more info will come out of that.

In regards to the update log, we're still plagued by bug 1008135 (missing update log on Win), so unfortunately this doesn't help us here :( (this issue is still assigned to me, but I haven't touched it in quite a while)
Summary: Test failure "Window has been found" in /testFallbackUpdate/test3.js → Test failure "Window has been found" in "testUpdateNotAppliedAndDownloadComplete" (testFallbackUpdate/testUpdate.js)
Well, I'm not able to reproduce the "Window has been found" issue locally:
http://mozmill-crowd.blargon7.com/#/update/reports?app=All&branch=35.0&platform=Win&from=2014-10-14&to=2014-10-14
Flags: needinfo?(andrei.eftimie)
This failed today for an update from  Firefox 31.0 lv on mm-win-7-64-3 (2014-10-31_09-04-22) to 31.0b5.

http://mozmill-release.blargon7.com/#/update/report/46dbc8f622b855f9ec017c8a602287a9

<updates><update type="minor" displayVersion="34.0 Beta 5" appVersion="34.0" platformVersion="34.0" buildID="20141030172027" detailsURL="https://www.mozilla.com/lv/firefox/34.0/releasenotes/"><patch type="complete" URL="http://download.mozilla.org/?product=firefox-34.0b5-complete&os=win&lang=lv&force=1" hashFunction="sha512" hashValue="bd82e2fefcf7a743a3c15393690edbaeb0fc2e31ae96114d1a2689d599100b38a90aa029749bfaebabced9ed42e7a3913be91d5fc45dff1d054db61a61f1fe02" size="48278468"/></update></updates>


In the console logs it looked like a timeout error:
09:08:56 TEST-START | testUpdate.js | testUpdateNotAppliedAndDownloadComplete
09:09:01 ERROR | Test Failure | {
09:09:01   "exception": {
09:09:01     "message": "Window has been found.", 
09:09:01     "lineNumber": 27, 
09:09:01     "name": "TimeoutError", 
09:09:01     "fileName": "resource://mozmill/modules/errors.js"
09:09:01   }
09:09:01 }
09:09:01 TEST-UNEXPECTED-FAIL | testUpdate.js | testUpdateNotAppliedAndDownloadComplete
This passed on a rebuild on beta-cdntest, but now that I'm running update tests on the beta channel it failed twice more.  Is it timing out becuase it can't find the build? Or just timing out for some other reason? I would love help in reading and interpreting these reports so that I can know what is useful for your debugging. 

http://mm-ci-master.qa.scl3.mozilla.com:8080/job/ondemand_update/102107/

the AUS snippets are,

https://aus3.mozilla.org/update/3/Firefox/30.0/20140527133511/WINNT_x86-msvc/ku/beta/Windows_NT%206.1/default/default/update.xml?force=1

<updates><update type="minor" displayVersion="34.0 Beta 5" appVersion="34.0" platformVersion="34.0" buildID="20141030172027" detailsURL="https://www.mozilla.com/ku/firefox/34.0/releasenotes/"><patch type="complete" URL="http://download.mozilla.org/?product=firefox-34.0b5-complete&os=win&lang=ku&force=1" hashFunction="sha512" hashValue="e02ed67254c6d371693cf758e42648fb25ac0d6c1c254ae8bfda6af5c5a87cc2a37e77f1f1d856cd64accab1e46b1c6358a1a45ba9736d25a47c2e0e63ab483d" size="47683983"/></update></updates>

and

https://aus3.mozilla.org/update/3/Firefox/34.0/20141030172027/WINNT_x86-msvc/ku/beta/Windows_NT%206.1/default/default/update.xml?force=1   (which is blank)
This failed today for Firefox 31.0 (31.0, pt-BR, 20140626181429): 

 http://mozmill-release.blargon7.com/#/update/report/1e5e44bea8f3e17708194a929a7677ee

and here is the console output:

07:51:16 TEST-START | testUpdate.js | testUpdateNotAppliedAndDownloadComplete
07:51:21 ERROR | Test Failure | {
07:51:21   "exception": {
07:51:21     "message": "Window has been found.", 
07:51:21     "lineNumber": 27, 
07:51:21     "name": "TimeoutError", 
07:51:21     "fileName": "resource://mozmill/modules/errors.js"
07:51:21   }
07:51:21 }
07:51:21 TEST-UNEXPECTED-FAIL | testUpdate.js | testUpdateNotAppliedAndDownloadComplete
And again for Firefox 30.0 (30.0, it, 20140527133511): http://mozmill-release.blargon7.com/#/update/report/1e5e44bea8f3e17708194a929a783126 

console:
07:54:10 TEST-START | testUpdate.js | testUpdateNotAppliedAndDownloadComplete
07:54:15 ERROR | Test Failure | {
07:54:15   "exception": {
07:54:15     "message": "Window has been found.", 
07:54:15     "lineNumber": 27, 
07:54:15     "name": "TimeoutError", 
07:54:15     "fileName": "resource://mozmill/modules/errors.js"
07:54:15   }
07:54:15 }
07:54:15 TEST-UNEXPECTED-FAIL | testUpdate.js | testUpdateNotAppliedAndDownloadComplete
Saw this again today with Firefox 34.0b8 update tests for win 32 ko. 

Mozmill ondemand_update testrun for Firefox 31.0 ko on mm-win-7-32-4 (2014-11-11_09-45-46) completed with  failures.


http://mm-ci-master.qa.scl3.mozilla.com:8080/job/ondemand_update/104721/

09:49:41 ERROR | Test Failure | {
09:49:41   "exception": {
09:49:41     "message": "Window has been found.", 
09:49:41     "lineNumber": 27, 
09:49:41     "name": "TimeoutError", 
09:49:41     "fileName": "resource://mozmill/modules/errors.js"
09:49:41   }
09:49:41 }
09:49:41 TEST-UNEXPECTED-FAIL | testUpdate.js | testUpdateNotAppliedAndDownloadComplete

and from http://mozmill-release.blargon7.com/#/update/report/b67428b6e502c230ff85b6a4c40712db
this was the post-update AUS snippet,
<updates><update type="minor" displayVersion="34.0 Beta 8" appVersion="34.0" platformVersion="34.0" buildID="20141110195804" detailsURL="https://www.mozilla.com/ko/firefox/34.0/releasenotes/"><patch type="complete" URL="http://download.mozilla.org/?product=firefox-34.0b8-complete&os=win&lang=ko&force=1" hashFunction="sha512" hashValue="8693e8ece4c54fc14b39fab628f11dbdb1038831e9bcc53f8215e1c21e1c56a1e0196c280e4d6e62d85c5c4c5dc8fa86fdc590bf713848d9e206a7c36551a58b" size="47669780"/></update></updates>

This test failed twice, but succeeded on the 3rd rebuild attempt.
In this step we are waiting for the software updater window, which should appear after a restart with the downloaded patch made invalid. As it looks like this does not happen all the time. It could have different reasons why it does not appear. The interesting fact is that the update has not been applied, so we seem to have made it invalid. But it's hard to predict where the problem is actually located.

I would propose that we add a check in the 2nd test to ensure that modifying the update.status file was successful. So we should read-back its content and assert it. If it fails we can be sure that this can cause the window not to appear. If we don't fail and the window does not appear, I would assume it is a bug in Firefox and happens under strange circumstances.
Assignee: nobody → andreea.matei
Status: NEW → ASSIGNED
Whiteboard: [mozmill-test-failure] → [mozmill-test-failure][sprint]
This will be fixed in bug 599290, see bug 599290 comment 115.
Depends on: 599290
The patch on bug 599290 landed. So closing as fixed.
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Whiteboard: [mozmill-test-failure][sprint] → [mozmill-test-failure][sprint][fixed by bug 599290]
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: