Bug 732372 - Search fails - a.contact is undefined in gloda.js. Part 1 - Fix some logging issues. r=bienvenu,a=Standard8 COMM110_20120307_RELBRANCH
authorAndrew Sutherland <bugmail@asutherland.org>
Thu, 08 Mar 2012 16:02:56 +0000
branchCOMM110_20120307_RELBRANCH
changeset 10252 ac82f70dfe844dd6495d8388ebc4f79f84bc13a1
parent 10244 4a607f01ba04ff831454fe009d630f18df707ba6
child 10253 3b9a5b68fdebc7b13439bb45a61e9809b6b88a11
push idunknown
push userunknown
push dateunknown
reviewersbienvenu, Standard8
bugs732372
Bug 732372 - Search fails - a.contact is undefined in gloda.js. Part 1 - Fix some logging issues. r=bienvenu,a=Standard8
mailnews/db/gloda/modules/datastore.js
mailnews/db/gloda/modules/gloda.js
mailnews/db/gloda/modules/index_ab.js
mailnews/db/gloda/modules/index_msg.js
mailnews/db/gloda/modules/indexer.js
mailnews/db/gloda/modules/suffixtree.js
--- a/mailnews/db/gloda/modules/datastore.js
+++ b/mailnews/db/gloda/modules/datastore.js
@@ -95,17 +95,17 @@ PostCommitHandler.prototype = {
                ex.lineNumber + ") threw: " + ex);
         }
       }
     }
     try {
       GlodaDatastore._asyncCompleted();
     }
     catch (e) {
-      PCH_LOG.error("Exception in handleCompletion: " + e);
+      PCH_LOG.error("Exception in handleCompletion:", e);
     }
 
   }
 };
 
 let QFQ_LOG = Log4Moz.repository.getLogger("gloda.ds.qfq");
 
 /**
@@ -289,18 +289,17 @@ QueryFromQueryCallback.prototype = {
           childrenList.push(item);
         }
 
         pendingItems.push(item);
         pendingIdMap[item.id] = item;
       }
     }
     catch (e) {
-      GlodaDatastore._log.error("Exception in handleResult: (" + e.fileName +
-                                ":" + e.lineNumber + "): " + e);
+      GlodaDatastore._log.error("Exception in handleResult:", e);
     }
   },
 
   handleError: function gloda_ds_qfq_handleError(aError) {
     GlodaDatastore._log.error("Async queryFromQuery error: " +
       aError.result + ": " + aError.message);
   },
 
@@ -415,17 +414,17 @@ QueryFromQueryCallback.prototype = {
           //  next concerned subCollection or the actual listener if this is the
           //  master collection.  (Also, call _onQueryCompleted).
           QueryFromQueryResolver.onItemsAdded(null, {data: this.collection}, true);
           QueryFromQueryResolver.onQueryCompleted({data: this.collection});
         }
       }
       catch (e) {
         Components.utils.reportError(e);
-        QFQ_LOG.error("Exception: " + e);
+        QFQ_LOG.error("Exception:", e);
       }
     }
     finally {
       GlodaDatastore._asyncCompleted();
     }
   }
 };
 
@@ -1027,18 +1026,18 @@ var GlodaDatastore = {
       catch (ex) {
         if (ex.result == Cr.NS_ERROR_FILE_CORRUPTED) {
           this._log.warn("Database was corrupt, removing the old one.");
           dbFile.remove(false);
           this._log.warn("Removed old database, creating a new one.");
           dbConnection = this._createDB(dbService, dbFile);
         }
         else {
-          this._log.error("Unexpected error when trying to open the database:" +
-                          " " + ex);
+          this._log.error("Unexpected error when trying to open the database:",
+                          ex);
           throw ex;
         }
       }
     }
 
     this.syncConnection = dbConnection;
     this.asyncConnection = dbConnection;
 
@@ -1398,17 +1397,17 @@ var GlodaDatastore = {
 
   _realCreateAsyncStatement: function gloda_ds_createAsyncStatement(aSQLString,
                                                                 aWillFinalize) {
     let statement = null;
     try {
       statement = this.asyncConnection.createAsyncStatement(aSQLString);
     }
     catch(ex) {
-       throw("error creating async statement " + aSQLString + " - " +
+       throw new Error("error creating async statement " + aSQLString + " - " +
              this.asyncConnection.lastError + ": " +
              this.asyncConnection.lastErrorString + " - " + ex);
     }
 
     if (!aWillFinalize)
       this._outstandingAsyncStatements.push(statement);
 
     return statement;
@@ -1454,17 +1453,17 @@ var GlodaDatastore = {
 
   _createSyncStatement: function gloda_ds_createSyncStatement(aSQLString,
                                                               aWillFinalize) {
     let statement = null;
     try {
       statement = this.syncConnection.createStatement(aSQLString);
     }
     catch(ex) {
-       throw("error creating sync statement " + aSQLString + " - " +
+       throw new Error("error creating sync statement " + aSQLString + " - " +
              this.syncConnection.lastError + ": " +
              this.syncConnection.lastErrorString + " - " + ex);
     }
 
     if (!aWillFinalize)
       this._outstandingSyncStatements.push(statement);
 
     return statement;
@@ -1520,17 +1519,17 @@ var GlodaDatastore = {
     else if (typeof aVariant == "number") {
       // we differentiate for storage representation reasons only.
       if (Math.floor(aVariant) === aVariant)
         aStatement.bindInt64Parameter(aIndex, aVariant);
       else
         aStatement.bindDoubleParameter(aIndex, aVariant);
     }
     else
-      throw("Attempt to bind variant with unsupported type: " +
+      throw new Error("Attempt to bind variant with unsupported type: " +
             (typeof aVariant));
   },
 
   /**
    * Helper that uses the appropriate getter given the data type; should be
    *  mooted once we move to 1.9.2 and can use built-in variant support.
    */
   _getVariant: function gloda_ds_getBlob(aRow, aIndex) {
@@ -1611,17 +1610,17 @@ var GlodaDatastore = {
       try {
         if (this._transactionGood)
           this._commitTransactionStatement.executeAsync(
             new PostCommitHandler(this._pendingPostCommitCallbacks));
         else
           this._rollbackTransactionStatement.executeAsync(this.trackAsync());
       }
       catch (ex) {
-        this._log.error("Commit problem: " + ex);
+        this._log.error("Commit problem:", ex);
       }
       this._pendingPostCommitCallbacks = [];
     }
   },
   /**
    * Abort the commit of the potentially nested transaction.  If we are not the
    *  outermost transaction, we set a flag that tells the outermost transaction
    *  that it must roll back.
@@ -1629,17 +1628,17 @@ var GlodaDatastore = {
   _rollbackTransaction: function gloda_ds_rollbackTransaction() {
     this._transactionDepth--;
     this._transactionGood = false;
     if (this._transactionDepth == 0) {
       try {
         this._rollbackTransactionStatement.executeAsync(this.trackAsync());
       }
       catch (ex) {
-        this._log.error("Rollback problem: " + ex);
+        this._log.error("Rollback problem:", ex);
       }
     }
   },
 
   _pendingAsyncStatements: 0,
   /**
    * The function to call, if any, when we hit 0 pending async statements.
    */
@@ -1659,17 +1658,17 @@ var GlodaDatastore = {
                         aError.result + ": " + aError.message);
     },
     handleCompletion: function () {
       try {
         // the helper method exists because the other classes need to call it too
         GlodaDatastore._asyncCompleted();
       }
       catch (e) {
-        this._log.error("Exception in handleCompletion: " + e);
+        this._log.error("Exception in handleCompletion:", e);
       }
     }
   },
   /**
    * Increments _pendingAsyncStatements and returns a listener that will
    *  decrement the value when the statement completes.
    */
   trackAsync: function() {
@@ -1971,17 +1970,17 @@ var GlodaDatastore = {
    * @return The GlodaFolder instance with the given id.  If no such instance
    *     exists, we will throw an exception.
    */
   _mapFolderID: function gloda_ds_mapFolderID(aFolderID) {
     if (aFolderID === null)
       return null;
     if (aFolderID in this._folderByID)
       return this._folderByID[aFolderID];
-    throw "Got impossible folder ID: " + aFolderID;
+    throw new Error("Got impossible folder ID: " + aFolderID);
   },
 
   /**
    * Mark the gloda folder as deleted for any outstanding references to it and
    *  remove it from our tables so we don't hand out any new references.  The
    *  latter is especially important in the case a folder with the same name
    *  is created afterwards; we don't want to confuse the new one with the old
    *  one!
@@ -2341,17 +2340,17 @@ var GlodaDatastore = {
     else
       ims.bindNullParameter(6);
     ims.bindInt64Parameter(7, aMessage.notability);
 
     try {
        ims.executeAsync(this.trackAsync());
     }
     catch(ex) {
-       throw("error executing statement... " +
+       throw new Error("error executing statement... " +
              this.asyncConnection.lastError + ": " +
              this.asyncConnection.lastErrorString + " - " + ex);
     }
 
     // we create the full-text row for any message that isn't a ghost,
     // whether we have the body or not
     if (aMessage.folderID !== null)
       this._insertMessageText(aMessage);
@@ -2383,17 +2382,17 @@ var GlodaDatastore = {
 
     imts.bindStringParameter(4, aMessage._indexAuthor);
     imts.bindStringParameter(5, aMessage._indexRecipients);
 
     try {
       imts.executeAsync(this.trackAsync());
     }
     catch(ex) {
-      throw("error executing fulltext statement... " +
+      throw new Error("error executing fulltext statement... " +
             this.asyncConnection.lastError + ": " +
             this.asyncConnection.lastErrorString + " - " + ex);
     }
   },
 
   get _updateMessageStatement() {
     let statement = this._createAsyncStatement(
       "UPDATE messages SET folderID = ?1, \
@@ -2495,17 +2494,17 @@ var GlodaDatastore = {
       umts.bindNullParameter(1);
     else
       umts.bindStringParameter(1, aMessage._attachmentNames.join("\n"));
 
     try {
       umts.executeAsync(this.trackAsync());
     }
     catch(ex) {
-      throw("error executing fulltext statement... " +
+      throw new Error("error executing fulltext statement... " +
             this.asyncConnection.lastError + ": " +
             this.asyncConnection.lastErrorString + " - " + ex);
     }
   },
 
   get _updateMessageLocationStatement() {
     let statement = this._createAsyncStatement(
       "UPDATE messages SET folderID = ?1, messageKey = ?2 WHERE id = ?3");
@@ -2881,17 +2880,17 @@ var GlodaDatastore = {
         dmas.bindInt64Parameter(2, aMessage.conversationID);
         dmas.bindInt64Parameter(3, aMessage.id);
         dmas.executeAsync(this.trackAsync());
       }
 
       this._commitTransaction();
     }
     catch (ex) {
-      this._log.error("adjustMessageAttributes:" + ex.lineNumber + ": " + eX);
+      this._log.error("adjustMessageAttributes:", ex);
       this._rollbackTransaction();
       throw ex;
     }
   },
 
   get _deleteMessageAttributesByMessageIDStatement() {
     let statement = this._createAsyncStatement(
       "DELETE FROM messageAttributes WHERE messageID = ?1");
@@ -2975,17 +2974,17 @@ var GlodaDatastore = {
           das.bindDoubleParameter(1, attribValueTuple[1]);
         das.bindInt64Parameter(2, aItem.id);
         das.executeAsync(this.trackAsync());
       }
 
       this._commitTransaction();
     }
     catch (ex) {
-      this._log.error("adjustAttributes:" + ex.lineNumber + ": " + eX);
+      this._log.error("adjustAttributes:", ex);
       this._rollbackTransaction();
       throw ex;
     }
   },
 
   clearAttributes: function gloda_ds_clearAttributes(aItem) {
     let nounDef = aItem.NOUN_DEF;
     let dbMeta = nounMeta._dbMeta;
--- a/mailnews/db/gloda/modules/gloda.js
+++ b/mailnews/db/gloda/modules/gloda.js
@@ -2043,21 +2043,18 @@ var Gloda = {
       //  removeDBattribs, if the attribute is not to generate entries in
       //  messageAttributes
       if (oldValue !== undefined || !aIsConceptuallyNew)
         aOldItem[key] = value;
 
       // the new canQuery property has to be explicitly set to generate entries
       // in the messageAttributes table, hence making the message query-able.
       if (!attrib.canQuery) {
-        this._log.debug("Not inserting attribute "+attrib.attributeName
-            +" into the db, since we don't plan on querying on it");
         continue;
       }
-      this._log.debug("Inserting attribute "+attrib.attributeName);
 
       // - database index attributes
 
       // perform a delta analysis against the old value, if we have one
       if (oldValue !== undefined) {
         // in the singular case if they don't match, it's one add and one remove
         if (attrib.singular) {
           // test for identicality, failing that, see if they have explicit
--- a/mailnews/db/gloda/modules/index_ab.js
+++ b/mailnews/db/gloda/modules/index_ab.js
@@ -286,17 +286,17 @@ var GlodaABAttrs = {
     for (let freeTagName in this._attrFreeTag.parameterBindings) {
       this._log.debug("Telling FreeTagNoun about: " + freeTagName);
       FreeTagNoun.getFreeTag(freeTagName);
     }
   },
 
   process: function(aContact, aCard, aIsNew, aCallbackHandle) {
     if (aContact.NOUN_ID != Gloda.NOUN_CONTACT) {
-      this._log.warning("Somehow got a non-contact: " + aContact);
+      this._log.warn("Somehow got a non-contact: " + aContact);
       return; // this will produce an exception; we like.
     }
 
     // update the name
     if (aCard.displayName && aCard.displayName != aContact.name)
       aContact.name = aCard.displayName;
 
     aContact.freeTags = [];
--- a/mailnews/db/gloda/modules/index_msg.js
+++ b/mailnews/db/gloda/modules/index_msg.js
@@ -1448,23 +1448,23 @@ var GlodaMsgIndexer = {
         // if the message seems valid and we are not forcing indexing, skip it.
         //  (that means good gloda id and not dirty)
         if (!force &&
             glodaId >= GLODA_FIRST_VALID_MESSAGE_ID &&
             glodaDirty == this.kMessageClean)
           continue;
 
         if (logDebug)
-          this._log.debug(">>>  _indexMessage");
+          this._log.debug(">>>  calling _indexMessage");
         yield aCallbackHandle.pushAndGo(
           this._indexMessage(msgHdr, aCallbackHandle),
           {what: "indexMessage", msgHdr: msgHdr});
         GlodaIndexer._indexedMessageCount++;
         if (logDebug)
-          this._log.debug("<<<  _indexMessage");
+          this._log.debug("<<<  back from _indexMessage");
       }
     }
 
     // This will trigger an (async) db update which cannot hit the disk prior to
     //  the actual database records that constitute the clean state.
     // XXX There is the slight possibility that, in the event of a crash, this
     //  will hit the disk but the gloda-id properties on the headers will not
     //  get set.  This should ideally be resolved by detecting a non-clean
@@ -1576,29 +1576,35 @@ var GlodaMsgIndexer = {
    * Recover from a "folder" or "message" job failing inside a call to
    *  |_indexMessage|, marking the message bad.  If we were not in an
    *  |_indexMessage| call, then fail to recover.
    *
    * @param aJob The job that was being worked.  We ignore this for now.
    * @param aContextStack The callbackHandle mechanism's context stack.  When we
    *     invoke pushAndGo for _indexMessage we put something in so we can
    *     detect when it is on the async stack.
+   * @param aException The exception that is necessitating we attempt to
+   *     recover.
    *
    * @return 1 if we were able to recover (because we want the call stack
    *     popped down to our worker), false if we can't.
    */
   _recover_indexMessage:
-      function gloda_index_recover_indexMessage(aJob, aContextStack) {
+      function gloda_index_recover_indexMessage(aJob, aContextStack,
+                                                aException) {
     // See if indexMessage is on the stack...
     if (aContextStack.length >= 2 &&
         aContextStack[1] &&
         ("what" in aContextStack[1]) &&
         aContextStack[1].what == "indexMessage") {
       // it is, so this is probably recoverable.
 
+      this._log.debug(
+        "Exception while indexing message, marking it bad (gloda id of 1).");
+
       // -- Mark the message as bad
       let msgHdr = aContextStack[1].msgHdr;
       // (In the worst case, the header is no longer valid, which will result in
       //  exceptions.  We need to be prepared for that.)
       try {
         msgHdr.setUint32Property(GLODA_MESSAGE_ID_PROPERTY,
                                  GLODA_BAD_MESSAGE_ID);
         // clear the dirty bit if it has one
@@ -2110,18 +2116,17 @@ var GlodaMsgIndexer = {
      */
     msgsClassified: function gloda_indexer_msgsClassified(
                       aMsgHdrs, aJunkClassified, aTraitClassified) {
       this.indexer._log.debug("msgsClassified notification");
       try {
         GlodaMsgIndexer._reindexChangedMessages(aMsgHdrs.enumerate(), false);
       }
       catch (ex) {
-        this.indexer._log.error("Explosion in msgsClassified handling: " +
-                                ex.stack);
+        this.indexer._log.error("Explosion in msgsClassified handling:", ex);
       }
     },
 
     /**
      * Handle real, actual deletion (move to trash and IMAP deletion model
      *  don't count); we only see the deletion here when it becomes forever,
      *  or rather _just before_ it becomes forever.  Because the header is
      *  going away, we need to either process things immediately or extract the
@@ -2382,18 +2387,18 @@ var GlodaMsgIndexer = {
           }
 
           // mark the folder as dirty; we'll get to it later.
           let destGlodaFolder = GlodaDatastore._mapFolder(aDestFolder);
           destGlodaFolder._ensureFolderDirty();
           this.indexer.indexingSweepNeeded = true;
         }
       } catch (ex) {
-        this.indexer._log.error("Problem encountered during message move/copy" +
-          ": " + ex + "\n\n" + ex.stack + "\n\n");
+        this.indexer._log.error("Problem encountered during message move/copy:",
+                                ex.stack);
       }
     },
 
     /**
      * Queue up message key changes that are a result of offline fake headers
      *  being made real for the actual update during the msgsClassified
      *  notification that is expected after this.  We defer the
      *  actual work (if there is any to be done; the fake header might have
--- a/mailnews/db/gloda/modules/indexer.js
+++ b/mailnews/db/gloda/modules/indexer.js
@@ -91,25 +91,28 @@ function IndexingJob(aJobType, aID, aIte
   this.id = aID;
   this.items = (aItems != null) ? aItems : [];
   this.offset = 0;
   this.goal = null;
   this.callback = null;
   this.callbackThis = null;
 }
 IndexingJob.prototype = {
+  /**
+   * Invoke the callback associated with this job, passing through all arguments
+   *  received by this function to the callback function.
+   */
   safelyInvokeCallback: function() {
     if (!this.callback)
       return;
     try {
       this.callback.apply(this.callbackThis, arguments);
     }
     catch(ex) {
-      GlodaIndexer._log.warning("job callback invocation problem: " +
-                                ex.fileName + ":" + ex.lineNumber + ": " + ex);
+      GlodaIndexer._log.warn("job callback invocation problem:", ex);
     }
   },
   toString: function IndexingJob_toString() {
     return "[job:" + this.jobType +
       " id:" + this.id + " items:" + (this.items ? this.items.length : "no") +
       " offset:" + this.offset + " goal:" + this.goal + "]";
   }
 };
@@ -486,16 +489,17 @@ var GlodaIndexer = {
   registerIndexer: function gloda_index_registerIndexer(aIndexer) {
     this._log.info("Registering indexer: " + aIndexer.name);
     this._indexers.push(aIndexer);
 
     try {
       for each (let [iWorker, workerInfo] in Iterator(aIndexer.workers)) {
         let workerCode = workerInfo[0];
         let workerDef = workerInfo[1];
+        workerDef.name = workerCode;
         workerDef.indexer = aIndexer;
         this._indexerWorkerDefs[workerCode] = workerDef;
         if (!("recover" in workerDef))
           workerDef.recover = null;
         if (!("cleanup" in workerDef))
           workerDef.cleanup = null;
         if (!("onSchedule" in workerDef))
           workerDef.onSchedule = null;
@@ -1080,36 +1084,51 @@ var GlodaIndexer = {
             case this.kWorkDoneWithResult:
               this._workBatchData = this._callbackHandle.popWithResult();
               break;
             default:
               break;
           }
         }
         catch (ex) {
+          this._log.debug("Exception in batch processing:", ex);
           let workerDef = this._curIndexingJob._workerDef;
           if (workerDef.recover) {
-            let recoverToDepth =
+            let recoverToDepth;
+            try {
+              recoverToDepth =
               workerDef.recover.call(workerDef.indexer,
                                      this._curIndexingJob,
-                                     this._callbackHandle.contextStack);
+                                       this._callbackHandle.contextStack,
+                                       ex);
+            }
+            catch (ex2) {
+              this._log.error("Worker '" + workerDef.name +
+                              "' recovery function itself failed:", ex2);
+            }
             if (this._unitTestHookRecover)
               this._unitTestHookRecover(recoverToDepth, ex,
                                         this._curIndexingJob,
                                         this._callbackHandle);
 
             if (recoverToDepth) {
               this._callbackHandle.cleanup(recoverToDepth);
               continue;
             }
           }
           // (we either did not have a recover handler or it couldn't recover)
           // call the cleanup helper if there is one
           if (workerDef.cleanup) {
+            try {
             workerDef.cleanup.call(workerDef.indexer, this._curIndexingJob);
+            }
+            catch (ex2) {
+              this._log.error("Worker '" + workerDef.name +
+                              "' cleanup function itself failed:", ex2);
+            }
             if (this._unitTestHookCleanup)
               this._unitTestHookCleanup(true, ex, this._curIndexingJob,
                                         this._callbackHandle);
           }
           else {
             if (this._unitTestHookCleanup)
               this._unitTestHookCleanup(false, ex, this._curIndexingJob,
                                         this._callbackHandle);
@@ -1117,20 +1136,17 @@ var GlodaIndexer = {
 
           // Clean out everything on the async stack, warn about the job, kill.
           // We do not log this warning lightly; it will break unit tests and
           //  be visible to users.  Anything expected should likely have a
           //  recovery function or the cleanup logic should be extended to
           //  indicate that the failure is acceptable.
           this._callbackHandle.cleanup();
           this._log.warn("Problem during " + this._curIndexingJob +
-            ", bailing.  Problem was at " + ex.fileName + ":" +
-            ex.lineNumber + ": " + ex +
-            (ex.stack ? (". Stack:\n  " + ex.stack.replace("\n", "\n  ", "g"))
-                      : ""));
+            ", bailing:", ex);
           this._curIndexingJob = null;
           // the data must now be invalid
           this._workBatchData = undefined;
         }
       }
       this._perfIndexStopwatch.stop();
 
       // idleTime can throw if there is no idle-provider available, such as an
--- a/mailnews/db/gloda/modules/suffixtree.js
+++ b/mailnews/db/gloda/modules/suffixtree.js
@@ -38,17 +38,17 @@
 const EXPORTED_SYMBOLS = ["SuffixTree", "MultiSuffixTree"];
 
 /**
  * Given a list of strings and a corresponding map of items that those strings
  *  correspond to, build a suffix tree.
  */
 function MultiSuffixTree(aStrings, aItems) {
   if (aStrings.length != aItems.length)
-    throw Error("Array lengths need to be the same.");
+    throw new Error("Array lengths need to be the same.");
 
   let s = '';
   let offsetsToItems = [];
   let lastLength = 0;
   for (let i = 0; i < aStrings.length; i++) {
     s += aStrings[i];
     offsetsToItems.push(lastLength, s.length, aItems[i]);
     lastLength = s.length;