Improve logging

Author: alexjg

src/fs_store.rs

@@ -164,7 +164,9 @@ impl FsStore {
         Ok(result.into_iter().collect())
     }
 
+    #[tracing::instrument(skip(self, changes))]
     pub fn append(&self, id: &DocumentId, changes: &[u8]) -> Result<(), Error> {
+        tracing::debug!("writing incremental change");
         let paths = DocIdPaths::from(id);
         std::fs::create_dir_all(paths.level2_path(&self.root)).map_err(|e| {
             Error(ErrorKind::CreateLevel2Path(
@@ -179,7 +181,9 @@ impl FsStore {
         Ok(())
     }
 
+    #[tracing::instrument(skip(self, full_doc))]
     pub fn compact(&self, id: &DocumentId, full_doc: &[u8]) -> Result<(), Error> {
+        tracing::debug!("compacting document");
         let paths = DocIdPaths::from(id);
 
         // Load all the data we have into a doc
@@ -211,11 +215,8 @@ impl FsStore {
                     let path = paths.chunk_path(&self.root, snapshot);
 
                     if path == just_wrote {
-                        tracing::error!(
-                            ?path,
-                            "Somehow trying to delete the same path we just wrote to. Not today \
-                            Satan"
-                        );
+                        // This can happen if for some reason `compact` is called when the only thing
+                        // on disk is a snapshot containing the changes we are being asked to compact
                         continue;
                     }
 
@@ -415,7 +416,7 @@ impl Chunks {
     fn load(root: &Path, doc_id: &DocumentId) -> Result<Option<Self>, Error> {
         let doc_id_hash = DocIdPaths::from(doc_id);
         let level2_path = doc_id_hash.level2_path(root);
-        tracing::debug!(
+        tracing::trace!(
             root=%root.display(),
             doc_id=?doc_id,
             doc_path=%level2_path.display(),
@@ -459,7 +460,7 @@ impl Chunks {
                 tracing::warn!(bad_file=%path.display(), "unexpected non-chunk file in level2 path");
                 continue;
             };
-            tracing::debug!(chunk_path=%path.display(), "reading chunk file");
+            tracing::trace!(chunk_path=%path.display(), "reading chunk file");
             let contents = match std::fs::read(&path) {
                 Ok(c) => c,
                 Err(e) => {

src/repo.rs

@@ -532,7 +532,8 @@ impl DocState {
                         let pinned = Pin::new(&mut storage_fut);
                         match pinned.poll(&mut Context::from_waker(&waker)) {
                             Poll::Ready(Ok(_)) => None,
-                            Poll::Ready(Err(_)) => {
+                            Poll::Ready(Err(e)) => {
+                                tracing::error!(err=?e, "error in save operation");
                                 // TODO: propagate error to doc handle.
                                 // `with_doc_mut` could return a future for this.
                                 None
@@ -555,7 +556,8 @@ impl DocState {
                         let pinned = Pin::new(&mut storage_fut);
                         let res = match pinned.poll(&mut Context::from_waker(&waker)) {
                             Poll::Ready(Ok(_)) => None,
-                            Poll::Ready(Err(_)) => {
+                            Poll::Ready(Err(e)) => {
+                                tracing::error!(err=?e, "error in storage operation");
                                 // TODO: propagate error to doc handle.
                                 // `with_doc_mut` could return a future for this.
                                 None
@@ -880,6 +882,9 @@ impl DocumentInfo {
             changes.len()
         };
         let has_patches = count > 0;
+        if has_patches {
+            tracing::debug!("doc has changed");
+        }
         self.changes_since_last_compact = self.changes_since_last_compact.saturating_add(count);
         has_patches
     }
@@ -902,13 +907,15 @@ impl DocumentInfo {
         let should_compact =
             self.changes_since_last_compact > self.allowable_changes_until_compaction;
         let (storage_fut, new_heads) = if should_compact {
+            tracing::trace!(%document_id, "compacting document");
             let (to_save, new_heads) = {
                 let doc = self.document.read();
                 (doc.automerge.save(), doc.automerge.get_heads())
             };
             self.changes_since_last_compact = 0;
             (storage.compact(document_id.clone(), to_save), new_heads)
         } else {
+            tracing::trace!(%document_id, "writing incremental chunk");
             let (to_save, new_heads) = {
                 let doc = self.document.read();
                 (