1392634 - Part of test runs out of sequence

Status: RESOLVED INVALID

(Testing :: Mochitest, enhancement)

Description

[Mike Kaply [:mkaply]]

I'm having a problem where part of a test runs out of sequence. Unfortunately the API is not in yet (because of failing test) but I'm hoping that there's something in the test/output that can help debug.

I'll be attaching the log and the test.

Comment 1

[Mike Kaply [:mkaply]]

Attachment: Log of test failure

There are two tests and I have put obvious places in the output to see the tests.

You can clearly see:

++++++++++ Beginning of FIRST test (test_user_changing_default_engine)

and

---------- End of FIRST test (test_user_changing_default_engine)

If you look before the end of the first test, you see this line:

ST - Default engine should be Google

This is from the second test. This happens even though you don't see

++++++++++ Beginning of SECOND test (test_two_addons_with_even_more_disabling)

until later on. It's really confusing.

I've tried using waitForExplicitFinish/finish and it had no effect.

Comment 2

[Mike Kaply [:mkaply]]

Attachment: The test file

This is the test file that was used to create that output.

Comment 3

[Shane Caraveo (:mixedpuppy)]

Comment on attachment 8899849 [details]
The test file

>/* -*- Mode: indent-tabs-mode: nil; js-indent-level: 2 -*- */
>/* vim: set sts=2 sw=2 et tw=80: */
>
>"use strict";
>
>XPCOMUtils.defineLazyGetter(this, "Management", () => {
>  const {Management} = Cu.import("resource://gre/modules/Extension.jsm", {});
>  return Management;
>});
>
>XPCOMUtils.defineLazyModuleGetter(this, "AddonManager",
>                                  "resource://gre/modules/AddonManager.jsm");
>
>const EXTENSION11_ID = "[e-mail]";
>const EXTENSION22_ID = "[e-mail]";
>const EXTENSION9_ID = "[e-mail]";
>
>function awaitEvent(eventName, id) {
>  return new Promise(resolve => {
>    let listener = (_eventName, ...args) => {
>      let extension = args[0];
>      if (_eventName === eventName &&
>          extension.id == id) {
>        Management.off(eventName, listener);
>        resolve(...args);
>      }
>    };
>
>    Management.on(eventName, listener);
>  });
>}
>
>add_task(async function test_user_changing_default_engine() {
>  Components.utils.reportError("++++++++++ Beginning of FIRST test (test_user_changing_default_engine)")

Use info(text)

>  is(defaultEngineName, defaultEngineName, "ST - Default engine should be " + defaultEngineName);

and again, info()
 
>  await ext1.startup();
>
>  is(Services.search.currentEngine.name, "Amazon.com", "ST - Default engine should be DuckDuckGo");

is(expect, got, message)
and elsewhere.

Why do none of the names in the message match?  I would expect to see:

is("Amazon.com", Services.search.currentEngine.name, "ST - Default engine should be Amazon");

This makes the test and logs confusing.

>  is(Services.search.currentEngine.name, defaultEngineName, "Default engine should be " + defaultEngineName);

`Default engine should be ${defaultEngineName}`

Comment 4

[Shane Caraveo (:mixedpuppy)]

reportError calls are probably not getting flushed as you expect.  Use the test logging functions (e.g. info or browser.test.log in browser pages).

My guess is that Bing was not removed in the first test somehow, and it is still in the chain of default engines.  So when you remove the two extensions in the second test, the default goes back to bing.  This would point to a problem with handling the non-webextension change to the default that you are testing here:

  let engine = Services.search.getEngineByName("Twitter");
  Services.search.currentEngine = engine;

  await ext1.unload();

  is(Services.search.currentEngine.name, "Twitter", "FT - Default engine should be Twitter");
  Services.search.currentEngine = Services.search.getEngineByName(defaultEngineName);


What is defaultEngineName?

Comment 5

[Mike Kaply [:mkaply]]

No, it's weirder than that. If you look in the log, you see that the first is() in the second test executed before the first test is actually finished.

I'm wondering if because tests run async, I should be doing all this stuff in one big test instead of doing lots of little tests?

Thanks for the other info. I'll clean that up.

> What is defaultEngineName?

I query it at the beginning. Then I make sure that when I'm done, it's the same as what I started with. That's actually the core of this problem. I query the engine at the beginning of the second test, but the engine is messed up by the first test while the second test is running.

The names don't match because I was testing out other engine names to see if it fixed my problems. I'll clean it up and repost a better version.

Comment 6

[Shane Caraveo (:mixedpuppy)]

What happens if you run it with --sequential?  Tasks can run at the same time IIUC, I'm not sure how the log output is handled in that case.

Comment 7

[Shane Caraveo (:mixedpuppy)]

sequential may only be xpcshell

Comment 8

[Mike Kaply [:mkaply]]

is(expect, got, message)

That's not what I'm seeing in the output.

For instance:

Default engine should be Twitter - Got Twitter, expected Google

for

is("Twitter", Services.search.currentEngine.name, "FT - Default engine should be Twitter");

that's

is(got, expect, message)


So what I've determined is the act of changing the engine for the user in the first test messes up the second test, even if I change it back. But it only happens on the first pass.

Comment 9

[Mike Kaply [:mkaply]]

Attachment: Updated/cleaned up test

Cleaned up the test.

Comment 10

[Mike Kaply [:mkaply]]

I think what I was seeing was a side effect of a bug in my code. I have everything working now.

Thanks for the debugging tips.