Bug 1097587 - UITour: Add some logging to ease debugging. r=Unfocused
authorMatthew Noorenberghe <mozilla@noorenberghe.ca>
Thu, 13 Nov 2014 19:22:53 +0100
changeset 231820 8b35d3ba140d75c881286468d733110402f0a454
parent 231819 af2a649a6d6bbdc1ff2f4b8ed93165c75912dcef
child 231821 7f0d92595432f9c0a8e83c21f7a7ed4bd43d2b9d
push id7326
push userbhearsum@mozilla.com
push dateFri, 28 Nov 2014 15:58:42 +0000
treeherdermozilla-aurora@d3a3b2a0f2f8 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersUnfocused
bugs1097587
milestone36.0a1
Bug 1097587 - UITour: Add some logging to ease debugging. r=Unfocused
browser/app/profile/firefox.js
browser/modules/UITour.jsm
--- a/browser/app/profile/firefox.js
+++ b/browser/app/profile/firefox.js
@@ -250,16 +250,17 @@ pref("extensions.{972ce4c6-7e08-4474-a28
 pref("extensions.{972ce4c6-7e08-4474-a285-3208198ce6fd}.description", "chrome://browser/locale/browser.properties");
 
 pref("lightweightThemes.update.enabled", true);
 pref("lightweightThemes.getMoreURL", "https://addons.mozilla.org/%LOCALE%/firefox/themes");
 pref("lightweightThemes.recommendedThemes", "[{\"id\":\"recommended-1\",\"homepageURL\":\"https://addons.mozilla.org/firefox/addon/a-web-browser-renaissance/\",\"headerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/1.header.jpg\",\"footerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/1.footer.jpg\",\"textcolor\":\"#000000\",\"accentcolor\":\"#f2d9b1\",\"iconURL\":\"resource:///chrome/browser/content/browser/defaultthemes/1.icon.jpg\",\"previewURL\":\"resource:///chrome/browser/content/browser/defaultthemes/1.preview.jpg\",\"author\":\"Sean.Martell\",\"version\":\"0\"},{\"id\":\"recommended-2\",\"homepageURL\":\"https://addons.mozilla.org/firefox/addon/space-fantasy/\",\"headerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/2.header.jpg\",\"footerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/2.footer.jpg\",\"textcolor\":\"#ffffff\",\"accentcolor\":\"#d9d9d9\",\"iconURL\":\"resource:///chrome/browser/content/browser/defaultthemes/2.icon.jpg\",\"previewURL\":\"resource:///chrome/browser/content/browser/defaultthemes/2.preview.jpg\",\"author\":\"fx5800p\",\"version\":\"1.0\"},{\"id\":\"recommended-3\",\"homepageURL\":\"https://addons.mozilla.org/firefox/addon/linen-light/\",\"headerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/3.header.png\",\"footerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/3.footer.png\",\"textcolor\":\"#None\",\"accentcolor\":\"#ada8a8\",\"iconURL\":\"resource:///chrome/browser/content/browser/defaultthemes/3.icon.png\",\"previewURL\":\"resource:///chrome/browser/content/browser/defaultthemes/3.preview.png\",\"author\":\"DVemer\",\"version\":\"1.0\"},{\"id\":\"recommended-4\",\"homepageURL\":\"https://addons.mozilla.org/firefox/addon/pastel-gradient/\",\"headerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/4.header.png\",\"footerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/4.footer.png\",\"textcolor\":\"#000000\",\"accentcolor\":\"#000000\",\"iconURL\":\"resource:///chrome/browser/content/browser/defaultthemes/4.icon.png\",\"previewURL\":\"resource:///chrome/browser/content/browser/defaultthemes/4.preview.png\",\"author\":\"darrinhenein\",\"version\":\"1.0\"},{\"id\":\"recommended-5\",\"homepageURL\":\"https://addons.mozilla.org/firefox/addon/carbon-light/\",\"headerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/5.header.png\",\"footerURL\":\"resource:///chrome/browser/content/browser/defaultthemes/5.footer.png\",\"textcolor\":\"#3b3b3b\",\"accentcolor\":\"#2e2e2e\",\"iconURL\":\"resource:///chrome/browser/content/browser/defaultthemes/5.icon.jpg\",\"previewURL\":\"resource:///chrome/browser/content/browser/defaultthemes/5.preview.jpg\",\"author\":\"Jaxivo\",\"version\":\"1.0\"}]");
 
 // UI tour experience.
 pref("browser.uitour.enabled", true);
+pref("browser.uitour.loglevel", "Error");
 pref("browser.uitour.requireSecure", true);
 pref("browser.uitour.themeOrigin", "https://addons.mozilla.org/%LOCALE%/firefox/themes/");
 pref("browser.uitour.pinnedTabUrl", "https://support.mozilla.org/%LOCALE%/kb/pinned-tabs-keep-favorite-websites-open");
 pref("browser.uitour.url", "https://www.mozilla.org/%LOCALE%/firefox/%VERSION%/tour/");
 
 pref("browser.customizemode.tip0.shown", false);
 pref("browser.customizemode.tip0.learnMoreUrl", "https://support.mozilla.org/1/firefox/%VERSION%/%OS%/%LOCALE%/customize");
 
--- a/browser/modules/UITour.jsm
+++ b/browser/modules/UITour.jsm
@@ -20,16 +20,18 @@ XPCOMUtils.defineLazyModuleGetter(this, 
 XPCOMUtils.defineLazyModuleGetter(this, "CustomizableUI",
   "resource:///modules/CustomizableUI.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "UITelemetry",
   "resource://gre/modules/UITelemetry.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "BrowserUITelemetry",
   "resource:///modules/BrowserUITelemetry.jsm");
 
 
+// See LOG_LEVELS in Console.jsm. Common examples: "All", "Info", "Warn", & "Error".
+const PREF_LOG_LEVEL      = "browser.uitour.loglevel";
 const PREF_SEENPAGEIDS    = "browser.uitour.seenPageIDs";
 const MAX_BUTTONS         = 4;
 
 const BUCKET_NAME         = "UITour";
 const BUCKET_TIMESTEPS    = [
   1 * 60 * 1000, // Until 1 minute after tab is closed/inactive.
   3 * 60 * 1000, // Until 3 minutes after tab is closed/inactive.
   10 * 60 * 1000, // Until 10 minutes after tab is closed/inactive.
@@ -37,16 +39,26 @@ const BUCKET_TIMESTEPS    = [
 ];
 
 // Time after which seen Page IDs expire.
 const SEENPAGEID_EXPIRY  = 8 * 7 * 24 * 60 * 60 * 1000; // 8 weeks.
 
 // Prefix for any target matching a search engine.
 const TARGET_SEARCHENGINE_PREFIX = "searchEngine-";
 
+// Create a new instance of the ConsoleAPI so we can control the maxLogLevel with a pref.
+XPCOMUtils.defineLazyGetter(this, "log", () => {
+  let ConsoleAPI = Cu.import("resource://gre/modules/devtools/Console.jsm", {}).ConsoleAPI;
+  let consoleOptions = {
+    // toLowerCase is because the loglevel values use title case to be compatible with Log.jsm.
+    maxLogLevel: Services.prefs.getCharPref(PREF_LOG_LEVEL).toLowerCase(),
+    prefix: "UITour",
+  };
+  return new ConsoleAPI(consoleOptions);
+});
 
 this.UITour = {
   url: null,
   seenPageIDs: null,
   pageIDSourceTabs: new WeakMap(),
   pageIDSourceWindows: new WeakMap(),
   /* Map from browser windows to a set of tabs in which a tour is open */
   originTabs: new WeakMap(),
@@ -136,16 +148,17 @@ this.UITour = {
     }],
     ["urlbar",      {
       query: "#urlbar",
       widgetName: "urlbar-container",
     }],
   ]),
 
   init: function() {
+    log.debug("Initializing UITour");
     // Lazy getter is initialized here so it can be replicated any time
     // in a test.
     delete this.seenPageIDs;
     Object.defineProperty(this, "seenPageIDs", {
       get: this.restoreSeenPageIDs.bind(this),
       configurable: true,
     });
 
@@ -219,99 +232,113 @@ this.UITour = {
     }
 
     Services.prefs.setCharPref(PREF_SEENPAGEIDS,
                                JSON.stringify([...this.seenPageIDs]));
   },
 
   onPageEvent: function(aMessage, aEvent) {
     let contentDocument = null;
-
     let browser = aMessage.target;
     let window = browser.ownerDocument.defaultView;
     let tab = window.gBrowser.getTabForBrowser(browser);
     let messageManager = browser.messageManager;
 
-    if (typeof aEvent.detail != "object")
+    log.debug("onPageEvent:", aEvent.detail);
+
+    if (typeof aEvent.detail != "object") {
+      log.warn("Malformed event - detail not an object");
       return false;
+    }
 
     let action = aEvent.detail.action;
-    if (typeof action != "string" || !action)
+    if (typeof action != "string" || !action) {
+      log.warn("Action not defined");
       return false;
+    }
 
     let data = aEvent.detail.data;
-    if (typeof data != "object")
+    if (typeof data != "object") {
+      log.warn("Malformed event - data not an object");
       return false;
+    }
 
     // Do this before bailing if there's no tab, so later we can pick up the pieces:
     window.gBrowser.tabContainer.addEventListener("TabSelect", this);
 
     if (!window.gMultiProcessBrowser) { // Non-e10s. See bug 1089000.
       contentDocument = browser.contentWindow.document;
       if (!tab) {
         // This should only happen while detaching a tab:
         if (this._detachingTab) {
+          log.debug("Got event while detatching a tab");
           this._queuedEvents.push(aEvent);
           this._pendingDoc = Cu.getWeakReference(contentDocument);
           return;
         }
-        Cu.reportError("Discarding tabless UITour event (" + action + ") while not detaching a tab." +
+        log.error("Discarding tabless UITour event (" + action + ") while not detaching a tab." +
                        "This shouldn't happen!");
         return;
       }
     }
 
     switch (action) {
       case "registerPageID": {
         // This is only relevant if Telemtry is enabled.
-        if (!UITelemetry.enabled)
+        if (!UITelemetry.enabled) {
+          log.debug("registerPageID: Telemery disabled, not doing anything");
           break;
+        }
 
         // We don't want to allow BrowserUITelemetry.BUCKET_SEPARATOR in the
         // pageID, as it could make parsing the telemetry bucket name difficult.
-        if (typeof data.pageID == "string" &&
-            !data.pageID.contains(BrowserUITelemetry.BUCKET_SEPARATOR)) {
-          this.addSeenPageID(data.pageID);
+        if (typeof data.pageID != "string" ||
+            data.pageID.contains(BrowserUITelemetry.BUCKET_SEPARATOR)) {
+          log.warn("registerPageID: Invalid page ID specified");
+          break;
+        }
+
+        this.addSeenPageID(data.pageID);
 
-          // Store tabs and windows separately so we don't need to loop over all
-          // tabs when a window is closed.
-          this.pageIDSourceTabs.set(tab, data.pageID);
-          this.pageIDSourceWindows.set(window, data.pageID);
+        // Store tabs and windows separately so we don't need to loop over all
+        // tabs when a window is closed.
+        this.pageIDSourceTabs.set(tab, data.pageID);
+        this.pageIDSourceWindows.set(window, data.pageID);
 
-          this.setTelemetryBucket(data.pageID);
-        }
+        this.setTelemetryBucket(data.pageID);
+
         break;
       }
 
       case "showHighlight": {
         let targetPromise = this.getTarget(window, data.target);
         targetPromise.then(target => {
           if (!target.node) {
-            Cu.reportError("UITour: Target could not be resolved: " + data.target);
+            log.error("UITour: Target could not be resolved: " + data.target);
             return;
           }
           let effect = undefined;
           if (this.highlightEffects.indexOf(data.effect) !== -1) {
             effect = data.effect;
           }
           this.showHighlight(target, effect);
-        }).then(null, Cu.reportError);
+        }).catch(log.error);
         break;
       }
 
       case "hideHighlight": {
         this.hideHighlight(window);
         break;
       }
 
       case "showInfo": {
         let targetPromise = this.getTarget(window, data.target, true);
         targetPromise.then(target => {
           if (!target.node) {
-            Cu.reportError("UITour: Target could not be resolved: " + data.target);
+            log.error("UITour: Target could not be resolved: " + data.target);
             return;
           }
 
           let iconURL = null;
           if (typeof data.icon == "string")
             iconURL = this.resolveURL(browser, data.icon);
 
           let buttons = [];
@@ -328,31 +355,33 @@ this.UITour = {
                 if (typeof buttonData.icon == "string")
                   button.iconURL = this.resolveURL(browser, buttonData.icon);
 
                 if (typeof buttonData.style == "string")
                   button.style = buttonData.style;
 
                 buttons.push(button);
 
-                if (buttons.length == MAX_BUTTONS)
+                if (buttons.length == MAX_BUTTONS) {
+                  log.warn("showInfo: Reached limit of allowed number of buttons");
                   break;
+                }
               }
             }
           }
 
           let infoOptions = {};
 
           if (typeof data.closeButtonCallbackID == "string")
             infoOptions.closeButtonCallbackID = data.closeButtonCallbackID;
           if (typeof data.targetCallbackID == "string")
             infoOptions.targetCallbackID = data.targetCallbackID;
 
           this.showInfo(messageManager, target, data.title, data.text, iconURL, buttons, infoOptions);
-        }).then(null, Cu.reportError);
+        }).catch(log.error);
         break;
       }
 
       case "hideInfo": {
         this.hideInfo(window);
         break;
       }
 
@@ -387,46 +416,50 @@ this.UITour = {
       case "hideMenu": {
         this.hideMenu(window, data.name);
         break;
       }
 
       case "startUrlbarCapture": {
         if (typeof data.text != "string" || !data.text ||
             typeof data.url != "string" || !data.url) {
+          log.warn("startUrlbarCapture: Text or URL not specified");
           return false;
         }
 
         let uri = null;
         try {
           uri = Services.io.newURI(data.url, null, null);
         } catch (e) {
+          log.warn("startUrlbarCapture: Malformed URL specified");
           return false;
         }
 
         let secman = Services.scriptSecurityManager;
         let principal = contentDocument.nodePrincipal;
         let flags = secman.DISALLOW_INHERIT_PRINCIPAL;
         try {
           secman.checkLoadURIWithPrincipal(principal, uri, flags);
         } catch (e) {
+          log.warn("startUrlbarCapture: Orginating page doesn't have permission to open specified URL");
           return false;
         }
 
         this.startUrlbarCapture(window, data.text, data.url);
         break;
       }
 
       case "endUrlbarCapture": {
         this.endUrlbarCapture(window);
         break;
       }
 
       case "getConfiguration": {
         if (typeof data.configuration != "string") {
+          log.warn("getConfiguration: No configuration option specified");
           return false;
         }
 
         this.getConfiguration(messageManager, window, data.configuration, data.callbackID);
         break;
       }
 
       case "showFirefoxAccounts": {
@@ -443,17 +476,17 @@ this.UITour = {
         break;
       }
 
       case "addNavBarWidget": {
         // Add a widget to the toolbar
         let targetPromise = this.getTarget(window, data.name);
         targetPromise.then(target => {
           this.addNavBarWidget(target, messageManager, data.callbackID);
-        }).then(null, Cu.reportError);
+        }).catch(log.error);
         break;
       }
     }
 
     if (!window.gMultiProcessBrowser) { // Non-e10s. See bug 1089000.
       if (!this.originTabs.has(window)) {
         this.originTabs.set(window, new Set());
       }
@@ -524,17 +557,17 @@ this.UITour = {
             }
             this.originTabs.get(window).add(selectedTab);
             this.pendingDoc = null;
             this._detachingTab = false;
             while (this._queuedEvents.length) {
               try {
                 this.onPageEvent(this._queuedEvents.shift());
               } catch (ex) {
-                Cu.reportError(ex);
+                log.error(ex);
               }
             }
             break;
           }
         }
 
         this.teardownTour(window);
         break;
@@ -578,16 +611,17 @@ this.UITour = {
   // can remain lazy-loaded on-demand.
   getTelemetry: function() {
     return {
       seenPageIDs: [...this.seenPageIDs.keys()],
     };
   },
 
   teardownTour: function(aWindow, aWindowClosing = false) {
+    log.debug("teardownTour: aWindowClosing = " + aWindowClosing);
     aWindow.gBrowser.tabContainer.removeEventListener("TabSelect", this);
     aWindow.PanelUI.panel.removeEventListener("popuphiding", this.hidePanelAnnotations);
     aWindow.PanelUI.panel.removeEventListener("ViewShowing", this.hidePanelAnnotations);
     aWindow.removeEventListener("SSWindowClosing", this);
 
     let originTabs = this.originTabs.get(aWindow);
     if (originTabs) {
       for (let tab of originTabs) {
@@ -622,18 +656,20 @@ this.UITour = {
   },
 
   // This function is copied to UITourListener.
   isSafeScheme: function(aURI) {
     let allowedSchemes = new Set(["https", "about"]);
     if (!Services.prefs.getBoolPref("browser.uitour.requireSecure"))
       allowedSchemes.add("http");
 
-    if (!allowedSchemes.has(aURI.scheme))
+    if (!allowedSchemes.has(aURI.scheme)) {
+      log.error("Unsafe scheme:", aURI.scheme);
       return false;
+    }
 
     return true;
   },
 
   resolveURL: function(aBrowser, aURL) {
     try {
       let uri = Services.io.newURI(aURL, null, aBrowser.currentURI);
 
@@ -643,27 +679,30 @@ this.UITour = {
       return uri.spec;
     } catch (e) {}
 
     return null;
   },
 
   sendPageCallback: function(aMessageManager, aCallbackID, aData = {}) {
     let detail = {data: aData, callbackID: aCallbackID};
+    log.debug("sendPageCallback", detail);
     aMessageManager.sendAsyncMessage("UITour:SendPageCallback", detail);
   },
 
   isElementVisible: function(aElement) {
     let targetStyle = aElement.ownerDocument.defaultView.getComputedStyle(aElement);
     return (targetStyle.display != "none" && targetStyle.visibility == "visible");
   },
 
   getTarget: function(aWindow, aTargetName, aSticky = false) {
+    log.debug("getTarget:", aTargetName);
     let deferred = Promise.defer();
     if (typeof aTargetName != "string" || !aTargetName) {
+      log.warn("getTarget: Invalid target name specified");
       deferred.reject("Invalid target name specified");
       return deferred.promise;
     }
 
     if (aTargetName == "pinnedTab") {
       deferred.resolve({
           targetName: aTargetName,
           node: this.ensurePinnedTab(aWindow, aSticky)
@@ -673,42 +712,44 @@ this.UITour = {
 
     if (aTargetName.startsWith(TARGET_SEARCHENGINE_PREFIX)) {
       let engineID = aTargetName.slice(TARGET_SEARCHENGINE_PREFIX.length);
       return this.getSearchEngineTarget(aWindow, engineID);
     }
 
     let targetObject = this.targets.get(aTargetName);
     if (!targetObject) {
+      log.warn("getTarget: The specified target name is not in the allowed set");
       deferred.reject("The specified target name is not in the allowed set");
       return deferred.promise;
     }
 
     let targetQuery = targetObject.query;
     aWindow.PanelUI.ensureReady().then(() => {
       let node;
       if (typeof targetQuery == "function") {
         try {
           node = targetQuery(aWindow.document);
         } catch (ex) {
+          log.warn("getTarget: Error running target query:", ex);
           node = null;
         }
       } else {
         node = aWindow.document.querySelector(targetQuery);
       }
 
       deferred.resolve({
         addTargetListener: targetObject.addTargetListener,
         node: node,
         removeTargetListener: targetObject.removeTargetListener,
         targetName: aTargetName,
         widgetName: targetObject.widgetName,
         allowAdd: targetObject.allowAdd,
       });
-    }).then(null, Cu.reportError);
+    }).catch(log.error);
     return deferred.promise;
   },
 
   targetIsInAppMenu: function(aTarget) {
     let placement = CustomizableUI.getPlacementOfWidget(aTarget.widgetName || aTarget.node.id);
     if (placement && placement.area == CustomizableUI.AREA_PANEL) {
       return true;
     }
@@ -724,41 +765,48 @@ this.UITour = {
              && targetElement.id != "PanelUI-button";
   },
 
   /**
    * Called before opening or after closing a highlight or info panel to see if
    * we need to open or close the appMenu to see the annotation's anchor.
    */
   _setAppMenuStateForAnnotation: function(aWindow, aAnnotationType, aShouldOpenForHighlight, aCallback = null) {
+    log.debug("_setAppMenuStateForAnnotation:", aAnnotationType);
+    log.debug("_setAppMenuStateForAnnotation: Menu is exptected to be:", aShouldOpenForHighlight ? "open" : "closed");
+
     // If the panel is in the desired state, we're done.
     let panelIsOpen = aWindow.PanelUI.panel.state != "closed";
     if (aShouldOpenForHighlight == panelIsOpen) {
+      log.debug("_setAppMenuStateForAnnotation: Panel already in expected state");
       if (aCallback)
         aCallback();
       return;
     }
 
     // Don't close the menu if it wasn't opened by us (e.g. via showmenu instead).
     if (!aShouldOpenForHighlight && !this.appMenuOpenForAnnotation.has(aAnnotationType)) {
+      log.debug("_setAppMenuStateForAnnotation: Menu not opened by us, not closing");
       if (aCallback)
         aCallback();
       return;
     }
 
     if (aShouldOpenForHighlight) {
       this.appMenuOpenForAnnotation.add(aAnnotationType);
     } else {
       this.appMenuOpenForAnnotation.delete(aAnnotationType);
     }
 
     // Actually show or hide the menu
     if (this.appMenuOpenForAnnotation.size) {
+      log.debug("_setAppMenuStateForAnnotation: Opening the menu");
       this.showMenu(aWindow, "appMenu", aCallback);
     } else {
+      log.debug("_setAppMenuStateForAnnotation: Closing the menu");
       this.hideMenu(aWindow, "appMenu");
       if (aCallback)
         aCallback();
     }
 
   },
 
   previewTheme: function(aTheme) {
@@ -865,16 +913,17 @@ this.UITour = {
         highlighter.style.borderRadius = "";
       }
 
       highlighter.style.height = highlightHeight + "px";
       highlighter.style.width = highlightWidth + "px";
 
       // Close a previous highlight so we can relocate the panel.
       if (highlighter.parentElement.state == "showing" || highlighter.parentElement.state == "open") {
+        log.debug("showHighlight: Closing previous highlight first");
         highlighter.parentElement.hidePopup();
       }
       /* The "overlap" position anchors from the top-left but we want to centre highlights at their
          minimum size. */
       let highlightWindow = aTarget.node.ownerDocument.defaultView;
       let containerStyle = highlightWindow.getComputedStyle(highlighter.parentElement);
       let paddingTopPx = 0 - parseFloat(containerStyle.paddingTop);
       let paddingLeftPx = 0 - parseFloat(containerStyle.paddingLeft);
@@ -885,18 +934,20 @@ this.UITour = {
                       - (Math.max(0, highlightWidthWithMin - targetRect.width) / 2);
       let offsetY = paddingLeftPx
                       - (Math.max(0, highlightHeightWithMin - targetRect.height) / 2);
       this._addAnnotationPanelMutationObserver(highlighter.parentElement);
       highlighter.parentElement.openPopup(highlightAnchor, "overlap", offsetX, offsetY);
     }
 
     // Prevent showing a panel at an undefined position.
-    if (!this.isElementVisible(aTarget.node))
+    if (!this.isElementVisible(aTarget.node)) {
+      log.warn("showHighlight: Not showing a highlight since the target isn't visible", aTarget);
       return;
+    }
 
     this._setAppMenuStateForAnnotation(aTarget.node.ownerDocument.defaultView, "highlight",
                                        this.targetIsInAppMenu(aTarget),
                                        showHighlightPanel.bind(this));
   },
 
   hideHighlight: function(aWindow) {
     let tabData = this.pinnedTabs.get(aWindow);
@@ -1084,17 +1135,17 @@ this.UITour = {
       }
       aWindow.PanelUI.show();
     } else if (aMenuName == "bookmarks") {
       let menuBtn = aWindow.document.getElementById("bookmarks-menu-button");
       openMenuButton(menuBtn);
     } else if (aMenuName == "searchEngines") {
       this.getTarget(aWindow, "searchProvider").then(target => {
         openMenuButton(target.node);
-      }).catch(Cu.reportError);
+      }).catch(log.error);
     }
   },
 
   hideMenu: function(aWindow, aMenuName) {
     function closeMenuButton(aMenuBtn) {
       if (aMenuBtn && aMenuBtn.boxObject)
         aMenuBtn.boxObject.openMenu(false);
     }
@@ -1126,17 +1177,17 @@ this.UITour = {
           // Since getTarget is async, we need to make sure that the target hasn't
           // changed since it may have just moved to somewhere outside of the app menu.
           if (annotationElement.getAttribute("targetName") != aTarget.targetName ||
               annotationElement.state == "closed" ||
               !UITour.targetIsInAppMenu(aTarget)) {
             return;
           }
           hideMethod(win);
-        }).then(null, Cu.reportError);
+        }).catch(log.error);
       }
     });
     UITour.appMenuOpenForAnnotation.clear();
   },
 
   recreatePopup: function(aPanel) {
     // After changing popup attributes that relate to how the native widget is created
     // (e.g. @noautohide) we need to re-create the frame/widget for it to take effect.
@@ -1198,26 +1249,27 @@ this.UITour = {
         break;
       case "appinfo":
         let props = ["defaultUpdateChannel", "version"];
         let appinfo = {};
         props.forEach(property => appinfo[property] = Services.appinfo[property]);
         this.sendPageCallback(aMessageManager, aCallbackID, appinfo);
         break;
       default:
-        Cu.reportError("getConfiguration: Unknown configuration requested: " + aConfiguration);
+        log.error("getConfiguration: Unknown configuration requested: " + aConfiguration);
         break;
     }
   },
 
   getAvailableTargets: function(aMessageManager, aChromeWindow, aCallbackID) {
     Task.spawn(function*() {
       let window = aChromeWindow;
       let data = this.availableTargetsCache.get(window);
       if (data) {
+        log.debug("getAvailableTargets: Using cached targets list", data.targets.join(","));
         this.sendPageCallback(aMessageManager, aCallbackID, data);
         return;
       }
 
       let promises = [];
       for (let targetName of this.targets.keys()) {
         promises.push(this.getTarget(window, targetName));
       }
@@ -1237,34 +1289,34 @@ this.UITour = {
       );
 
       data = {
         targets: targetNames,
       };
       this.availableTargetsCache.set(window, data);
       this.sendPageCallback(aMessageManager, aCallbackID, data);
     }.bind(this)).catch(err => {
-      Cu.reportError(err);
+      log.error(err);
       this.sendPageCallback(aMessageManager, aCallbackID, {
         targets: [],
       });
     });
   },
 
   addNavBarWidget: function (aTarget, aMessageManager, aCallbackID) {
     if (aTarget.node) {
-      Cu.reportError("UITour: can't add a widget already present: " + data.target);
+      log.error("UITour: can't add a widget already present: " + data.target);
       return;
     }
     if (!aTarget.allowAdd) {
-      Cu.reportError("UITour: not allowed to add this widget: " + data.target);
+      log.error("UITour: not allowed to add this widget: " + data.target);
       return;
     }
     if (!aTarget.widgetName) {
-      Cu.reportError("UITour: can't add a widget without a widgetName property: " + data.target);
+      log.error("UITour: can't add a widget without a widgetName property: " + data.target);
       return;
     }
 
     CustomizableUI.addWidgetToArea(aTarget.widgetName, CustomizableUI.AREA_NAVBAR);
     this.sendPageCallback(aMessageManager, aCallbackID);
   },
 
   _addAnnotationPanelMutationObserver: function(aPanelEl) {