Add more logging around active_drop_spawns

Author: palfrey

nativelink-store/src/filesystem_store.rs

@@ -122,9 +122,15 @@ impl Drop for EncodedFilePath {
 
         let file_path = self.get_file_path().to_os_string();
         let shared_context = self.shared_context.clone();
-        shared_context
+        // .fetch_add returns previous value, so we add one to get approximate current value
+        let current_active_drop_spawns = shared_context
             .active_drop_spawns
-            .fetch_add(1, Ordering::Relaxed);
+            .fetch_add(1, Ordering::Relaxed)
+            + 1;
+        debug!(
+            ?current_active_drop_spawns,
+            "Spawned a filesystem_delete_file"
+        );
         background_spawn!("filesystem_delete_file", async move {
             let result = fs::remove_file(&file_path)
                 .await
@@ -134,9 +140,15 @@ impl Drop for EncodedFilePath {
             } else {
                 debug!(?file_path, "File deleted",);
             }
-            shared_context
+            // .fetch_sub returns previous value, so we subtract one to get approximate current value
+            let current_active_drop_spawns = shared_context
                 .active_drop_spawns
-                .fetch_sub(1, Ordering::Relaxed);
+                .fetch_sub(1, Ordering::Relaxed)
+                - 1;
+            debug!(
+                ?current_active_drop_spawns,
+                "Dropped a filesystem_delete_file"
+            );
         });
     }
 }

nativelink-store/tests/filesystem_store_test.rs

@@ -367,6 +367,13 @@ async fn temp_files_get_deleted_on_replace_test() -> Result<(), Error> {
         tokio::task::yield_now().await;
     }
 
+    assert!(logs_contain(
+        "Spawned a filesystem_delete_file current_active_drop_spawns=1"
+    ));
+    assert!(logs_contain(
+        "Dropped a filesystem_delete_file current_active_drop_spawns=0"
+    ));
+
     check_temp_empty(&temp_path).await
 }