Bug 1455413 - Use debug logging for bookmarks mirror trees; trace logging for details. r=tcsc
authorKit Cambridge <kit@yakshaving.ninja>
Thu, 19 Apr 2018 12:19:32 -0700
changeset 785558 a24163782fb72468fa3f83aacd9c15278ff060f3
parent 785557 77aa2a89aa37ea92194f79518895febc737ce341
child 785559 f7eaee35dcd2dab819bcadcdb9bba2ed53cc697f
push id107257
push userdgottwald@mozilla.com
push dateFri, 20 Apr 2018 10:55:57 +0000
reviewerstcsc
bugs1455413
milestone61.0a1
Bug 1455413 - Use debug logging for bookmarks mirror trees; trace logging for details. r=tcsc MozReview-Commit-ID: IVa4KzdNHrR
toolkit/components/places/SyncedBookmarksMirror.jsm
--- a/toolkit/components/places/SyncedBookmarksMirror.jsm
+++ b/toolkit/components/places/SyncedBookmarksMirror.jsm
@@ -459,33 +459,33 @@ class SyncedBookmarksMirror {
     // mirror, and we're holding the Sync lock at this point.
     MirrorLog.debug("Building remote tree from mirror");
     let { result: remoteTree, time: remoteTreeTiming } = await withTiming(
       "Fetch remote tree",
       () => this.fetchRemoteTree(remoteTimeSeconds)
     );
     applyStats.remoteTree = { time: remoteTreeTiming,
                               count: remoteTree.guidCount };
-    if (MirrorLog.level <= Log.Level.Trace) {
-      MirrorLog.trace("Built remote tree from mirror\n" +
+    if (MirrorLog.level <= Log.Level.Debug) {
+      MirrorLog.debug("Built remote tree from mirror\n" +
                       remoteTree.toASCIITreeString());
     }
 
     let observersToNotify = new BookmarkObserverRecorder(this.db);
 
     let changeRecords = await this.db.executeTransaction(async () => {
       MirrorLog.debug("Building local tree from Places");
       let { result: localTree, time: localTreeTiming } = await withTiming(
         "Fetch local tree",
         () => this.fetchLocalTree(localTimeSeconds)
       );
       applyStats.localTree = { time: localTreeTiming,
                                count: localTree.guidCount };
-      if (MirrorLog.level <= Log.Level.Trace) {
-        MirrorLog.trace("Built local tree from Places\n" +
+      if (MirrorLog.level <= Log.Level.Debug) {
+        MirrorLog.debug("Built local tree from Places\n" +
                         localTree.toASCIITreeString());
       }
 
       MirrorLog.debug("Fetching content info for new mirror items");
       let {
         result: newRemoteContents,
         time: remoteContentsTiming,
       } = await withTiming(
@@ -518,18 +518,18 @@ class SyncedBookmarksMirror {
         ));
         applyStats.merge = { time };
       } finally {
         for (let { value, extra } of merger.summarizeTelemetryEvents()) {
           this.recordTelemetryEvent("mirror", "merge", value, extra);
         }
       }
 
-      if (MirrorLog.level <= Log.Level.Trace) {
-        MirrorLog.trace([
+      if (MirrorLog.level <= Log.Level.Debug) {
+        MirrorLog.debug([
           "Built new merged tree",
           mergedRoot.toASCIITreeString(),
           ...merger.deletionsToStrings(),
         ].join("\n"));
       }
 
       // The merged tree should know about all items mentioned in the local
       // and remote trees. Otherwise, it's incomplete, and we'll corrupt
@@ -588,17 +588,17 @@ class SyncedBookmarksMirror {
 
       return changeRecords;
     });
 
     MirrorLog.debug("Replaying recorded observer notifications");
     try {
       await observersToNotify.notifyAll();
     } catch (ex) {
-      MirrorLog.error("Error notifying Places observers", ex);
+      MirrorLog.warn("Error notifying Places observers", ex);
     }
 
     for (let value in applyStats) {
       let extra = normalizeExtraTelemetryFields(applyStats[value]);
       if (extra) {
         this.recordTelemetryEvent("mirror", "apply", value, extra);
       }
     }
@@ -1281,28 +1281,28 @@ class SyncedBookmarksMirror {
    *        The root of the merged bookmark tree.
    * @param {Object[]} localDeletions
    *        `{ guid, level }` tuples for items to remove from Places and flag as
    *        merged.
    * @param {String[]} remoteDeletions
    *        Remotely deleted GUIDs that should be flagged as merged.
    */
   async updateLocalItemsInPlaces(mergedRoot, localDeletions, remoteDeletions) {
-    MirrorLog.debug("Setting up merge states table");
+    MirrorLog.trace("Setting up merge states table");
     let mergeStatesParams = Array.from(mergedRoot.mergeStatesParams());
     if (mergeStatesParams.length) {
       await this.db.execute(`
         INSERT INTO mergeStates(localGuid, mergedGuid, parentGuid, level,
                                 position, valueState, structureState)
         VALUES(IFNULL(:localGuid, :mergedGuid), :mergedGuid, :parentGuid,
                :level, :position, :valueState, :structureState)`,
         mergeStatesParams);
     }
 
-    MirrorLog.debug("Inserting new URLs into Places");
+    MirrorLog.trace("Inserting new URLs into Places");
     await this.db.execute(`
       INSERT OR IGNORE INTO moz_places(url, url_hash, rev_host, hidden,
                                        frecency, guid)
       SELECT u.url, u.hash, u.revHost, 0,
              (CASE v.kind WHEN :queryKind THEN 0 ELSE -1 END),
              IFNULL((SELECT h.guid FROM moz_places h
                      WHERE h.url_hash = u.hash AND
                            h.url = u.url), u.guid)
@@ -1311,29 +1311,29 @@ class SyncedBookmarksMirror {
       JOIN mergeStates r ON r.mergedGuid = v.guid
       WHERE r.valueState = :valueState`,
       { queryKind: SyncedBookmarksMirror.KIND.QUERY,
         valueState: BookmarkMergeState.TYPE.REMOTE });
     await this.db.execute(`DELETE FROM moz_updatehostsinsert_temp`);
 
     // Deleting from `itemsToMerge` fires the `insertNewLocalItems` and
     // `updateExistingLocalItems` triggers.
-    MirrorLog.debug("Updating value states for local bookmarks");
+    MirrorLog.trace("Updating value states for local bookmarks");
     await this.db.execute(`DELETE FROM itemsToMerge`);
 
     // Update the structure. The mirror stores structure info in a separate
     // table, like iOS, while Places stores structure info on children. We don't
     // check the parent's merge state here because our merged tree might
     // diverge from the server if we're missing children, or moved children
     // without parents to "unfiled". In that case, we *don't* want to reupload
     // the new local structure to the server.
-    MirrorLog.debug("Updating structure states for local bookmarks");
+    MirrorLog.trace("Updating structure states for local bookmarks");
     await this.db.execute(`DELETE FROM structureToMerge`);
 
-    MirrorLog.debug("Removing remotely deleted items from Places");
+    MirrorLog.trace("Removing remotely deleted items from Places");
     for (let chunk of PlacesSyncUtils.chunkArray(localDeletions,
       SQLITE_MAX_VARIABLE_NUMBER)) {
 
       let guids = chunk.map(({ guid }) => guid);
 
       // Record item removed notifications.
       await this.db.execute(`
         WITH
@@ -1379,17 +1379,17 @@ class SyncedBookmarksMirror {
       await this.db.execute(`
         UPDATE items SET
           needsMerge = 0
         WHERE needsMerge AND
               guid IN (SELECT guid FROM itemsRemoved
                        WHERE NOT isUntagging)`);
     }
 
-    MirrorLog.debug("Flagging remotely deleted items as merged");
+    MirrorLog.trace("Flagging remotely deleted items as merged");
     for (let chunk of PlacesSyncUtils.chunkArray(remoteDeletions,
       SQLITE_MAX_VARIABLE_NUMBER)) {
 
       await this.db.execute(`
         UPDATE items SET
           needsMerge = 0
         WHERE needsMerge AND
               guid IN (${new Array(chunk.length).fill("?").join(",")})`,
@@ -1399,17 +1399,17 @@ class SyncedBookmarksMirror {
 
   /**
    * Records Places observer notifications for removed, added, moved, and
    * changed items.
    *
    * @param {BookmarkObserverRecorder} observersToNotify
    */
   async noteObserverChanges(observersToNotify) {
-    MirrorLog.debug("Recording observer notifications for removed items");
+    MirrorLog.trace("Recording observer notifications for removed items");
     // `ORDER BY v.level DESC` sorts deleted children before parents, to ensure
     // that we update caches in the correct order (bug 1297941). We also order
     // by parent and position so that the notifications are well-ordered for
     // tests.
     let removedItemRows = await this.db.execute(`
       SELECT v.itemId AS id, v.parentId, v.parentGuid, v.position, v.type,
              h.url, v.guid, v.isUntagging
       FROM itemsRemoved v
@@ -1424,17 +1424,17 @@ class SyncedBookmarksMirror {
         urlHref: row.getResultByName("url"),
         guid: row.getResultByName("guid"),
         parentGuid: row.getResultByName("parentGuid"),
         isUntagging: row.getResultByName("isUntagging"),
       };
       observersToNotify.noteItemRemoved(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for changed GUIDs");
+    MirrorLog.trace("Recording observer notifications for changed GUIDs");
     let changedGuidRows = await this.db.execute(`
       SELECT b.id, b.lastModified, b.type, b.guid AS newGuid,
              c.oldGuid, p.id AS parentId, p.guid AS parentGuid
       FROM guidsChanged c
       JOIN moz_bookmarks b ON b.id = c.itemId
       JOIN moz_bookmarks p ON p.id = b.parent
       ORDER BY c.level, p.id, b.position`);
     for await (let row of yieldingIterator(changedGuidRows)) {
@@ -1445,17 +1445,17 @@ class SyncedBookmarksMirror {
         newGuid: row.getResultByName("newGuid"),
         oldGuid: row.getResultByName("oldGuid"),
         parentId: row.getResultByName("parentId"),
         parentGuid: row.getResultByName("parentGuid"),
       };
       observersToNotify.noteGuidChanged(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for new items");
+    MirrorLog.trace("Recording observer notifications for new items");
     let newItemRows = await this.db.execute(`
       SELECT b.id, p.id AS parentId, b.position, b.type, h.url,
              IFNULL(b.title, "") AS title, b.dateAdded, b.guid,
              p.guid AS parentGuid, n.isTagging
       FROM itemsAdded n
       JOIN moz_bookmarks b ON b.guid = n.guid
       JOIN moz_bookmarks p ON p.id = b.parent
       LEFT JOIN moz_places h ON h.id = b.fk
@@ -1471,17 +1471,17 @@ class SyncedBookmarksMirror {
         dateAdded: row.getResultByName("dateAdded"),
         guid: row.getResultByName("guid"),
         parentGuid: row.getResultByName("parentGuid"),
         isTagging: row.getResultByName("isTagging"),
       };
       observersToNotify.noteItemAdded(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for moved items");
+    MirrorLog.trace("Recording observer notifications for moved items");
     let movedItemRows = await this.db.execute(`
       SELECT b.id, b.guid, b.type, p.id AS newParentId, c.oldParentId,
              p.guid AS newParentGuid, c.oldParentGuid,
              b.position AS newPosition, c.oldPosition
       FROM itemsMoved c
       JOIN moz_bookmarks b ON b.id = c.itemId
       JOIN moz_bookmarks p ON p.id = b.parent
       ORDER BY c.level, newParentId, newPosition`);
@@ -1495,17 +1495,17 @@ class SyncedBookmarksMirror {
         newParentGuid: row.getResultByName("newParentGuid"),
         oldParentGuid: row.getResultByName("oldParentGuid"),
         newPosition: row.getResultByName("newPosition"),
         oldPosition: row.getResultByName("oldPosition"),
       };
       observersToNotify.noteItemMoved(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for changed items");
+    MirrorLog.trace("Recording observer notifications for changed items");
     let changedItemRows = await this.db.execute(`
       SELECT b.id, b.guid, b.lastModified, b.type,
              IFNULL(b.title, "") AS newTitle,
              IFNULL(c.oldTitle, "") AS oldTitle,
              h.url AS newURL, i.url AS oldURL,
              p.id AS parentId, p.guid AS parentGuid
       FROM itemsChanged c
       JOIN moz_bookmarks b ON b.id = c.itemId
@@ -1524,31 +1524,31 @@ class SyncedBookmarksMirror {
         newURLHref: row.getResultByName("newURL"),
         oldURLHref: row.getResultByName("oldURL"),
         parentId: row.getResultByName("parentId"),
         parentGuid: row.getResultByName("parentGuid"),
       };
       observersToNotify.noteItemChanged(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for changed annos");
+    MirrorLog.trace("Recording observer notifications for changed annos");
     let annoRows = await this.db.execute(`
       SELECT itemId, annoName, wasRemoved FROM annosChanged
       ORDER BY itemId`);
     for await (let row of yieldingIterator(annoRows)) {
       let id = row.getResultByName("itemId");
       let name = row.getResultByName("annoName");
       if (row.getResultByName("wasRemoved")) {
         observersToNotify.noteAnnoRemoved(id, name);
       } else {
         observersToNotify.noteAnnoSet(id, name);
       }
     }
 
-    MirrorLog.debug("Recording notifications for changed keywords");
+    MirrorLog.trace("Recording notifications for changed keywords");
     let keywordsChangedRows = await this.db.execute(`
       SELECT EXISTS(SELECT 1 FROM itemsAdded WHERE keywordChanged) OR
              EXISTS(SELECT 1 FROM itemsChanged WHERE keywordChanged)
              AS keywordsChanged`);
     observersToNotify.shouldInvalidateKeywords =
       !!keywordsChangedRows[0].getResultByName("keywordsChanged");
   }
 
@@ -2794,17 +2794,17 @@ async function inflateTree(tree, pseudoT
 
 // Executes a function and returns a `{ result, time }` tuple, where `result` is
 // the function's return value, and `time` is the time taken to execute the
 // function.
 async function withTiming(name, func) {
   let startTime = Cu.now();
   let result = await func();
   let elapsedTime = Cu.now() - startTime;
-  MirrorLog.debug(`${name} took ${elapsedTime.toFixed(3)}ms`);
+  MirrorLog.trace(`${name} took ${elapsedTime.toFixed(3)}ms`);
   return { result, time: elapsedTime };
 }
 
 /**
  * Content info for an item in the local or remote tree. This is used to dedupe
  * NEW local items to remote items that don't exist locally. See `makeDupeKey`
  * for how we determine if two items are dupes.
  */
@@ -4577,17 +4577,17 @@ class BookmarkObserverRecorder {
     await this.notifyAnnoObservers();
     if (this.shouldInvalidateLivemarks) {
       await PlacesUtils.livemarks.invalidateCachedLivemarks();
     }
     await this.updateFrecencies();
   }
 
   async updateFrecencies() {
-    MirrorLog.debug("Recalculating frecencies for new URLs");
+    MirrorLog.trace("Recalculating frecencies for new URLs");
     await this.db.execute(`
       UPDATE moz_places SET
         frecency = CALCULATE_FRECENCY(id)
       WHERE frecency = -1`);
   }
 
   noteItemAdded(info) {
     let uri = info.urlHref ? Services.io.newURI(info.urlHref) : null;
@@ -4670,32 +4670,32 @@ class BookmarkObserverRecorder {
     }
     this.annoObserverNotifications.push({
       name: "onItemAnnotationRemoved",
       args: [id, name, PlacesUtils.bookmarks.SOURCES.SYNC],
     });
   }
 
   async notifyBookmarkObservers() {
-    MirrorLog.debug("Notifying bookmark observers");
+    MirrorLog.trace("Notifying bookmark observers");
     let observers = PlacesUtils.bookmarks.getObservers();
     for (let observer of observers) {
       this.notifyObserver(observer, "onBeginUpdateBatch");
       for await (let info of yieldingIterator(this.bookmarkObserverNotifications)) {
         if (info.isTagging && observer.skipTags) {
           continue;
         }
         this.notifyObserver(observer, info.name, info.args);
       }
       this.notifyObserver(observer, "onEndUpdateBatch");
     }
   }
 
   async notifyAnnoObservers() {
-    MirrorLog.debug("Notifying anno observers");
+    MirrorLog.trace("Notifying anno observers");
     let observers = PlacesUtils.annotations.getObservers();
     for (let observer of observers) {
       let wrapped = yieldingIterator(this.annoObserverNotifications);
       for await (let { name, args } of wrapped) {
         this.notifyObserver(observer, name, args);
       }
     }
   }