gh-15088: Add debug log for space sync (gh-15117)

prefs/zen/sync.yaml

@@ -10,3 +10,6 @@
   value: false
   locked: true
   condition: "!@IS_TWILIGHT@"
+
+- name: zen.spaces-sync.debug
+  value: false

src/zen/sync/ZenSpacesSync.sys.mjs

@@ -11,6 +11,7 @@ import { CryptoWrapper } from "resource://services-sync/record.sys.mjs";
 import { SCORE_INCREMENT_XLARGE } from "resource://services-sync/constants.sys.mjs";
 import {
   SIDEBAR_COLLECTED_TOPIC,
+  syncLog,
   ZenSpacesSyncModel,
 } from "resource:///modules/zen/ZenSpacesSyncModel.sys.mjs";
 
@@ -98,6 +99,7 @@ class ZenSpacesSyncTracker extends Tracker {
     }
     try {
       if (ZenSpacesSyncModel.hasPendingChanges()) {
+        syncLog(`tracker: pending changes after ${topic}, requesting sync`);
         this.score += SCORE_INCREMENT_XLARGE;
       }
     } catch (e) {

src/zen/sync/ZenSpacesSyncApplier.sys.mjs

@@ -7,6 +7,7 @@ import {
   LAYOUT_RECORD_ID,
   RECORD_KINDS,
   syncableIconUrl,
+  syncLog,
   ZenSpacesSyncModel,
 } from "resource:///modules/zen/ZenSpacesSyncModel.sys.mjs";
 
@@ -110,6 +111,13 @@ class nsZenSpacesSyncApplier {
       handled.add(record);
     }
 
+    syncLog(
+      `incoming batch: ${incoming.containers.length} containers, ` +
+        `${incoming.spaces.length} spaces, ${incoming.tabs.length} tabs, ` +
+        `${incoming.folders.length} folders, ${incoming.splits.length} splits, ` +
+        `layout=${!!incoming.layout}, ${incoming.deleted.length} tombstones`
+    );
+
     const failed = new Set();
     const fail = (record, e) => {
       failed.add(record.id);
@@ -201,6 +209,21 @@ class nsZenSpacesSyncApplier {
         routed.spaces.push(entry);
       }
     }
+    if (deletions.length) {
+      const matched = new Set([
+        ...routed.tabs,
+        ...routed.folders,
+        ...routed.splits,
+        ...routed.spaces,
+      ]);
+      syncLog("tombstones routed:", {
+        tabs: routed.tabs.map(e => e.key),
+        folders: routed.folders.map(e => e.key),
+        splits: routed.splits.map(e => e.key),
+        spaces: routed.spaces.map(e => e.key),
+        unmatched: deletions.filter(e => !matched.has(e)).map(e => e.key),
+      });
+    }
     return routed;
   }
 
@@ -292,6 +315,13 @@ class nsZenSpacesSyncApplier {
             canonicalJSON(fields.theme ?? null);
         const containerChanged =
           !current || (current.containerTabId ?? 0) !== fields.containerTabId;
+        if (containerChanged) {
+          syncLog(
+            `space ${data.uuid} containerTabId ` +
+              `${current?.containerTabId ?? 0} -> ${fields.containerTabId} ` +
+              `(guid ${data.containerGuid ?? "none"})`
+          );
+        }
         if (!current) {
           list.push(fields);
           changed = true;
@@ -501,6 +531,11 @@ class nsZenSpacesSyncApplier {
 
   #createTab(win, tabId, data) {
     const userContextId = this.#resolveContainerId(data.containerGuid);
+    syncLog(
+      `creating tab ${tabId} ` +
+        `(essential=${!!data.essential}, container=${userContextId})`,
+      data.url
+    );
     const tab = win.gBrowser.addTrustedTab(data.url, {
       createLazyBrowser: true,
       inBackground: true,
@@ -576,12 +611,14 @@ class nsZenSpacesSyncApplier {
       }
     }
     tab.zenStaticIcon = data.hasStaticIcon && icon ? icon : undefined;
-    if (
-      icon &&
-      (data.hasStaticIcon || !tab.linkedPanel) &&
-      syncableIconUrl(tab.getAttribute("image")) !== icon
-    ) {
+    const iconDiffers =
+      icon && syncableIconUrl(tab.getAttribute("image")) !== icon;
+    if (iconDiffers && (data.hasStaticIcon || !tab.linkedPanel)) {
       try {
+        syncLog(
+          `setting synced${data.hasStaticIcon ? " static" : ""} ` +
+            `icon on tab ${tab.id}`
+        );
         win.gBrowser.setIcon(tab, icon);
         lazy.TabStateCache.update(tab.linkedBrowser.permanentKey, {
           image: null,
@@ -677,10 +714,14 @@ class nsZenSpacesSyncApplier {
 
     const isEssential = tab.hasAttribute("zen-essential");
     if (data.essential && !isEssential) {
+      syncLog(`incoming record promotes tab ${tab.id} to essential`);
       win.gZenPinnedTabManager.addToEssentials(tab, { replicating: true });
       return;
     }
     if (!data.essential && isEssential) {
+      console.warn(
+        `ZenSpacesSync: incoming record demotes essential tab ${tab.id}`
+      );
       win.gZenPinnedTabManager.removeEssentials(tab, /* unpin */ false);
     }
     if (data.essential) {
@@ -717,6 +758,14 @@ class nsZenSpacesSyncApplier {
       try {
         const tab = this.#itemIn(win, tabId);
         if (win.gBrowser.isTab(tab)) {
+          if (tab.hasAttribute("zen-essential")) {
+            console.warn(
+              `ZenSpacesSync: incoming tombstone removes essential tab ${tabId}`,
+              tab.linkedBrowser?.currentURI?.spec ?? ""
+            );
+          } else {
+            syncLog(`incoming tombstone removes tab ${tabId}`);
+          }
           this.#removeTab(win, tab);
         }
       } catch (e) {

src/zen/sync/ZenSpacesSyncModel.sys.mjs

@@ -3,6 +3,7 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 import { JSONFile } from "resource://gre/modules/JSONFile.sys.mjs";
+import { XPCOMUtils } from "resource://gre/modules/XPCOMUtils.sys.mjs";
 
 const lazy = {};
 
@@ -14,6 +15,26 @@ ChromeUtils.defineESModuleGetters(lazy, {
     "moz-src:///toolkit/components/contextualidentity/ContextualIdentityService.sys.mjs",
 });
 
+XPCOMUtils.defineLazyPreferenceGetter(
+  lazy,
+  "syncDebug",
+  "zen.spaces-sync.debug",
+  false
+);
+
+/**
+ * Debug logging for the whole Spaces sync pipeline.
+ *
+ * @param {string} message
+ * @param {...any} args
+ */
+export function syncLog(message, ...args) {
+  if (lazy.syncDebug) {
+    // eslint-disable-next-line no-console
+    console.debug(`ZenSpacesSync: ${message}`, ...args);
+  }
+}
+
 export const SIDEBAR_COLLECTED_TOPIC = "zen-sidebar-data-collected";
 
 export const RECORD_KINDS = Object.freeze({
@@ -598,6 +619,15 @@ class nsZenSpacesSyncModel {
         changes[id] = now;
       }
     }
+    if (lazy.syncDebug && Object.keys(changes).length) {
+      const map = this.projections();
+      syncLog(
+        "outgoing diff:",
+        Object.keys(changes).map(id =>
+          current.has(id) ? `${map.get(id)?.kind} ${id}` : `TOMBSTONE ${id}`
+        )
+      );
+    }
     return changes;
   }
 
@@ -634,6 +664,12 @@ class nsZenSpacesSyncModel {
         delete data.uploaded[id];
       }
     }
+    if (lazy.syncDebug && ids.length) {
+      syncLog(
+        "server acknowledged upload:",
+        ids.map(id => (current.has(id) ? id : `${id} (tombstone)`))
+      );
+    }
     this.#file.saveSoon();
   }
 
@@ -653,6 +689,9 @@ class nsZenSpacesSyncModel {
     } else {
       data.uploaded[id] = recordDigest(cleartext.kind, cleartext.data);
     }
+    syncLog(
+      `acknowledged incoming ${cleartext ? cleartext.kind : "tombstone"} ${id}`
+    );
     this.#file.saveSoon();
   }
 }

src/zen/tabs/ZenPinnedTabManager.mjs

@@ -523,6 +523,7 @@ class nsZenPinnedTabManager extends nsZenDOMOperatedFeature {
       // window or on another device, always into the tab's own container
       // section.
       if (!replicating && !this.canEssentialBeAdded(tab)) {
+        this.log(`addToEssentials rejected for ${tab.id}`);
         movedAll = false;
         continue;
       }
@@ -574,6 +575,13 @@ class nsZenPinnedTabManager extends nsZenDOMOperatedFeature {
     for (let i = 0; i < tabs.length; i++) {
       // eslint-disable-next-line no-shadow
       const tab = tabs[i];
+      if (this._canLog) {
+        // eslint-disable-next-line no-console
+        console.trace(
+          `ZenPinnedTabManager: removing tab ${tab.id} from essentials ` +
+            `(unpin=${unpin})`
+        );
+      }
       tab.removeAttribute("zen-essential");
       if (
         gZenWorkspaces.workspaceEnabled &&