eagerepo: add tracing messages

Summary: Make it easier to check whether APIs in EagerRepo is called or not.

Reviewed By: andll

Differential Revision: D27955426

fbshipit-source-id: 27ca505c63596368cff98642de010b5b5717454c

eden/scm/lib/eagerepo/Cargo.toml

@@ -14,6 +14,7 @@ http = "0.2"
 metalog = { path = "../metalog" }
 minibytes = { path = "../minibytes" }
 thiserror = "1.0"
+tracing = "0.1"
 zstore = { path = "../zstore" }
 
 [dev-dependencies]

eden/scm/lib/eagerepo/src/api.rs

@@ -40,6 +40,8 @@ use futures::StreamExt;
 use http::StatusCode;
 use http::Version;
 use std::collections::HashSet;
+use tracing::debug;
+use tracing::trace;
 
 #[async_trait::async_trait]
 impl EdenApi for EagerRepo {
@@ -53,6 +55,7 @@ impl EdenApi for EagerRepo {
         keys: Vec<Key>,
         _progress: Option<ProgressCallback>,
     ) -> edenapi::Result<Fetch<FileEntry>> {
+        debug!("files {}", debug_key_list(&keys));
         let mut values = Vec::with_capacity(keys.len());
         for key in keys {
             let id = key.hgid;
@@ -78,6 +81,7 @@ impl EdenApi for EagerRepo {
         _length: Option<u32>,
         _progress: Option<ProgressCallback>,
     ) -> edenapi::Result<Fetch<HistoryEntry>> {
+        debug!("history {}", debug_key_list(&keys));
         let mut values = Vec::new();
         let mut visited: HashSet<Key> = Default::default();
         let mut to_visit: Vec<Key> = keys;
@@ -129,6 +133,7 @@ impl EdenApi for EagerRepo {
         attributes: Option<TreeAttributes>,
         _progress: Option<ProgressCallback>,
     ) -> edenapi::Result<Fetch<Result<TreeEntry, edenapi::types::EdenApiServerError>>> {
+        debug!("trees {}", debug_key_list(&keys));
         let mut values = Vec::new();
         let attributes = attributes.unwrap_or_default();
         if attributes.child_metadata {
@@ -175,6 +180,7 @@ impl EdenApi for EagerRepo {
         hgids: Vec<HgId>,
         _progress: Option<ProgressCallback>,
     ) -> edenapi::Result<Fetch<CommitRevlogData>> {
+        debug!("revlog_data {}", debug_hgid_list(&hgids));
         let mut values = Vec::new();
         for id in hgids {
             let data = self.get_sha1_blob_for_api(id)?;
@@ -193,6 +199,7 @@ impl EdenApi for EagerRepo {
         _repo: String,
         _progress: Option<ProgressCallback>,
     ) -> edenapi::Result<dag::CloneData<HgId>> {
+        debug!("clone_data");
         let clone_data = self.dag().export_clone_data().await.map_err(map_dag_err)?;
         check_convert_to_hgid(clone_data.idmap.values())?;
         let clone_data = dag::CloneData {
@@ -317,6 +324,7 @@ impl EdenApi for EagerRepo {
         _repo: String,
         hgids: Vec<HgId>,
     ) -> edenapi::Result<Fetch<CommitKnownResponse>> {
+        debug!("commit_known {}", debug_hgid_list(&hgids));
         let mut values = Vec::new();
         for id in hgids {
             let known = self.get_sha1_blob(id).map_err(map_crate_err)?.is_some();
@@ -335,6 +343,11 @@ impl EdenApi for EagerRepo {
         heads: Vec<HgId>,
         common: Vec<HgId>,
     ) -> Result<Fetch<CommitGraphEntry>, EdenApiError> {
+        debug!(
+            "commit_graph {} {}",
+            debug_hgid_list(&heads),
+            debug_hgid_list(&common),
+        );
         let heads =
             dag::Set::from_static_names(heads.iter().map(|v| Vertex::copy_from(v.as_ref())));
         let common =
@@ -365,6 +378,7 @@ impl EdenApi for EagerRepo {
         bookmarks: Vec<String>,
         _progress: Option<ProgressCallback>,
     ) -> edenapi::Result<Fetch<BookmarkEntry>> {
+        debug!("bookmarks {}", debug_string_list(&bookmarks),);
         let mut values = Vec::new();
         let map = self.get_bookmarks_map().map_err(map_crate_err)?;
         for name in bookmarks {
@@ -383,11 +397,17 @@ impl EagerRepo {
     fn get_sha1_blob_for_api(&self, id: HgId) -> edenapi::Result<minibytes::Bytes> {
         // Emulate the HTTP errors.
         match self.get_sha1_blob(id) {
-            Ok(None) => Err(EdenApiError::HttpError {
+            Ok(None) => {
-                status: StatusCode::NOT_FOUND,
+                trace!(" not found: {}", id.to_hex());
-                message: format!("{} cannot be found", id.to_hex()),
+                Err(EdenApiError::HttpError {
-            }),
+                    status: StatusCode::NOT_FOUND,
-            Ok(Some(data)) => Ok(data),
+                    message: format!("{} cannot be found", id.to_hex()),
+                })
+            }
+            Ok(Some(data)) => {
+                trace!(" found: {}, {} bytes", id.to_hex(), data.len());
+                Ok(data)
+            }
             Err(e) => Err(EdenApiError::HttpError {
                 status: StatusCode::INTERNAL_SERVER_ERROR,
                 message: format!("{:?}", e),
@@ -478,3 +498,30 @@ fn map_dag_err(e: dag::Error) -> EdenApiError {
 fn map_crate_err(e: crate::Error) -> EdenApiError {
     EdenApiError::Other(e.into())
 }
+
+fn debug_key_list(keys: &[Key]) -> String {
+    debug_list(keys, |k| k.hgid.to_hex())
+}
+
+fn debug_hgid_list(ids: &[HgId]) -> String {
+    debug_list(ids, |i| i.to_hex())
+}
+
+fn debug_string_list(s: &[String]) -> String {
+    debug_list(s, |s| s.clone())
+}
+
+fn debug_list<T>(keys: &[T], func: impl Fn(&T) -> String) -> String {
+    let limit = 5;
+    let msg = keys
+        .iter()
+        .take(limit)
+        .map(|k| func(k))
+        .collect::<Vec<_>>()
+        .join(", ");
+    if keys.len() > limit {
+        format!("{} and {} more", msg, keys.len() - limit)
+    } else {
+        msg
+    }
+}

eden/scm/tests/test-eager-exchange.t

@@ -3,7 +3,7 @@
   $ configure modern
 
   $ setconfig paths.default=eager:$TESTTMP/e1 ui.traceback=1
-  $ export LOG=edenscm::mercurial::eagerpeer=trace
+  $ export LOG=edenscm::mercurial::eagerpeer=trace,eagerepo=trace
 
 Disable SSH:
 
@@ -22,10 +22,13 @@ Push:
 
   $ hg push -r $C --to master --create
   pushing rev dc0947a82db8 to destination eager://$TESTTMP/e1 bookmark master
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict()
+   DEBUG eagerepo::api: commit_known dc0947a82db884575bb76ea10ac97b08536bfa03
    TRACE edenscm::mercurial::eagerpeer: known dc0947a82db884575bb76ea10ac97b08536bfa03: False
    DEBUG edenscm::mercurial::eagerpeer: heads = []
   searching for changes
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict()
    TRACE edenscm::mercurial::eagerpeer: adding   blob 005d992c5dcf32993668f7cede29d296c494a5d9
    TRACE edenscm::mercurial::eagerpeer: adding   tree 41b34f08c1356f6ad068e9ab9b43d984245111aa
@@ -34,23 +37,29 @@ Push:
    TRACE edenscm::mercurial::eagerpeer: adding   tree 5a538d6dd01b4058a549747c7947ce2dbf29f2ae
    TRACE edenscm::mercurial::eagerpeer: adding commit dc0947a82db884575bb76ea10ac97b08536bfa03
    DEBUG edenscm::mercurial::eagerpeer: flushed
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict()
    DEBUG edenscm::mercurial::eagerpeer: flushed
    DEBUG edenscm::mercurial::eagerpeer: pushkey bookmarks 'master': '' => 'dc0947a82db884575bb76ea10ac97b08536bfa03' (success)
   exporting bookmark master
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
 
   $ hg push -r $B --allow-anon
   pushing to eager://$TESTTMP/e1
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
+   DEBUG eagerepo::api: commit_known 112478962961147124edd43549aedd1a335e44bf, dc0947a82db884575bb76ea10ac97b08536bfa03
    TRACE edenscm::mercurial::eagerpeer: known 112478962961147124edd43549aedd1a335e44bf: False
    TRACE edenscm::mercurial::eagerpeer: known dc0947a82db884575bb76ea10ac97b08536bfa03: True
   searching for changes
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
    TRACE edenscm::mercurial::eagerpeer: adding   blob 35e7525ce3a48913275d7061dd9a867ffef1e34d
    TRACE edenscm::mercurial::eagerpeer: adding   tree eb79886383871977bccdb3000c275a279f0d4c99
    TRACE edenscm::mercurial::eagerpeer: adding commit 112478962961147124edd43549aedd1a335e44bf
    DEBUG edenscm::mercurial::eagerpeer: flushed
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
 
 Pull:
@@ -60,25 +69,40 @@ Pull:
   $ hg debugchangelog --migrate lazy
   $ hg pull -B master
   pulling from eager://$TESTTMP/e1
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
+   DEBUG eagerepo::api: commit_known 
+   DEBUG eagerepo::api: commit_graph dc0947a82db884575bb76ea10ac97b08536bfa03 
    TRACE edenscm::mercurial::eagerpeer: graph node 426bada5c67598ca65036d57d9e4b64b0c1ce7a0 []
    TRACE edenscm::mercurial::eagerpeer: graph node dc0947a82db884575bb76ea10ac97b08536bfa03 ['426bada5c67598ca65036d57d9e4b64b0c1ce7a0']
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(phases, []) = sortdict()
 
   $ hg pull -r $B
   pulling from eager://$TESTTMP/e1
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
+   DEBUG eagerepo::api: commit_known 112478962961147124edd43549aedd1a335e44bf
    TRACE edenscm::mercurial::eagerpeer: known 112478962961147124edd43549aedd1a335e44bf: True
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
+   DEBUG eagerepo::api: bookmarks master
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')])
+   DEBUG eagerepo::api: commit_known dc0947a82db884575bb76ea10ac97b08536bfa03
    TRACE edenscm::mercurial::eagerpeer: known dc0947a82db884575bb76ea10ac97b08536bfa03: True
   searching for changes
+   DEBUG eagerepo::api: commit_graph 112478962961147124edd43549aedd1a335e44bf, dc0947a82db884575bb76ea10ac97b08536bfa03 dc0947a82db884575bb76ea10ac97b08536bfa03
    TRACE edenscm::mercurial::eagerpeer: graph node 112478962961147124edd43549aedd1a335e44bf ['426bada5c67598ca65036d57d9e4b64b0c1ce7a0']
    DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(phases, []) = sortdict()
 
   $ hg log -Gr 'all()' -T '{desc} {remotenames}'
+   DEBUG eagerepo::api: revlog_data 112478962961147124edd43549aedd1a335e44bf, dc0947a82db884575bb76ea10ac97b08536bfa03, 426bada5c67598ca65036d57d9e4b64b0c1ce7a0
+   TRACE eagerepo::api:  found: 112478962961147124edd43549aedd1a335e44bf, 94 bytes
+   TRACE eagerepo::api:  found: dc0947a82db884575bb76ea10ac97b08536bfa03, 94 bytes
+   TRACE eagerepo::api:  found: 426bada5c67598ca65036d57d9e4b64b0c1ce7a0, 94 bytes
   o  B
   │
   │ o  C remote/master