Closed Bug 1331313 Opened 3 years ago Closed 2 years ago

Intermittent test_addons.py TestAddons.test_install_and_remove_temporary_unsigned_addon | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)

Categories

(Testing :: Marionette, defect)

Version 3
defect
Not set

Tracking

(firefox57 fixed)

RESOLVED FIXED
mozilla57
Tracking Status
firefox57 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Something is wrong with the addon install method because it seems to return the wrong add-on id:

> 1484538708244	Marionette	TRACE	conn187 -> [0,7,"addon:install",{"path":"/builds/slave/test/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/mn-restartless-unsigned.xpi","temporary":true}]
> 1484538708431	Marionette	TRACE	conn187 <- [1,7,null,{"value":"gmp-gmpopenh264"}]

As you can see 'gmp-gmpopenh264' is returned for the call to install our test add-on. As such we are trying to remove it later and fail:

> 1484538708685	Marionette	TRACE	conn187 -> [0,12,"addon:uninstall",{"id":"gmp-gmpopenh264"}]
> 1484538708693	addons.manager	WARN	Exception calling callback: TypeError: addon.uninstall is not a function (chrome://marionette/content
hasnt been seen since march
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → WORKSFORME
This happened again:

[task 2017-08-17T21:15:04.344599Z] 21:15:04     INFO -  1503004504337	Marionette	TRACE	153 -> [0,6,"addon:install",{"path":"/home/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/webextension-unsigned.xpi","temporary":true}]
[task 2017-08-17T21:15:04.401752Z] 21:15:04     INFO -  1503004504394	Marionette	TRACE	153 <- [1,6,null,{"value":"gmp-gmpopenh264"}]

The code we have in Marionette looks fine. I wonder what could cause the Addon Manager to return the GMP plugin, instead of our installed addon.

https://dxr.mozilla.org/mozilla-central/rev/7dddbd85047c6dc73ddbe1e423cd643a217845b3/testing/marionette/addon.js#53-85

Dave, mind telling us who currently works on the Add-on Manager?
Status: RESOLVED → REOPENED
Flags: needinfo?(dtownsend)
Resolution: WORKSFORME → ---
Summary: Intermittent test_addons.py TestAddons.test_install_and_remove_temporary_unsigned_addon | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 60.0s) → Intermittent test_addons.py TestAddons.test_install_and_remove_temporary_unsigned_addon | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
Rhelmer might be able to help you
Flags: needinfo?(dtownsend) → needinfo?(rhelmer)
So presumably some other code is depending on the the addon ID that the promise your `addon.install` function resolves with?

The gecko media plugin add-ons get automatically installed shortly after startup, I suspect this install is racing yours and ends up resolving the promise first sometimes, since your listener doesn't check that it's the expected add-on ID.

if you want to ensure that your add-on is installed correctly then you can get it reliably from the AddonInstall object and compare that to the ID in the listener.

Although before you bother fixing the above, do you really need the non-temporary-install case? If not, `AddonManager.installTemporaryAddon()` returns a promise that resolves or rejects when the add-on is done installing, so you could just dispense with the listener code if you only care about temporary add-on installs.
Flags: needinfo?(rhelmer) → needinfo?(hskupin)
Good hint Robert! That indeed makes all sense. But one question remains. Yes, we need the non-temporary case still, so when I make use of `getInstallForFile` and its returned promise, would I still have to check for the addon id or would that be superfluous similar to `installTemporaryAddon`?
Flags: needinfo?(hskupin) → needinfo?(rhelmer)
(In reply to Henrik Skupin (:whimboo) from comment #9)
> Good hint Robert! That indeed makes all sense. But one question remains.
> Yes, we need the non-temporary case still, so when I make use of
> `getInstallForFile` and its returned promise, would I still have to check
> for the addon id or would that be superfluous similar to
> `installTemporaryAddon`?

For the non-temporary case you still need the listener, but you could get the expected ID from the install object the `getInstallForFile` returns (`install.addon.id`) and your listener could resolve the promise only if it matches that ID.
Flags: needinfo?(rhelmer)
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

Robert, does the following make sense to you? Same for uninstall, which we didn't handle correctly. Thanks.
Attachment #8900675 - Flags: feedback?(rhelmer)
Assignee: nobody → hskupin
Status: REOPENED → ASSIGNED
Attachment #8900675 - Flags: feedback?(rhelmer) → feedback+
lgtm - not set up to test locally but this looks like what I'd expect. Thanks!
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review177966

::: commit-message-c86b7:1
(Diff revision 2)
> +Bug 1331313 - Make installing and uninstalling of addons more reliable.

This isn’t a great one-line description of what it changes.

::: testing/marionette/addon.js:60
(Diff revision 2)
>      let file = new FileUtils.File(path);
>  
> -    let listener = {
> -      onInstallEnded(install, addon) {
> +    if (temporary) {
> +      AddonManager.installTemporaryAddon(file)
> +          .then(addon => resolve(addon.id))
> +          .catch(error => reject(error));

.catch(reject)

::: testing/marionette/addon.js:126
(Diff revision 2)
> -      resolve();
> +          resolve();
> +        }
> +      },
> +    };
> +
> +    AddonManager.addAddonListener(listener);

Is this removed if the addon fails to uninstall?

::: testing/marionette/addon.js:130
(Diff revision 2)
> +
> +    AddonManager.addAddonListener(listener);
> +
> +    AddonManager.getAddonByID(id)
> +        .then(addon => addon.uninstall())
> +        .catch(error => reject(error));

.catch(reject)

::: testing/marionette/harness/marionette_harness/tests/unit/test_addons.py:41
(Diff revision 2)
>              """)
>  
> -        return addons
> +        return set(addons)
> +
> +    def reset_addons(self):
> +        with self.marionette.using_context('chrome'):

Use double quotes consistently.

::: testing/marionette/harness/marionette_harness/tests/unit/test_addons.py:48
(Diff revision 2)
> +                addon_id = self.marionette.execute_async_script("""
> +                  Components.utils.import("resource://gre/modules/AddonManager.jsm");
> +                  return new Promise(resolve => {
> +                    AddonManager.getAddonByID(arguments[0], function(addon) {
> +                      addon.uninstall();
> +                      marionetteScriptFinished(addon.id);

Prefer arguments[arguments.length - 1] as the callback argument as
we want to get rid of marionetteScriptFinished at some point.

::: testing/marionette/harness/marionette_harness/tests/unit/test_addons.py:83
(Diff revision 2)
>  
>          self.addons.uninstall(addon_id)
>          self.assertNotIn(addon_id, self.all_addon_ids)
> +
> +    def test_install_invalid_addon(self):
> +        addon_path = os.path.join(here, 'webextension-invalid.xpi')

Use double quotes consistently.
Attachment #8900675 - Flags: review?(ato) → review+
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review177966

> .catch(reject)

Why? We want to know why this is failing and not completely hiding the error message.

> .catch(reject)

Same as above.

> Use double quotes consistently.

Most lines were copied from existing tests, so I missed to update that. Given that the file is small enough I will also update the existing code.

> Prefer arguments[arguments.length - 1] as the callback argument as
> we want to get rid of marionetteScriptFinished at some point.

Did you meant to add this comment for line 46? If not it's not clear to me. We should never return a value which we passed in here, but what the addon manager returned to us. Only that way we can check if the correct addon was actually uninstalled.

As what I see now is that I have to update this code to also take the listener and reject case into account.
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review177966

> Why? We want to know why this is failing and not completely hiding the error message.

How does .catch(reject) hide the error message?

> Did you meant to add this comment for line 46? If not it's not clear to me. We should never return a value which we passed in here, but what the addon manager returned to us. Only that way we can check if the correct addon was actually uninstalled.
> 
> As what I see now is that I have to update this code to also take the listener and reject case into account.

I meant this for the line it highlights, which is :48.  In my diff
viewer it looks like this:

> marionetteScriptFinished(addon.id);

Just one question, are we talking about the same thing?  I’m
referring to replacing marionetteScriptFinished with something along
the lines of:

> let done = arguments[arguments.length - 1];
> done(addon.id);

Or:

> arguments[1](addon.id);

Sorry if that was not clear.
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review177966

> How does .catch(reject) hide the error message?

Ok, that was a wrong assumption, but fact is whatever I have here we still throw a JS error in Marionette. This is not something which I want and which will be irritating. Given that we move forward with async I will implement these methods accordingly.

> I meant this for the line it highlights, which is :48.  In my diff
> viewer it looks like this:
> 
> > marionetteScriptFinished(addon.id);
> 
> Just one question, are we talking about the same thing?  I’m
> referring to replacing marionetteScriptFinished with something along
> the lines of:
> 
> > let done = arguments[arguments.length - 1];
> > done(addon.id);
> 
> Or:
> 
> > arguments[1](addon.id);
> 
> Sorry if that was not clear.

I'm not sure what all this is what you are proposing here, but I would really defer any of the changes to a bug which can cover all the usages of `marionetteScriptFinished()`, and this is clearly not this bug. Keep in mind that all the Marionette unit tests are using the above method to return the value.
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

Andreas, because of the refactoring for async/await I would like to see another review from you. I will also trigger a new try build now. Thanks.
Attachment #8900675 - Flags: review?(ato)
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review178670

With the latest change to use a mixture of promises and async in addon.install, I don’t understand what is going on anymore.  Specifically this construct is confusing:

> return await new Promise(…)

What are you trying to achieve here?

Using async/await makes sense for AddonManager.installTemporaryAddon because that returns a promise.  The non-temporary addon installation doesn’t, so you use a promise, which is the right way to solve this, but _mixing_ the two styles in the same function is highly confusing.  I would perhaps suggest extracting the non-temporary installation code to a separate function in addon.js and awaiting it the same way you do for temporary addons.
Attachment #8900675 - Flags: review+ → review-
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review178674
Attachment #8900675 - Flags: review?(ato) → review-
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review178670

This is code which is used a lot in our code base, so I don't see why this is problematic:
https://dxr.mozilla.org/mozilla-central/search?q=await+new+romise&redirect=false

The point is that `install` itself should ensure that it is a deterministic operation and returns a value which can directly be used. As such we have a clear API to the outside. Therefor I decided to return the addon id, and not force the caller to be async too to call `await` on `addon.install`.
Adding ni? for Andreas so we can clarify the last changes, and I can get this finished. Thanks.
Flags: needinfo?(ato)
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review178670

I still find your previous iteration on this patch cleaner.  The point is that you’re mixing the use of promises, callbacks, and awaiting async functions in the same function… inside the scope of a try…catch.  This is very challenging to read and I think it would beneficial to split it up into at least two different sub-functions so that the invocation from addon.install would be symmetric.

> Therefor I decided to return the addon id, and not force the caller to be async too to call await on addon.install.

The return value is still an async primitive.  You need Task.spawn to work around that.  The async return value gets passed from GeckoDriver#installAddon to server.TCPConnection#onPacket where "await this.execute(msg)" resolves it.
Flags: needinfo?(ato)
Comment on attachment 8900675 [details]
Bug 1331313 - Let add-on install() / uninstall() wait for the expected add-on.

https://reviewboard.mozilla.org/r/172108/#review181744

Much clearer now, thanks.
Attachment #8900675 - Flags: review?(ato) → review+
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cd25a0a7bcca
Let add-on install() / uninstall() wait for the expected add-on. r=ato
https://hg.mozilla.org/mozilla-central/rev/cd25a0a7bcca
Status: ASSIGNED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
You need to log in before you can comment on or make changes to this bug.