Bug 1264717 - Part 1 - Add some debug logging to the session store. r=margaret draft
authorJan Henning <jh+bugzilla@buttercookie.de>
Mon, 18 Apr 2016 20:59:50 +0200
changeset 352764 e31636f70c29c0fb0a3645025364109d9a5d4e7d
parent 352763 fcbad75814a212576cc11c629463e83dc9ca594c
child 518735 d8ebe8e24b4a115e2243ec4a4a640e2f329a239b
push id15788
push usermozilla@buttercookie.de
push dateMon, 18 Apr 2016 19:07:59 +0000
reviewersmargaret
bugs1264717
milestone48.0a1
Bug 1264717 - Part 1 - Add some debug logging to the session store. r=margaret The logging can be enabled by setting "browser.sessionstore.debug_logging" in about:config. MozReview-Commit-ID: DCJevcsg549
mobile/android/app/mobile.js
mobile/android/components/SessionStore.js
--- a/mobile/android/app/mobile.js
+++ b/mobile/android/app/mobile.js
@@ -134,16 +134,17 @@ pref("browser.sessionhistory.contentView
 /* session store */
 pref("browser.sessionstore.resume_session_once", false);
 pref("browser.sessionstore.resume_from_crash", true);
 pref("browser.sessionstore.interval", 10000); // milliseconds
 pref("browser.sessionstore.max_tabs_undo", 5);
 pref("browser.sessionstore.max_resumed_crashes", 1);
 pref("browser.sessionstore.recent_crashes", 0);
 pref("browser.sessionstore.privacy_level", 0); // saving data: 0 = all, 1 = unencrypted sites, 2 = never
+pref("browser.sessionstore.debug_logging", false);
 
 /* these should help performance */
 pref("mozilla.widget.force-24bpp", true);
 pref("mozilla.widget.use-buffer-pixmap", true);
 pref("mozilla.widget.disable-native-theme", true);
 pref("layout.reflow.synthMouseMove", false);
 pref("layout.css.report_errors", false);
 
--- a/mobile/android/components/SessionStore.js
+++ b/mobile/android/components/SessionStore.js
@@ -11,21 +11,31 @@ Cu.import("resource://gre/modules/XPCOMU
 Cu.import("resource://gre/modules/Services.jsm");
 
 XPCOMUtils.defineLazyModuleGetter(this, "Task", "resource://gre/modules/Task.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "OS", "resource://gre/modules/osfile.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "Messaging", "resource://gre/modules/Messaging.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "PrivateBrowsingUtils", "resource://gre/modules/PrivateBrowsingUtils.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "FormData", "resource://gre/modules/FormData.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "TelemetryStopwatch", "resource://gre/modules/TelemetryStopwatch.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "Log", "resource://gre/modules/AndroidLog.jsm", "AndroidLog");
 
 function dump(a) {
   Services.console.logStringMessage(a);
 }
 
+let loggingEnabled = false;
+
+function log(a) {
+  if (!loggingEnabled) {
+    return;
+  }
+  Log.d("SessionStore", a);
+}
+
 // -----------------------------------------------------------------------
 // Session Store
 // -----------------------------------------------------------------------
 
 const STATE_STOPPED = 0;
 const STATE_RUNNING = 1;
 
 const PRIVACY_NONE = 0;
@@ -51,16 +61,18 @@ SessionStore.prototype = {
   // The index where the most recently closed tab was in the tabs array
   // when it was closed.
   _lastClosedTabIndex: -1,
 
   // Whether or not to send notifications for changes to the closed tabs.
   _notifyClosedTabs: false,
 
   init: function ss_init() {
+    loggingEnabled = Services.prefs.getBoolPref("browser.sessionstore.debug_logging");
+
     // Get file references
     this._sessionFile = Services.dirsvc.get("ProfD", Ci.nsILocalFile);
     this._sessionFileBackup = this._sessionFile.clone();
     this._sessionFile.append("sessionstore.js");
     this._sessionFileBackup.append("sessionstore.bak");
 
     this._loadState = STATE_STOPPED;
 
@@ -122,16 +134,17 @@ SessionStore.prototype = {
         Services.obs.notifyObservers(null, "sessionstore-state-purge-complete", "");
         if (this._notifyClosedTabs) {
           this._sendClosedTabsToJava(Services.wm.getMostRecentWindow("navigator:browser"));
         }
         break;
       case "timer-callback":
         // Timer call back for delayed saving
         this._saveTimer = null;
+        log("timer-callback, pendingWrite = " + this._pendingWrite);
         if (this._pendingWrite) {
           this.saveState();
         }
         break;
       case "Session:Restore": {
         Services.obs.removeObserver(this, "Session:Restore");
         if (aData) {
           // Be ready to handle any restore failures by making sure we have a valid tab opened
@@ -170,16 +183,17 @@ SessionStore.prototype = {
         }
         break;
       }
       case "application-background":
         // We receive this notification when Android's onPause callback is
         // executed. After onPause, the application may be terminated at any
         // point without notice; therefore, we must synchronously write out any
         // pending save state to ensure that this data does not get lost.
+        log("application-background");
         this.flushPendingState();
         break;
       case "ClosedTabs:StartNotifications":
         this._notifyClosedTabs = true;
         this._sendClosedTabsToJava(Services.wm.getMostRecentWindow("navigator:browser"));
         break;
       case "ClosedTabs:StopNotifications":
         this._notifyClosedTabs = false;
@@ -199,69 +213,77 @@ SessionStore.prototype = {
     }
   },
 
   handleEvent: function ss_handleEvent(aEvent) {
     let window = aEvent.currentTarget.ownerDocument.defaultView;
     switch (aEvent.type) {
       case "TabOpen": {
         let browser = aEvent.target;
+        log("TabOpen for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         this.onTabAdd(window, browser);
         break;
       }
       case "TabClose": {
         let browser = aEvent.target;
+        log("TabClose for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         this.onTabClose(window, browser, aEvent.detail);
         this.onTabRemove(window, browser);
         break;
       }
       case "TabPreZombify": {
         let browser = aEvent.target;
+        log("TabPreZombify for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         this.onTabRemove(window, browser, true);
         break;
       }
       case "TabPostZombify": {
         let browser = aEvent.target;
+        log("TabPostZombify for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         this.onTabAdd(window, browser, true);
         break;
       }
       case "TabSelect": {
         let browser = aEvent.target;
+        log("TabSelect for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         this.onTabSelect(window, browser);
         break;
       }
       case "DOMTitleChanged": {
         let browser = aEvent.currentTarget;
 
         // Handle only top-level DOMTitleChanged event
         if (browser.contentDocument !== aEvent.originalTarget) {
           return;
         }
 
         // Use DOMTitleChanged to detect page loads over alternatives.
         // onLocationChange happens too early, so we don't have the page title
         // yet; pageshow happens too late, so we could lose session data if the
         // browser were killed.
+        log("DOMTitleChanged for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         this.onTabLoad(window, browser);
         break;
       }
       case "load": {
         // Handle restoring the text data into the content and frames. We wait
         // until the main content and all frames are loaded before trying to
         // restore the text data.
         let browser = aEvent.currentTarget;
+        log("load for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         if (browser.__SS_restore_text_data) {
           this._restoreTextData(browser.__SS_data.formdata, browser);
         }
         break;
       }
       case "change":
       case "input":
       case "DOMAutoComplete": {
         let browser = aEvent.currentTarget;
+        log("TabInput for tab " + window.BrowserApp.getTabForBrowser(browser).id);
         this.onTabInput(window, browser);
         break;
       }
     }
   },
 
   onWindowOpen: function ss_onWindowOpen(aWindow) {
     // Return if window has already been initialized
@@ -336,37 +358,43 @@ SessionStore.prototype = {
     // Use load to restore text data
     aBrowser.addEventListener("load", this, true);
 
     // Use a combination of events to watch for text data changes
     aBrowser.addEventListener("change", this, true);
     aBrowser.addEventListener("input", this, true);
     aBrowser.addEventListener("DOMAutoComplete", this, true);
 
+    log("onTabAdd() ran for tab " + aWindow.BrowserApp.getTabForBrowser(aBrowser).id +
+        ", aNoNotification = " + aNoNotification);
     if (!aNoNotification) {
       this.saveStateDelayed();
     }
     this._updateCrashReportURL(aWindow);
   },
 
   onTabRemove: function ss_onTabRemove(aWindow, aBrowser, aNoNotification) {
     // Cleanup event listeners
     aBrowser.removeEventListener("DOMTitleChanged", this, true);
     aBrowser.removeEventListener("load", this, true);
     aBrowser.removeEventListener("change", this, true);
     aBrowser.removeEventListener("input", this, true);
     aBrowser.removeEventListener("DOMAutoComplete", this, true);
 
+    let tabId = aWindow.BrowserApp.getTabForBrowser(aBrowser).id;
+
     // If this browser is being restored, skip any session save activity
     if (aBrowser.__SS_restore) {
+      log("onTabRemove() ran for zombie tab " + tabId + ", aNoNotification = " + aNoNotification);
       return;
     }
 
     delete aBrowser.__SS_data;
 
+    log("onTabRemove() ran for tab " + tabId + ", aNoNotification = " + aNoNotification);
     if (!aNoNotification) {
       this.saveStateDelayed();
     }
   },
 
   onTabClose: function ss_onTabClose(aWindow, aBrowser, aTabIndex) {
     if (this._maxTabsUndo == 0) {
       return;
@@ -385,16 +413,17 @@ SessionStore.prototype = {
       }
 
       this._lastClosedTabIndex = aTabIndex;
 
       if (this._notifyClosedTabs) {
         this._sendClosedTabsToJava(aWindow);
       }
 
+      log("onTabClose() ran for tab " + aWindow.BrowserApp.getTabForBrowser(aBrowser).id);
       let evt = new Event("SSTabCloseProcessed", {"bubbles":true, "cancelable":false});
       aBrowser.dispatchEvent(evt);
     }
   },
 
   onTabLoad: function ss_onTabLoad(aWindow, aBrowser) {
     // If this browser is being restored, skip any session save activity
     if (aBrowser.__SS_restore) {
@@ -441,41 +470,46 @@ SessionStore.prototype = {
     } else {
       // When navigating via the forward/back buttons, Gecko restores
       // the form data all by itself and doesn't invoke any input events.
       // As _collectTabData() doesn't save any form data, we need to manually
       // capture it to bridge the time until the next input event arrives.
       this.onTabInput(aWindow, aBrowser);
     }
 
+    log("onTabLoad() ran for tab " + aWindow.BrowserApp.getTabForBrowser(aBrowser).id);
     let evt = new Event("SSTabDataUpdated", {"bubbles":true, "cancelable":false});
     aBrowser.dispatchEvent(evt);
     this.saveStateDelayed();
 
     this._updateCrashReportURL(aWindow);
   },
 
   onTabSelect: function ss_onTabSelect(aWindow, aBrowser) {
     if (this._loadState != STATE_RUNNING) {
       return;
     }
 
     let browsers = aWindow.document.getElementById("browsers");
     let index = browsers.selectedIndex;
     this._windows[aWindow.__SSID].selected = parseInt(index) + 1; // 1-based
 
+    let tabId = aWindow.BrowserApp.getTabForBrowser(aBrowser).id;
+
     // Restore the resurrected browser
     if (aBrowser.__SS_restore) {
       let data = aBrowser.__SS_data;
       this._restoreTab(data, aBrowser);
 
       delete aBrowser.__SS_restore;
       aBrowser.removeAttribute("pending");
+      log("onTabSelect() restored zombie tab " + tabId);
     }
 
+    log("onTabSelect() ran for tab " + tabId);
     this.saveStateDelayed();
     this._updateCrashReportURL(aWindow);
 
     // If the selected tab has changed while listening for closed tab
     // notifications, we may have switched between different private browsing
     // modes.
     if (this._notifyClosedTabs) {
       this._sendClosedTabsToJava(aWindow);
@@ -524,59 +558,69 @@ SessionStore.prototype = {
     // If any frame had text data, add it to the main form data
     if (children.length) {
       formdata.children = children;
     }
 
     // If we found any form data, main content or frames, let's save it
     if (Object.keys(formdata).length) {
       data.formdata = formdata;
+      log("onTabInput() ran for tab " + aWindow.BrowserApp.getTabForBrowser(aBrowser).id);
       this.saveStateDelayed();
     }
   },
 
   saveStateDelayed: function ss_saveStateDelayed() {
     if (!this._saveTimer) {
       // Interval until the next disk operation is allowed
       let minimalDelay = this._lastSaveTime + this._interval - Date.now();
 
       // If we have to wait, set a timer, otherwise saveState directly
       let delay = Math.max(minimalDelay, 2000);
       if (delay > 0) {
         this._pendingWrite++;
         this._saveTimer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
         this._saveTimer.init(this, delay, Ci.nsITimer.TYPE_ONE_SHOT);
+        log("saveStateDelayed() timer delay = " + delay +
+             ", incrementing _pendingWrite to " + this._pendingWrite);
       } else {
+        log("saveStateDelayed() no delay");
         this.saveState();
       }
     }
+    log("saveStateDelayed() timer already running, taking no action");
   },
 
   saveState: function ss_saveState() {
     this._pendingWrite++;
+    log("saveState(), incrementing _pendingWrite to " + this._pendingWrite);
     this._saveState(true);
   },
 
   // Immediately and synchronously writes any pending state to disk.
   flushPendingState: function ss_flushPendingState() {
+    log("flushPendingState(), _pendingWrite = " + this._pendingWrite);
     if (this._pendingWrite) {
       this._saveState(false);
     }
   },
 
   _saveState: function ss_saveState(aAsync) {
+    log("_saveState(aAsync = " + aAsync + ")");
     // Kill any queued timer and save immediately
     if (this._saveTimer) {
       this._saveTimer.cancel();
       this._saveTimer = null;
+      log("_saveState() killed queued timer");
     }
 
     let data = this._getCurrentState();
     let normalData = { windows: [] };
     let privateData = { windows: [] };
+    log("_saveState() current state collected");
 
     for (let winIndex = 0; winIndex < data.windows.length; ++winIndex) {
       let win = data.windows[winIndex];
       let normalWin = {};
       for (let prop in win) {
         normalWin[prop] = data[prop];
       }
       normalWin.tabs = [];
@@ -596,16 +640,18 @@ SessionStore.prototype = {
         savedWin.tabs.push(tab);
         if (win.selected == i + 1) {
           savedWin.selected = savedWin.tabs.length;
         }
       }
     }
 
     // Write only non-private data to disk
+    log("_saveState() writing normal data, " +
+         normalData.windows[0].tabs.length + " tabs in window[0]");
     this._writeFile(this._sessionFile, normalData, aAsync);
 
     // If we have private data, send it to Java; otherwise, send null to
     // indicate that there is no private data
     Messaging.sendRequest({
       type: "PrivateBrowsing:Data",
       session: (privateData.windows.length > 0 && privateData.windows[0].tabs.length > 0) ? JSON.stringify(privateData) : null
     });
@@ -694,28 +740,31 @@ SessionStore.prototype = {
     TelemetryStopwatch.finish("FX_SESSION_RESTORE_SERIALIZE_DATA_MS");
 
     // Convert data string to a utf-8 encoded array buffer
     let buffer = new TextEncoder().encode(state);
     Services.telemetry.getHistogramById("FX_SESSION_RESTORE_FILE_SIZE_BYTES").add(buffer.byteLength);
 
     Services.obs.notifyObservers(null, "sessionstore-state-write", "");
     let startWriteMs = Cu.now();
- 
+
+    log("_writeFile(aAsync = " + aAsync + "), _pendingWrite = " + this._pendingWrite);
     let pendingWrite = this._pendingWrite;
     this._write(aFile, buffer, aAsync).then(() => {
       let stopWriteMs = Cu.now();
 
       // Make sure this._pendingWrite is the same value it was before we
       // fired off the async write. If the count is different, another write
       // is pending, so we shouldn't reset this._pendingWrite yet.
       if (pendingWrite === this._pendingWrite) {
         this._pendingWrite = 0;
       }
 
+      log("_writeFile() _write() returned, _pendingWrite = " + this._pendingWrite);
+
       // We don't use a stopwatch here since the calls are async and stopwatches can only manage
       // a single timer per histogram.
       Services.telemetry.getHistogramById("FX_SESSION_RESTORE_WRITE_FILE_MS").add(Math.round(stopWriteMs - startWriteMs));
       Services.obs.notifyObservers(null, "sessionstore-state-write-complete", "");
     });
   },
 
   /**
@@ -723,25 +772,27 @@ SessionStore.prototype = {
    * @param aFile nsIFile used for saving the session
    * @param aBuffer UTF-8 encoded ArrayBuffer of the session state
    * @param aAsync boolelan used to determine the method of saving the state
    * @return Promise that resolves when the file has been written
    */
   _write: function ss_write(aFile, aBuffer, aAsync) {
     // Use async file writer and just return it's promise
     if (aAsync) {
+      log("_write() writing asynchronously");
       return OS.File.writeAtomic(aFile.path, aBuffer, { tmpPath: aFile.path + ".tmp" });
     }
 
     // Convert buffer to an encoded string and sync write to disk
     let bytes = String.fromCharCode.apply(null, new Uint16Array(aBuffer));
     let stream = Cc["@mozilla.org/network/file-output-stream;1"].createInstance(Ci.nsIFileOutputStream);
     stream.init(aFile, 0x02 | 0x08 | 0x20, 0o666, 0);
     stream.write(bytes, bytes.length);
     stream.close();
+    log("_write() writing synchronously");
 
     // Return a resolved promise to make the caller happy
     return Promise.resolve();
   },
 
   _updateCrashReportURL: function ss_updateCrashReportURL(aWindow) {
     let crashReporterBuilt = "nsICrashReporter" in Ci && Services.appinfo instanceof Ci.nsICrashReporter;
     if (!crashReporterBuilt) {
@@ -1093,16 +1144,17 @@ SessionStore.prototype = {
     }
   },
 
   /**
   * Takes serialized form text data and restores it into the given browser.
   */
   _restoreTextData: function ss_restoreTextData(aFormData, aBrowser) {
     if (aFormData) {
+      log("_restoreTextData()");
       FormData.restoreTree(aBrowser.contentWindow, aFormData);
     }
     delete aBrowser.__SS_restore_text_data;
   },
 
   getBrowserState: function ss_getBrowserState() {
     return this._getCurrentState();
   },
@@ -1119,19 +1171,22 @@ SessionStore.prototype = {
     if (!state || state.windows.length == 0 || !state.windows[0].tabs || state.windows[0].tabs.length == 0) {
       throw "Invalid session JSON: " + aData;
     }
 
     let window = Services.wm.getMostRecentWindow("navigator:browser");
 
     let tabs = state.windows[0].tabs;
     let selected = state.windows[0].selected;
+    log("_restoreWindow() selected tab in aData is " + selected + " of " + tabs.length)
     if (selected == null || selected > tabs.length) { // Clamp the selected index if it's bogus
+      log("_restoreWindow() resetting selected tab");
       selected = 1;
     }
+    log("restoreWindow() window.BrowserApp.selectedTab is " + window.BrowserApp.selectedTab.id);
 
     for (let i = 0; i < tabs.length; i++) {
       let tabData = tabs[i];
       let entry = tabData.entries[tabData.index - 1];
 
       // Use stubbed tab if we've already created it; otherwise, make a new tab
       let tab;
       if (tabData.tabId == null) {