Bug 1003204: Removed CommonUtils.exceptionStr() in services/sync r=markh r=gfritzsche

services/sync/modules/addonsreconciler.js

@@ -488,8 +488,7 @@ AddonsReconciler.prototype = {
       try {
         listener.changeListener.call(listener, date, change, state);
       } catch (ex) {
-        this._log.warn("Exception calling change listener: " +
+        this._log.warn("Exception calling change listener", ex);
-                       Utils.exceptionStr(ex));
       }
     }
   },
@@ -635,7 +634,7 @@ AddonsReconciler.prototype = {
       }
     }
     catch (ex) {
-      this._log.warn("Exception: " + Utils.exceptionStr(ex));
+      this._log.warn("Exception", ex);
     }
   },
 

services/sync/modules/addonutils.js

@@ -147,7 +147,7 @@ AddonUtilsInternal.prototype = {
         install.install();
       }
       catch (ex) {
-        this._log.error("Error installing add-on: " + Utils.exceptionstr(ex));
+        this._log.error("Error installing add-on", ex);
         cb(ex, null);
       }
     }.bind(this));

services/sync/modules/engines.js

@@ -15,7 +15,6 @@ var {classes: Cc, interfaces: Ci, results: Cr, utils: Cu} = Components;
 Cu.import("resource://services-common/async.js");
 Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://services-common/observers.js");
-Cu.import("resource://services-common/utils.js");
 Cu.import("resource://services-sync/constants.js");
 Cu.import("resource://services-sync/identity.js");
 Cu.import("resource://services-sync/record.js");
@@ -308,8 +307,7 @@ Store.prototype = {
         // ex.cause will carry its stack with it when rethrown.
         throw ex.cause;
       } catch (ex if !Async.isShutdownException(ex)) {
-        this._log.warn("Failed to apply incoming record " + record.id);
+        this._log.warn("Failed to apply incoming record " + record.id, ex);
-        this._log.warn("Encountered exception: " + Utils.exceptionStr(ex));
         this.engine._noteApplyFailure();
         failed.push(record.id);
       }
@@ -578,16 +576,11 @@ EngineManager.prototype = {
         this._engines[name] = engine;
       }
     } catch (ex) {
-      this._log.error(CommonUtils.exceptionStr(ex));
-
-      let mesg = ex.message ? ex.message : ex;
       let name = engineObject || "";
       name = name.prototype || "";
       name = name.name || "";
 
-      let out = "Could not initialize engine '" + name + "': " + mesg;
+      this._log.error(`Could not initialize engine ${name}`, ex);
-      this._log.error(out);
-
       return engineObject;
     }
   },
@@ -817,7 +810,7 @@ SyncEngine.prototype = {
     return this._previousFailed;
   },
   set previousFailed(val) {
-    let cb = (error) => this._log.error(Utils.exceptionStr(error));
+    let cb = (error) => this._log.error("Failed to set previousFailed", error);
     // Coerce the array to a string for more efficient comparison.
     if (val + "" == this._previousFailed) {
       return;
@@ -1000,8 +993,7 @@ SyncEngine.prototype = {
       } catch (ex if !Async.isShutdownException(ex)) {
         // Catch any error that escapes from applyIncomingBatch. At present
         // those will all be abort events.
-        this._log.warn("Got exception " + Utils.exceptionStr(ex) +
+        this._log.warn("Got exception, aborting processIncoming", ex);
-                       ", aborting processIncoming.");
         aborting = ex;
       }
       this._tracker.ignoreAll = false;
@@ -1069,7 +1061,7 @@ SyncEngine.prototype = {
               self._log.debug("Ignoring second retry suggestion.");
               // Fall through to error case.
             case SyncEngine.kRecoveryStrategy.error:
-              self._log.warn("Error decrypting record: " + Utils.exceptionStr(ex));
+              self._log.warn("Error decrypting record", ex);
               self._noteApplyFailure();
               failed.push(item.id);
               return;
@@ -1080,7 +1072,7 @@ SyncEngine.prototype = {
           }
         }
       } catch (ex) {
-        self._log.warn("Error decrypting record: " + Utils.exceptionStr(ex));
+        self._log.warn("Error decrypting record", ex);
         self._noteApplyFailure();
         failed.push(item.id);
         return;
@@ -1095,8 +1087,7 @@ SyncEngine.prototype = {
         failed.push(item.id);
         aborting = ex.cause;
       } catch (ex if !Async.isShutdownException(ex)) {
-        self._log.warn("Failed to reconcile incoming record " + item.id);
+        self._log.warn("Failed to reconcile incoming record " + item.id, ex);
-        self._log.warn("Encountered exception: " + Utils.exceptionStr(ex));
         self._noteApplyFailure();
         failed.push(item.id);
         return;
@@ -1485,7 +1476,7 @@ SyncEngine.prototype = {
           out.encrypt(this.service.collectionKeys.keyForCollection(this.name));
           up.pushData(out);
         } catch (ex if !Async.isShutdownException(ex)) {
-          this._log.warn("Error creating record: " + Utils.exceptionStr(ex));
+          this._log.warn("Error creating record", ex);
         }
 
         // Partial upload
@@ -1576,7 +1567,7 @@ SyncEngine.prototype = {
       this._log.trace("Trying to decrypt a record from the server..");
       test.get();
     } catch (ex if !Async.isShutdownException(ex)) {
-      this._log.debug("Failed test decrypt: " + Utils.exceptionStr(ex));
+      this._log.debug("Failed test decrypt", ex);
     }
 
     return canDecrypt;

services/sync/modules/engines/bookmarks.js

@@ -426,8 +426,7 @@ BookmarksEngine.prototype = {
         // Failure to create a backup is somewhat bad, but probably not bad
         // enough to prevent syncing of bookmarks - so just log the error and
         // continue.
-        this._log.warn("Got exception \"" + Utils.exceptionStr(ex) +
+        this._log.warn("Error while backing up bookmarks, but continuing with sync", ex);
-                       "\" backing up bookmarks, but continuing with sync.");
         cb();
       }
     );
@@ -442,9 +441,7 @@ BookmarksEngine.prototype = {
       try {
         guidMap = this._buildGUIDMap();
       } catch (ex if !Async.isShutdownException(ex)) {
-        this._log.warn("Got exception \"" + Utils.exceptionStr(ex) +
+        this._log.warn("Error while building GUID map, skipping all other incoming items", ex);
-                       "\" building GUID map." +
-                       " Skipping all other incoming items.");
         throw {code: Engine.prototype.eEngineAbortApplyIncoming,
                cause: ex};
       }
@@ -691,7 +688,7 @@ BookmarksStore.prototype = {
         return true;
       }
     } catch(ex) {
-      this._log.debug("Failed to reparent item. " + Utils.exceptionStr(ex));
+      this._log.debug("Failed to reparent item", ex);
     }
     return false;
   },
@@ -1323,8 +1320,7 @@ BookmarksStore.prototype = {
       let u = PlacesUtils.bookmarks.getBookmarkURI(itemID);
       this._tagURI(u, tags);
     } catch (e) {
-      this._log.warn("Got exception fetching URI for " + itemID + ": not tagging. " +
+      this._log.warn(`Got exception fetching URI for ${itemID} not tagging`, e);
-                     Utils.exceptionStr(e));
 
       // I guess it doesn't have a URI. Don't try to tag it.
       return;

services/sync/modules/engines/passwords.js

@@ -69,7 +69,7 @@ PasswordEngine.prototype = {
         Svc.Prefs.set("deletePwdFxA", true);
         Svc.Prefs.reset("deletePwd"); // The old prefname we previously used.
       } catch (ex if !Async.isShutdownException(ex)) {
-        this._log.debug("Password deletes failed: " + Utils.exceptionStr(ex));
+        this._log.debug("Password deletes failed", ex);
       }
     }
   },
@@ -233,8 +233,7 @@ PasswordStore.prototype = {
     try {
       Services.logins.addLogin(login);
     } catch(ex) {
-      this._log.debug("Adding record " + record.id +
+      this._log.debug(`Adding record ${record.id} resulted in exception`, ex);
-                      " resulted in exception " + Utils.exceptionStr(ex));
     }
   },
 
@@ -266,9 +265,7 @@ PasswordStore.prototype = {
     try {
       Services.logins.modifyLogin(loginItem, newinfo);
     } catch(ex) {
-      this._log.debug("Modifying record " + record.id +
+      this._log.debug(`Modifying record ${record.id} resulted in exception; not modifying`, ex);
-                      " resulted in exception " + Utils.exceptionStr(ex) +
-                      ". Not modifying.");
     }
   },
 

services/sync/modules/identity.js

@@ -326,7 +326,7 @@ IdentityManager.prototype = {
       try {
         this._syncKeyBundle = new SyncKeyBundle(this.username, this.syncKey);
       } catch (ex) {
-        this._log.warn(Utils.exceptionStr(ex));
+        this._log.warn("Failed to create sync bundle", ex);
         return null;
       }
     }

services/sync/modules/policies.js

@@ -581,7 +581,7 @@ ErrorHandler.prototype = {
         this.checkServerError(exception, "engines/" + engine_name);
 
         Status.engines = [engine_name, exception.failureCode || ENGINE_UNKNOWN_FAIL];
-        this._log.debug(engine_name + " failed: " + Utils.exceptionStr(exception));
+        this._log.debug(engine_name + " failed", exception);
 
         Services.telemetry.getKeyedHistogramById("WEAVE_ENGINE_SYNC_ERRORS")
                           .add(engine_name);

services/sync/modules/record.js

@@ -239,7 +239,7 @@ RecordManager.prototype = {
 
       return this.set(url, record);
     } catch (ex if !Async.isShutdownException(ex)) {
-      this._log.debug("Failed to import record: " + Utils.exceptionStr(ex));
+      this._log.debug("Failed to import record", ex);
       return null;
     }
   },

services/sync/modules/resource.js

@@ -233,7 +233,7 @@ AsyncResource.prototype = {
       channel.asyncOpen(listener, null);
     } catch (ex) {
       // asyncOpen can throw in a bunch of cases -- e.g., a forbidden port.
-      this._log.warn("Caught an error in asyncOpen: " + CommonUtils.exceptionStr(ex));
+      this._log.warn("Caught an error in asyncOpen", ex);
       CommonUtils.nextTick(callback.bind(this, ex));
     }
   },
@@ -280,9 +280,7 @@ AsyncResource.prototype = {
     } catch(ex) {
       // Got a response, but an exception occurred during processing.
       // This shouldn't occur.
-      this._log.warn("Caught unexpected exception " + CommonUtils.exceptionStr(ex) +
+      this._log.warn("Caught unexpected exception in _oncomplete", ex);
-                     " in _onComplete.");
-      this._log.debug(CommonUtils.stackTrace(ex));
     }
 
     // Process headers. They can be empty, or the call can otherwise fail, so
@@ -320,9 +318,7 @@ AsyncResource.prototype = {
                        contentLength + ".");
       }
     } catch (ex) {
-      this._log.debug("Caught exception " + CommonUtils.exceptionStr(ex) +
+      this._log.debug("Caught exception visiting headers in _onComplete", ex);
-                      " visiting headers in _onComplete.");
-      this._log.debug(CommonUtils.stackTrace(ex));
     }
 
     let ret     = new String(data);
@@ -338,7 +334,7 @@ AsyncResource.prototype = {
       try {
         return JSON.parse(ret);
       } catch (ex) {
-        this._log.warn("Got exception parsing response body: \"" + CommonUtils.exceptionStr(ex));
+        this._log.warn("Got exception parsing response body", ex);
         // Stringify to avoid possibly printing non-printable characters.
         this._log.debug("Parse fail: Response body starts: \"" +
                         JSON.stringify((ret + "").slice(0, 100)) +
@@ -544,7 +540,7 @@ ChannelListener.prototype = {
       siStream = Cc["@mozilla.org/scriptableinputstream;1"].createInstance(Ci.nsIScriptableInputStream);
       siStream.init(stream);
     } catch (ex) {
-      this._log.warn("Exception creating nsIScriptableInputStream." + CommonUtils.exceptionStr(ex));
+      this._log.warn("Exception creating nsIScriptableInputStream", ex);
       this._log.debug("Parameters: " + req.URI.spec + ", " + stream + ", " + off + ", " + count);
       // Cannot proceed, so rethrow and allow the channel to cancel itself.
       throw ex;
@@ -561,8 +557,7 @@ ChannelListener.prototype = {
       this._onProgress();
     } catch (ex if !Async.isShutdownException(ex)) {
       this._log.warn("Got exception calling onProgress handler during fetch of "
-                     + req.URI.spec);
+                     + req.URI.spec, ex);
-      this._log.debug(CommonUtils.exceptionStr(ex));
       this._log.trace("Rethrowing; expect a failure code from the HTTP channel.");
       throw ex;
     }
@@ -577,7 +572,7 @@ ChannelListener.prototype = {
     try {
       CommonUtils.namedTimer(this.abortRequest, this._timeout, this, "abortTimer");
     } catch (ex) {
-      this._log.warn("Got exception extending abort timer: " + CommonUtils.exceptionStr(ex));
+      this._log.warn("Got exception extending abort timer", ex);
     }
   },
 
@@ -671,14 +666,14 @@ ChannelNotificationListener.prototype = {
         }
       }
     } catch (ex) {
-      this._log.error("Error copying headers: " + CommonUtils.exceptionStr(ex));
+      this._log.error("Error copying headers", ex);
     }
 
     // We let all redirects proceed.
     try {
       callback.onRedirectVerifyCallback(Cr.NS_OK);
     } catch (ex) {
-      this._log.error("onRedirectVerifyCallback threw!" + CommonUtils.exceptionStr(ex));
+      this._log.error("onRedirectVerifyCallback threw!", ex);
     }
   }
 };

services/sync/modules/service.js

@@ -21,7 +21,6 @@ const KEYS_WBO = "keys";
 Cu.import("resource://gre/modules/Preferences.jsm");
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Log.jsm");
-Cu.import("resource://services-common/utils.js");
 Cu.import("resource://services-sync/constants.js");
 Cu.import("resource://services-sync/engines.js");
 Cu.import("resource://services-sync/engines/clients.js");
@@ -490,8 +489,7 @@ Sync11Service.prototype = {
 
         this.engineManager.register(ns[engineName]);
       } catch (ex) {
-        this._log.warn("Could not register engine " + name + ": " +
+        this._log.warn("Could not register engine " + name, ex);
-                       CommonUtils.exceptionStr(ex));
       }
     }
 
@@ -688,8 +686,7 @@ Sync11Service.prototype = {
 
     } catch (ex) {
       // This means no keys are present, or there's a network error.
-      this._log.debug("Failed to fetch and verify keys: "
+      this._log.debug("Failed to fetch and verify keys", ex);
-                      + Utils.exceptionStr(ex));
       this.errorHandler.checkServerError(ex, "crypto/keys");
       return false;
     }
@@ -785,7 +782,7 @@ Sync11Service.prototype = {
       }
     } catch (ex) {
       // Must have failed on some network issue
-      this._log.debug("verifyLogin failed: " + Utils.exceptionStr(ex));
+      this._log.debug("verifyLogin failed", ex);
       this.status.login = LOGIN_FAILED_NETWORK_ERROR;
       this.errorHandler.checkServerError(ex, "info/collections");
       return false;
@@ -858,8 +855,7 @@ Sync11Service.prototype = {
     try {
       cb.wait();
     } catch (ex) {
-      this._log.debug("Password change failed: " +
+      this._log.debug("Password change failed", ex);
-                      CommonUtils.exceptionStr(ex));
       return false;
     }
 
@@ -905,8 +901,7 @@ Sync11Service.prototype = {
         try {
           engine.removeClientData();
         } catch(ex) {
-          this._log.warn("Deleting client data for " + engine.name + " failed:"
+          this._log.warn(`Deleting client data for ${engine.name} failed`, ex);
-                         + Utils.exceptionStr(ex));
         }
       }
       this._log.debug("Finished deleting client data.");
@@ -1537,7 +1532,7 @@ Sync11Service.prototype = {
       try {
         response = res.delete();
       } catch (ex) {
-        this._log.debug("Failed to wipe server: " + CommonUtils.exceptionStr(ex));
+        this._log.debug("Failed to wipe server", ex);
         throw ex;
       }
       if (response.status != 200 && response.status != 404) {
@@ -1554,8 +1549,7 @@ Sync11Service.prototype = {
       try {
         response = this.resource(url).delete();
       } catch (ex) {
-        this._log.debug("Failed to wipe '" + name + "' collection: " +
+        this._log.debug("Failed to wipe '" + name + "' collection", ex);
-                        Utils.exceptionStr(ex));
         throw ex;
       }
 
@@ -1701,8 +1695,7 @@ Sync11Service.prototype = {
     return this.getStorageRequest(url).get(function onComplete(error) {
       // Note: 'this' is the request.
       if (error) {
-        this._log.debug("Failed to retrieve '" + info_type + "': " +
+        this._log.debug("Failed to retrieve '" + info_type + "'", error);
-                        Utils.exceptionStr(error));
         return callback(error);
       }
       if (this.response.status != 200) {

services/sync/modules/stages/enginesync.js

@@ -142,8 +142,7 @@ EngineSynchronizer.prototype = {
     try {
       this._updateEnabledEngines();
     } catch (ex) {
-      this._log.debug("Updating enabled engines failed: " +
+      this._log.debug("Updating enabled engines failed", ex);
-                      Utils.exceptionStr(ex));
       this.service.errorHandler.checkServerError(ex, "meta/global");
       this.onComplete(ex);
       return;

services/sync/modules/util.js

@@ -35,7 +35,6 @@ this.Utils = {
   // In the ideal world, references to these would be removed.
   nextTick: CommonUtils.nextTick,
   namedTimer: CommonUtils.namedTimer,
-  exceptionStr: CommonUtils.exceptionStr,
   stackTrace: CommonUtils.stackTrace,
   makeURI: CommonUtils.makeURI,
   encodeUTF8: CommonUtils.encodeUTF8,
@@ -77,7 +76,7 @@ this.Utils = {
         return func.call(thisArg);
       }
       catch(ex) {
-        thisArg._log.debug("Exception: " + Utils.exceptionStr(ex));
+        thisArg._log.debug("Exception", ex);
         if (exceptionCallback) {
           return exceptionCallback.call(thisArg, ex);
         }
@@ -342,8 +341,7 @@ this.Utils = {
       // Ignore non-existent files.
     } catch (e) {
       if (that._log) {
-        that._log.debug("Failed to load json: " +
+        that._log.debug("Failed to load json", e);
-                        CommonUtils.exceptionStr(e));
       }
     }
 

services/sync/tests/unit/head_http_server.js

@@ -586,7 +586,7 @@ SyncServer.prototype = {
     } catch (ex) {
       _("==========================================");
       _("Got exception starting Sync HTTP server.");
-      _("Error: " + Utils.exceptionStr(ex));
+      _("Error: " + Log.exceptionStr(ex));
       _("Is there a process already listening on port " + port + "?");
       _("==========================================");
       do_throw(ex);

services/sync/tests/unit/test_addon_utils.js

@@ -3,6 +3,7 @@
 
 "use strict";
 
+Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://gre/modules/Preferences.jsm");
 Cu.import("resource://services-sync/addonutils.js");
 Cu.import("resource://services-sync/util.js");
@@ -35,7 +36,7 @@ function createAndStartHTTPServer(port=HTTP_PORT) {
     return server;
   } catch (ex) {
     _("Got exception starting HTTP server on port " + port);
-    _("Error: " + Utils.exceptionStr(ex));
+    _("Error: " + Log.exceptionStr(ex));
     do_throw(ex);
   }
 }

services/sync/tests/unit/test_addons_store.js

@@ -3,6 +3,7 @@
 
 "use strict";
 
+Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://gre/modules/Preferences.jsm");
 Cu.import("resource://services-sync/addonutils.js");
 Cu.import("resource://services-sync/engines/addons.js");
@@ -61,7 +62,7 @@ function createAndStartHTTPServer(port) {
     return server;
   } catch (ex) {
     _("Got exception starting HTTP server on port " + port);
-    _("Error: " + Utils.exceptionStr(ex));
+    _("Error: " + Log.exceptionStr(ex));
     do_throw(ex);
   }
 }

services/sync/tests/unit/test_bookmark_engine.js

@@ -71,7 +71,7 @@ add_test(function test_ID_caching() {
     _("New mobile ID: " + newMobileID);
   } catch (ex) {
     err = ex;
-    _("Error: " + Utils.exceptionStr(err));
+    _("Error: " + Log.exceptionStr(err));
   }
 
   do_check_true(!err);
@@ -220,7 +220,7 @@ add_task(function test_restorePromptsReupload() {
       engine.sync();
     } catch(ex) {
       error = ex;
-      _("Got error: " + Utils.exceptionStr(ex));
+      _("Got error: " + Log.exceptionStr(ex));
     }
     do_check_true(!error);
 
@@ -264,7 +264,7 @@ add_task(function test_restorePromptsReupload() {
       engine.sync();
     } catch(ex) {
       error = ex;
-      _("Got error: " + Utils.exceptionStr(ex));
+      _("Got error: " + Log.exceptionStr(ex));
     }
     do_check_true(!error);
 

services/sync/tests/unit/test_fxa_node_reassignment.js

@@ -97,7 +97,7 @@ function getReassigned() {
     return false;
   } catch (ex) {
     do_throw("Got exception retrieving lastSyncReassigned: " +
-             Utils.exceptionStr(ex));
+             Log.exceptionStr(ex));
   }
 }
 

services/sync/tests/unit/test_node_reassignment.js

@@ -96,7 +96,7 @@ function getReassigned() {
     return false;
   } catch (ex) {
     do_throw("Got exception retrieving lastSyncReassigned: " +
-             Utils.exceptionStr(ex));
+             Log.exceptionStr(ex));
   }
 }
 

services/sync/tests/unit/test_service_sync_locked.js

@@ -11,8 +11,10 @@ function run_test() {
   function augmentLogger(old) {
     let d = old.debug;
     let i = old.info;
-    old.debug = function(m) { debug.push(m); d.call(old, m); }
+    // For the purposes of this test we don't need to do full formatting
-    old.info  = function(m) { info.push(m);  i.call(old, m); }
+    // of the 2nd param, as the ones we care about are always strings.
+    old.debug = function(m, p) { debug.push(p ? m + ": " + p : m); d.call(old, m, p); }
+    old.info  = function(m, p) { info.push(p ? m + ": " + p : m);  i.call(old, m, p); }
     return old;
   }
 
@@ -28,9 +30,7 @@ function run_test() {
   Service.sync();
   Service._locked = false;
 
-  do_check_eq(debug[debug.length - 2],
+  do_check_true(debug[debug.length - 2].startsWith("Exception: Could not acquire lock. Label: \"service.js: login\"."));
-              "Exception: Could not acquire lock. Label: \"service.js: login\". No traceback available");
+  do_check_eq(info[info.length - 1], "Cannot start sync: already syncing?");
-  do_check_eq(info[info.length - 1],
-              "Cannot start sync: already syncing?");
 }
 

services/sync/tests/unit/test_utils_catch.js

@@ -8,7 +8,7 @@ function run_test() {
     catch: Utils.catch,
     _log: {
       debug: function(str) {
-        didThrow = str.search(/^Exception: /) == 0;
+        didThrow = str.search(/^Exception/) == 0;
       },
       info: function(str) {
         wasLocked = str.indexOf("Cannot start sync: already syncing?") == 0;

services/sync/tps/extensions/tps/resource/tps.jsm

@@ -14,6 +14,7 @@ const {classes: Cc, interfaces: Ci, utils: Cu} = Components;
 var module = this;
 
 // Global modules
+Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://services-common/async.js");
@@ -138,7 +139,7 @@ var TPS = {
     this._errors++;
     let errInfo;
     if (exc) {
-      errInfo = Utils.exceptionStr(exc); // includes details and stack-trace.
+      errInfo = Log.exceptionStr(exc); // includes details and stack-trace.
     } else {
       // always write a stack even if no error passed.
       errInfo = Utils.stackTrace(new Error());
@@ -1051,4 +1052,4 @@ var Windows = {
 };
 
 // Initialize TPS
-TPS._init();
+TPS._init();