940232 - Test failure "AddonsManager_isAddonInstalled: Add-on has been specified. - got 'undefined'" in /restartTests/testAddons_InstallAddonWithoutEULA/test2.js

Status: RESOLVED FIXED

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

Description

[Andrei Eftimie]

Module:    testInstallAddonWithEULA
Test:      restartTests/testAddons_InstallAddonWithoutEULA/test2.js    
Failure:   AddonsManager_isAddonInstalled: Add-on has been specified. - got 'undefined'
Branches:  default
Platforms: Windows 8

I have not been able to reproduce this failure.
Tried on Windows 8 and OSX

This has been run with Australis merged into Nightly.
That might be a possible cause.

Comment 1

[Andrei Eftimie]

I managed to reproduce this on Windows 8 (while running tests for mozmill 2.0.1)

The error I see has more context:

> *** ERROR addons.xpi: Failed to close file for c:\users\user\appdata\local\temp\tmp42izyv.mozrunner\extensions\staged\{8620c15f-30dc-4dba-a131-7c5d20cf4a29}\chrome\locale\en-US\variables.properties
> *** ERROR addons.xpi: extractFilesAsync: failed to extract file c:\users\user\appdata\local\temp\tmp42izyv.mozrunner\extensions\staged\{8620c15f-30dc-4dba-a131-7c5d20cf4a29}\chrome\locale\en-US\variables.properties: Error: OS.File has been shut down. (resource://gre/modules/osfile/osfile_async_front.jsm:123)
> TEST-START | restartTests\testAddons_InstallAddonWithoutEULA\test2.js | setupModule
> TEST-START | restartTests\testAddons_InstallAddonWithoutEULA\test2.js | testInstallAddonWithEULA
> ERROR | Test Failure | {
>   "exception": {
>     "message": "AddonsManager_isAddonInstalled: Add-on has been specified. - got 'undefined'",
>     "lineNumber": 349,
>     "name": "Error",
>     "fileName": "file:///c:/work/bugs/temp/mozmill-tests/lib/addons.js"
>   }
> }
> TEST-UNEXPECTED-FAIL | restartTests\testAddons_InstallAddonWithoutEULA\test2.js | testInstallAddonWithEULA

Comment 2

[Andrei Eftimie]

I also see this on OSX with mozmill 2.0
All the time
> *** ERROR addons.xpi: extractFilesAsync: failed to extract file /var/folders/9l/sn_p3bw914s360j602z20jsc0000gq/T/tmpZu6xWl.mozrunner/extensions/staged/{8620c15f-30dc-4dba-a131-7c5d20cf4a29}/components/aboutNightly.js: Error: OS.File has been shut down. (resource://gre/modules/osfile/osfile_async_front.jsm:123)

Same error, reproducible.
Looks Australis related.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Please test with a build from the holly branch to be fully sure.

Comment 4

[Andrei Eftimie]

This is not Australis related.
I'll come with a regression range

Comment 5

[Andrei Eftimie]

This is an interesting failure.

This would fail every time while I used newer builds.
Once I used an older build that passed the test, I wasn't able to reproduce the issue even on the build that previously failed every time.

After a long while, older builds would fail again. But again, after successfully passing the test on an older build, I can't reproduce it anymore.

I'd blame some sort of caching for this inconsistency, but it is too early to tell.
But the failure announces a file in a tmp folder which shouldn't get used again.

Ugh

Comment 6

[Andrei Eftimie]

mozilla-central pushlog would be:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=f003c386c77a&tochange=9e571ad29946

And cross-examining the pushlog and commits done to the file mentioned in the error message
(resource://gre/modules/osfile/osfile_async_front.jsm) makes a likely contender:
http://hg.mozilla.org/mozilla-central/rev/8898b6c66941

Which adds lz4 (probably not this) _and_ async file read.

**
I seem to have better results (in getting the test to fail) with running the affected test right after completely clearing the browser cache.

Comment 7

[Andrei Eftimie]

I read the code wrong, it doesn't really seem to be async support in the above mentioned commit.
I'll dig deeper into our code.

Comment 8

[Andrei Eftimie]

Found something similar (if not the same issue) in bug 932361

Comment 9

[Andrei Eftimie]

Erm bug 932361 also landed on the 8th November on mozilla-central, and it changed how XPI's get unzipped/installed (which is where we apparentlyfail).
This looks more plausible.

I'll probably need to build FF to test this, there are no tinderbox builds

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Andrei Eftimie from comment #9)
> I'll probably need to build FF to test this, there are no tinderbox builds

Why that? I see a lot of tinderbox builds at this time in the archive:
http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/

Blair, do you have an idea what could be the cause of this problem?

Comment 11

[Andrei Eftimie]

I don't know why I thought that we had no tinderbox builds directly in mozilla-central.

Well, here is a pushlog from the aforementioned builds:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=a6e7f0663458&tochange=361a24da7112

And we do have bug 932361 with 
http://hg.mozilla.org/mozilla-central/rev/38b01389507d in there.

Dave or Blair, do you any insight on the cause of this problem?

Comment 12

[Dave Townsend [:mossop]]

The message "Error: OS.File has been shut down" suggests that something is trying to install an extension after the application has started closing

Comment 13

[Andreea Matei [:AndreeaMatei]]

How often is this? We might want a skip patch.

Comment 14

[Blair McBride [:Unfocused] (UNAVAILABLE)]

I suspect what's happening is that the test has been making an assumption that that part of the install is synchronous - so it requests a add-on be installed, then *immediately* checks if the add-on is installed and shuts down. Meanwhile, the install is still happening in the background - which leads to the error mentioned in comment 12.

We should probably handle that case better in the Add-on Manager code (filed bug 942661), but it won't actually fix the test here.

Comment 15

[mario garbi]

Happend just now with the Mozmill 2.0 run on Mac OS X 10.6.8 (x86_64) with Firefox 27.0a2 en-US:
http://mozmill-daily.blargon7.com/#/remote/report/b99421c0f132c68dec1548288a3aa900
http://mozmill-daily.blargon7.com/#/remote/report/b99421c0f132c68dec1548288a3a7201

Comment 16

[Cosmin Malutan, [:cosmin-malutan]]

This fails due to asynchronously installation of addons, and because we don't wait for installation to complete, and and we restart the firefox after we hit the install button. I made a fix patch, and I will be back with reports soon.

Comment 17

[Cosmin Malutan, [:cosmin-malutan]]

Attachment: patch_v1.0

Reports:
http://mozmill-crowd.blargon7.com/#/functional/report/b99421c0f132c68dec1548288a47cf8b
http://mozmill-crowd.blargon7.com/#/functional/report/b99421c0f132c68dec1548288a47c6e7
http://mozmill-crowd.blargon7.com/#/functional/report/b99421c0f132c68dec1548288a47e7bc

Comment 18

[Andreea Matei [:AndreeaMatei]]

Comment on attachment 8339917 [details] [diff] [review]
patch_v1.0

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

This seems right to me. Please check other test in which we do the same to make the same change.
http://hg.mozilla.org/qa/mozmill-tests/rev/0c92878da7c5 (default)

Comment 19

[Cosmin Malutan, [:cosmin-malutan]]

I haven't seen any other so far, the aurora branch is affected and the patch applies, we don't have the test on other branches.

Comment 20

[Andrei Eftimie]

Transplanted:
http://hg.mozilla.org/qa/mozmill-tests/rev/bfe15fa3ab7a (mozilla-aurora)

We should be good here.