commitcloud: add blackbox logging of cloud changes

Summary:
Add blackbox logging of syncing to or from the commit cloud workspace,
including which changes are being submitted.

Also log when obsmarker fixup happens in blackbox.

Reviewed By: quark-zju

Differential Revision: D16961281

fbshipit-source-id: 0d0f675d77ab3446198703b31eea940dae3bdd85

edenscm/hgext/commitcloud/sync.py

@@ -11,6 +11,7 @@ import socket
 import time
 
 from edenscm.mercurial import (
+    blackbox,
     exchange,
     extensions,
     hg,
@@ -205,6 +206,35 @@ def sync(
     return _maybeupdateworkingcopy(repo, startnode)
 
 
+def logsyncop(repo, op, version, oldheads, newheads, oldbm, newbm, oldrbm, newrbm):
+    oldheadsset = set(oldheads)
+    newheadsset = set(newheads)
+    oldbmset = set(oldbm)
+    newbmset = set(newbm)
+    oldrbmset = set(oldrbm)
+    newrbmset = set(newrbm)
+    addedheads = blackbox.shortlist([h for h in newheads if h not in oldheadsset])
+    removedheads = blackbox.shortlist([h for h in oldheads if h not in newheadsset])
+    addedbm = blackbox.shortlist([h for h in newbm if h not in oldbmset])
+    removedbm = blackbox.shortlist([h for h in oldbm if h not in newbmset])
+    addedrbm = blackbox.shortlist([h for h in newrbm if h not in oldrbmset])
+    removedrbm = blackbox.shortlist([h for h in oldrbm if h not in newrbmset])
+    blackbox.log(
+        {
+            "commit_cloud_sync": {
+                "op": op,
+                "version": version,
+                "added_heads": addedheads,
+                "removed_heads": removedheads,
+                "added_bookmarks": addedbm,
+                "removed_bookmarks": removedbm,
+                "added_remote_bookmarks": addedrbm,
+                "removed_remote_bookmarks": removedrbm,
+            }
+        }
+    )
+
+
 def _maybeupdateworkingcopy(repo, currentnode):
     ui = repo.ui
 
@@ -404,15 +434,14 @@ def _applycloudchanges(repo, remotepath, lastsyncstate, cloudrefs, maxage, state
             )
         )
         if cloudvisibleonly or cloudhiddenonly:
-            repo.ui.warn(
-                _(
-                    "detected obsmarker inconsistency (fixing by obsoleting [%s] and reviving [%s])\n"
-                )
-                % (
-                    ", ".join([nodemod.short(ctx.node()) for ctx in cloudhiddenonly]),
-                    ", ".join([nodemod.short(ctx.node()) for ctx in cloudvisibleonly]),
-                )
+            msg = _(
+                "detected obsmarker inconsistency (fixing by obsoleting [%s] and reviving [%s])\n"
+            ) % (
+                ", ".join([nodemod.short(ctx.node()) for ctx in cloudhiddenonly]),
+                ", ".join([nodemod.short(ctx.node()) for ctx in cloudvisibleonly]),
             )
+            repo.ui.log("commitcloud_sync", msg)
+            repo.ui.warn(msg)
             repo._commitcloudskippendingobsmarkers = True
             with repo.lock():
                 obsolete.createmarkers(repo, [(ctx, ()) for ctx in cloudhiddenonly])
@@ -420,6 +449,17 @@ def _applycloudchanges(repo, remotepath, lastsyncstate, cloudrefs, maxage, state
             repo._commitcloudskippendingobsmarkers = False
 
     # We have now synced the repo to the cloud version.  Store this.
+    logsyncop(
+        repo,
+        "from_cloud",
+        cloudrefs.version,
+        lastsyncstate.heads,
+        cloudrefs.heads,
+        lastsyncstate.bookmarks,
+        cloudrefs.bookmarks,
+        lastsyncstate.remotebookmarks,
+        newremotebookmarks,
+    )
     lastsyncstate.update(
         cloudrefs.version,
         cloudrefs.heads,
@@ -822,6 +862,17 @@ def _submitlocalchanges(repo, reponame, workspacename, lastsyncstate, failed, se
         newremotebookmarks,
     )
     if synced:
+        logsyncop(
+            repo,
+            "to_cloud",
+            cloudrefs.version,
+            lastsyncstate.heads,
+            newcloudheads,
+            lastsyncstate.bookmarks,
+            newcloudbookmarks,
+            oldremotebookmarks,
+            newremotebookmarks,
+        )
         lastsyncstate.update(
             cloudrefs.version,
             newcloudheads,

lib/blackbox/src/event.rs

@@ -69,6 +69,34 @@ pub enum Event {
         duration_ms: u64,
     },
 
+    /// Commit Cloud Sync
+    #[serde(rename = "CCS", alias = "commit_cloud_sync")]
+    CommitCloudSync {
+        #[serde(rename = "O", alias = "op")]
+        op: CommitCloudSyncOp,
+
+        #[serde(rename = "V", alias = "version")]
+        version: u64,
+
+        #[serde(rename = "AH", alias = "added_heads")]
+        added_heads: ShortList,
+
+        #[serde(rename = "RH", alias = "removed_heads")]
+        removed_heads: ShortList,
+
+        #[serde(rename = "AB", alias = "added_bookmarks")]
+        added_bookmarks: ShortList,
+
+        #[serde(rename = "RB", alias = "removed_bookmarks")]
+        removed_bookmarks: ShortList,
+
+        #[serde(rename = "ARB", alias = "added_remote_bookmarks")]
+        added_remote_bookmarks: ShortList,
+
+        #[serde(rename = "RRB", alias = "removed_remote_bookmarks")]
+        removed_remote_bookmarks: ShortList,
+    },
+
     /// A subset of interesting configs.
     #[serde(rename = "C", alias = "config")]
     Config {
@@ -405,6 +433,16 @@ pub enum BlockedOp {
     MergeTool,
 }
 
+#[serde_alt]
+#[derive(Serialize, Deserialize, Debug, PartialEq)]
+pub enum CommitCloudSyncOp {
+    #[serde(rename = "F", alias = "from_cloud")]
+    FromCloud,
+
+    #[serde(rename = "T", alias = "to_cloud")]
+    ToCloud,
+}
+
 fn is_default<T: PartialEq + Default>(value: &T) -> bool {
     value == &Default::default()
 }
@@ -462,6 +500,44 @@ impl fmt::Display for Event {
                 )?,
                 None => write!(f, "[blocked] {:?} blocked for {} ms", op, duration_ms)?,
             },
+            CommitCloudSync {
+                op,
+                version,
+                added_heads,
+                removed_heads,
+                added_bookmarks,
+                removed_bookmarks,
+                added_remote_bookmarks,
+                removed_remote_bookmarks,
+            } => {
+                let direction = match op {
+                    CommitCloudSyncOp::ToCloud => "to",
+                    CommitCloudSyncOp::FromCloud => "from",
+                };
+                write!(
+                    f,
+                    "[commit_cloud_sync] sync {} cloud version {}",
+                    direction, version
+                )?;
+                if added_heads.len > 0 {
+                    write!(f, "; heads added {}", added_heads)?;
+                }
+                if removed_heads.len > 0 {
+                    write!(f, "; heads removed {}", removed_heads)?;
+                }
+                if added_bookmarks.len > 0 {
+                    write!(f, "; bookmarks added {}", added_bookmarks)?;
+                }
+                if removed_bookmarks.len > 0 {
+                    write!(f, "; bookmarks removed {}", removed_bookmarks)?;
+                }
+                if added_remote_bookmarks.len > 0 {
+                    write!(f, "; remote bookmarks added {}", added_remote_bookmarks)?;
+                }
+                if removed_remote_bookmarks.len > 0 {
+                    write!(f, "; remote bookmarks removed {}", removed_remote_bookmarks)?;
+                }
+            }
             Config { items, interactive } => {
                 let interactive = if *interactive {
                     "interactive"