650965 - permaorange: browser_addons.js | Addon element removed during uninstall

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Phil Ringnalda (:philor)]

Wasn't visible on Android until after bug 650578 let it get that far, but apparently has been happening all along on the hidden Maemo runs. During test 1, a restartless addon that's supposed to just get removed from the list instantly when it's uninstalled,

http://tinderbox.mozilla.org/showlog.cgi?log=Mobile/1303160034.1303160756.16951.gz#err0

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/mobile/chrome/browser_addons.js | Addon element removed during uninstall

Comment 1

[Wesley Johnston (:wesj)]

Attachment: Potential Fix

I'm not sure what the issue could be. Either list.removeChild(elt) is not blocking, or we are finding the item somewhere else in the list.

This just wraps in a setTimeout in case this is a race problem, but also adds some checks for the addon property on the element, which should not be present if it is in the search section (also added some logging so I can know if that is happening).

Comment 2

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 527803 [details] [diff] [review]
Potential Fix

> +                      close_manager(run_next_test);
> +                    }, 0)

Add a semicolon

Looks safe enough to try.

Comment 3

[Wesley Johnston (:wesj)]

http://hg.mozilla.org/mozilla-central/rev/9b17b766116d

Comment 4

[Phil Ringnalda (:philor)]

Sadly, that had no effect on it.

Comment 5

[Wesley Johnston (:wesj)]

Attachment: Potential Fix 2

We can try this. I'm also bumping the default max time we will wait in WaitFor and WaitForAndContinue because I'm suspicious that is our problem. Not a good solution by any means.

Comment 6

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 528354 [details] [diff] [review]
Potential Fix 2


>                     ExtensionsView.uninstall(elt);
>                     setTimeout(function() {
>                       elt = get_addon_element(aAddon.id);
>-                      ok(!elt || !elt.addon, "Addon element removed during uninstall");
>-                      if (elt && !elt.addon)
>-                        info("Element is still visible in search area");
>-                      Browser.closeTab(gCurrentTab);
>-                      close_manager(run_next_test);
>+                      waitForAndContinue(function() {
>+                        ok(!elt, "Addon element removed during uninstall");
>+                        Browser.closeTab(gCurrentTab);
>+                        close_manager(run_next_test);
>+                      }, function() { return !elt; });
>                     }, 0);

I think you can remove the setTimeout now

r+ with that change

Comment 7

[Wesley Johnston (:wesj)]

Attachment: Fix v2 for checkin

Whoops. Found another problem in this as well. We need to make sure we're querying for a new element each time in the waitFor test and callback.

Comment 8

[Wesley Johnston (:wesj)]

Pushed: http://hg.mozilla.org/mozilla-central/rev/19555867d9eb

I'll hold off on marking this again until we see results.

Comment 9

[Benjamin Stover (:stechz)]

Attachment: Permaorange, add logging for addons tests

Comment 10

[Benjamin Stover (:stechz)]

Perhaps the extension logging can enlighten us a little.

Comment 11

[Benjamin Stover (:stechz)]

Pushed http://hg.mozilla.org/mozilla-central/rev/e0a879ad7a4d

Comment 12

[Benjamin Stover (:stechz)]

Attachment: Permaorange, logging for Fennec's extension manager

Comment 13

[Wesley Johnston (:wesj)]

Comment on attachment 528984 [details] [diff] [review]
Permaorange, logging for Fennec's extension manager

Just to make sure its said, AddonLogging.jsm is already being pulled in by the ExtensionManager. But we should probably back this stuff out when done.

Comment 14

[Benjamin Stover (:stechz)]

Moar logging pooshed http://hg.mozilla.org/mozilla-central/rev/b7e0c1485f60

Comment 15

[Benjamin Stover (:stechz)]

Why not keep it? It won't be spammy by default and it could help us debug future issues.

Comment 16

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to comment #15)
> Why not keep it? It won't be spammy by default and it could help us debug
> future issues.

I'd rather back it out too.

Comment 17

[Wesley Johnston (:wesj)]

Attachment: Another attempt

Talked briefly to mfinkle about using "DOMNodeRemoved" events on IRC. This does that, but also has to include another setTimeout. The element is removed in the uninstall function, which in this case then calls our eventListener, who starts the next test before the uninstall function can finish, leading to a weird state. I'm not a fan of adding even more timeouts here, but we can try it...

Comment 18

[Wesley Johnston (:wesj)]

Attachment: Another attempt v2

Whoops. Left some crud in there.

Comment 19

[Benjamin Stover (:stechz)]

Attachment: Permaorange, log waitForAndContinue and more sanity checks

Comment 20

[Benjamin Stover (:stechz)]

Comment on attachment 529018 [details] [diff] [review]
Another attempt v2

This idea makes no sense to me. The node is removed synchronously in the uninstall function, and the logs have verified the correct branch is running. I think we want more logging (attached just a few seconds ago). Could it be that another node with this ID is somehow in the document? Perhaps it was added twice somehow?

If we do want to make sure the node is removed, I think DOMNodeRemoved is run synchronously, so the code in the event listener would run before anything after ExtensionsView.uninstall. This means you could just set a flag in the event listener and make sure it is set after the uninstall call.

Comment 21

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 529019 [details] [diff] [review]
Permaorange, log waitForAndContinue and more sanity checks

># HG changeset patch
># User Benjamin Stover <[e-mail]>
># Date 1304042685 25200
># Node ID 01060ee94522b884b400403282eb302e42313b95
># Parent  e6cca204fccc04451ff5f2b95de02a62b2783688
>Bug 650965 Permaorange, log waitForAndContinue and more sanity checks
>
>diff --git a/mobile/chrome/tests/browser_addons.js b/mobile/chrome/tests/browser_addons.js
>--- a/mobile/chrome/tests/browser_addons.js
>+++ b/mobile/chrome/tests/browser_addons.js
>@@ -357,39 +357,43 @@ function testPrompt(aTitle, aMessage, aB
>   }
> }
> 
> // Installs an addon via the urlbar.
> function installFromURLBar(aAddon) {
>   return function() {
>     loadUrl(gTestURL, function() {
>       loadUrl(aAddon.sourceURL, null, false);
>+      let elt = get_addon_element(aAddon.id);
>+      ok(!elt, "Addon element is not present before installation");
>       checkInstallAlert(true, function() {
>         checkDownloadNotification(function() {
>           checkInstallPopup(aAddon.name, function() {
>             checkInstallNotification(!aAddon.bootstrapped, function() {
>               open_manager(true, function() {
>                 isRestartShown(!aAddon.bootstrapped, false, function() {
>                   let elt = get_addon_element(aAddon.id);
>+                  info("elt.id is " + aAddon.id);
>                   if (aAddon.bootstrapped) {
>                     checkAddonListing(aAddon, elt, "local");
>                     var button = document.getAnonymousElementByAttribute(elt, "anonid", "uninstall-button");
>                     ok(!!button, "Extension has uninstall button");
> 
>                     var updateButton = document.getElementById("addons-update-all");
>                     is(updateButton.disabled, false, "Update button is enabled");
> 
>                     ExtensionsView.uninstall(elt);
>                     waitForAndContinue(function() {
>                       let elt = get_addon_element(aAddon.id);

let's add something to tell use where this element is located, if it exists:

  if (elt)
    info("unexpectedly found element in: " + elt.parentNode.id);

>                       ok(!elt, "Addon element removed during uninstall");
>                       Browser.closeTab(gCurrentTab);
>                       close_manager(run_next_test);
>                     }, function() {
>                       let elt = get_addon_element(aAddon.id);
>+                      info("Looking for element with id " + aAddon.id + ": " + elt);
>                       return !elt;
>                     });
>                   } else {
>                     ok(!elt, "Extension not in list");
>                     AddonManager.getAllInstalls(function(aInstalls) {
>                       for(var i = 0; i < aInstalls.length; i++) {
>                         aInstalls[i].cancel();
>                       }

Comment 22

[Benjamin Stover (:stechz)]

Pushed http://hg.mozilla.org/mozilla-central/rev/88d3c5bde0ba

Comment 23

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 529018 [details] [diff] [review]
Another attempt v2

I am not against using DOMNodeRemoved, but I agree with Ben about using the event handler to set a flag if the element with the right ID is removed. Then check the flag in the "continue" section

Comment 24

[Benjamin Stover (:stechz)]

http://tinderbox.mozilla.org/showlog.cgi?log=Mobile/1304047695.1304048666.29400.gz&fulltext=1#err0

My new theory is that this element is somehow getting added twice. Next step is probably logging when the addon is added to the DOM and see if the message occurs twice, and what the parent of the element is in waitForAndContinue.

Comment 25

[Wesley Johnston (:wesj)]

Attachment: Logg adding addons

More logging. Maybe we can watch when things are added to the list, and see if this is being added twice? I only see one place where we add items to the list.

Comment 26

[Wesley Johnston (:wesj)]

Attachment: Logg adding addons

This one should contain actual code.

Comment 27

[Wesley Johnston (:wesj)]

OK. So we are apparently adding this addon twice, and now I can reproduce! When we add the addon to the list, we watch for the install alert to be shown, but in my amazing smartness, I decided that on Android, where we can't see alerts, we should just skip ahead.

So on device we are showing the addon manager before the install finishes. We still shouldn't add the item if it has been added before:

http://mxr.mozilla.org/mobile-browser/source/chrome/content/extensions.js#922

but I suspect since we lazy load the addon manager (with a couple setTimeout 0's thrown in for good measure) the addon install finishes after we have the started creating the list, but before we have finished. Since there are no checks while we are making the list to make sure the addon doesn't already exist:

http://mxr.mozilla.org/mobile-browser/source/chrome/content/extensions.js#323

we happily add it twice.

Comment 28

[Wesley Johnston (:wesj)]

Attachment: Patch

OK. Lets try this. This implements two fixes:

1.) It checks in the AddonManager.getAddonsByTypes callback to make sure that any addons we are adding are not already in the list. If they are, it moves them to whatever position it was moving addons to. We could also fix this in addItem, but I'd like to catch any more mistakes I've made here.

2.) It fixes the test to use an AddonInstall listener to trigger opening the addons manager.

Also removed all the logging. This fixes things in my local tests. Need to write a separate test for this particular problem.

Comment 29

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 529761 [details] [diff] [review]
Patch


>       // the search-engine-modified observer in browser.js will take care of
>       // updating the list
>     } else {
>-      AddonLogger.log("Removing extension.");
> 
>       if (!aItem.addon) {

don't leave a blank line at the top of the block

r+ (fingers crossed)

Comment 30

[Wesley Johnston (:wesj)]

pushed: http://hg.mozilla.org/mozilla-central/rev/bed84d410802

Comment 31

[Wesley Johnston (:wesj)]

Filed Bug 654555 for the race condition test I need to write. Resolving this fixed.

Comment 32

[Andreea Pod]

Can this be marked as verified fixed?

Comment 33

[Dão Gottwald [:dao]]

bugspam

Comment 34

[Andreea Pod]

Marking this as verified fixed based on Thinderboxpuslog.