Fix tracing

crates/hdk/Cargo.toml

@@ -27,7 +27,7 @@ test_utils = [
 properties = ["holochain_zome_types/properties"]
 
 [dependencies]
-holochain_deterministic_integrity = { version = "0.0.6", path = "../holochain_deterministic_integrity" }
+holochain_deterministic_integrity = { version = "0.0.6", path = "../holochain_deterministic_integrity", features = ["trace"] }
 hdk_derive = { version = "0.0.33", path = "../hdk_derive" }
 holo_hash = { version = "0.0.25", path = "../holo_hash" }
 holochain_wasmer_guest = "=0.0.77"

crates/holochain/src/core/ribosome/host_fn/trace.rs

@@ -6,6 +6,17 @@ use once_cell::unsync::Lazy;
 use std::sync::Arc;
 use tracing::*;
 
+#[cfg(test)]
+use once_cell::sync::Lazy as SyncLazy;
+#[cfg(test)]
+use std::sync::atomic::AtomicBool;
+
+#[cfg(test)]
+static CAPTURE: AtomicBool = AtomicBool::new(false);
+#[cfg(test)]
+static CAPTURED: SyncLazy<Arc<std::sync::Mutex<Vec<TraceMsg>>>> =
+    SyncLazy::new(|| Arc::new(std::sync::Mutex::new(Vec::new())));
+
 #[instrument(skip(input))]
 pub fn wasm_trace(input: TraceMsg) {
     match input.level {
@@ -30,21 +41,26 @@ pub fn trace(
         .with_env_filter(tracing_subscriber::EnvFilter::new((*wasm_log).clone()))
         .with_target(false)
         .finish();
+
+    #[cfg(test)]
+    if CAPTURE.load(std::sync::atomic::Ordering::Relaxed) {
+        CAPTURED.lock().unwrap().push(input.clone());
+    }
+
     tracing::subscriber::with_default(collector, || wasm_trace(input));
     Ok(())
 }
 
 #[cfg(test)]
 #[cfg(feature = "slow_tests")]
 pub mod wasm_test {
-    use super::trace;
+    use super::*;
 
+    use crate::core::ribosome::wasm_test::RibosomeTestFixture;
     use crate::fixt::CallContextFixturator;
     use crate::fixt::RealRibosomeFixturator;
     use holochain_wasm_test_utils::TestWasm;
-    use holochain_zome_types::prelude::*;
     use std::sync::Arc;
-    use crate::core::ribosome::wasm_test::RibosomeTestFixture;
 
     /// we can get an entry hash out of the fn directly
     #[tokio::test(flavor = "multi_thread")]
@@ -56,7 +72,7 @@ pub mod wasm_test {
             .next()
             .unwrap();
         let input = TraceMsg {
-            level: Level::DEBUG,
+            level: holochain_types::prelude::Level::DEBUG,
             msg: "ribosome trace works".to_string(),
         };
 
@@ -67,11 +83,40 @@ pub mod wasm_test {
 
     #[tokio::test(flavor = "multi_thread")]
     async fn wasm_trace_test() {
+        CAPTURE.store(true, std::sync::atomic::Ordering::SeqCst);
         observability::test_run().ok();
         let RibosomeTestFixture {
             conductor, alice, ..
         } = RibosomeTestFixture::new(TestWasm::Debug).await;
 
         let _: () = conductor.call(&alice, "debug", ()).await;
+        let r: Vec<_> = CAPTURED.lock().unwrap().clone();
+        let expect = vec![
+            TraceMsg {
+                msg: "test_wasm_debug:debug/src/lib.rs:5 tracing works!".to_string(),
+                level: holochain_types::prelude::Level::TRACE,
+            },
+            TraceMsg {
+                msg: "test_wasm_debug:debug/src/lib.rs:6 debug works".to_string(),
+                level: holochain_types::prelude::Level::DEBUG,
+            },
+            TraceMsg {
+                msg: "test_wasm_debug:debug/src/lib.rs:7 info works".to_string(),
+                level: holochain_types::prelude::Level::INFO,
+            },
+            TraceMsg {
+                msg: "test_wasm_debug:debug/src/lib.rs:8 warn works".to_string(),
+                level: holochain_types::prelude::Level::WARN,
+            },
+            TraceMsg {
+                msg: "test_wasm_debug:debug/src/lib.rs:9 error works".to_string(),
+                level: holochain_types::prelude::Level::ERROR,
+            },
+            TraceMsg {
+                msg: "test_wasm_debug:debug/src/lib.rs:10 foo = \"fields\"; bar = \"work\"; too".to_string(),
+                level: holochain_types::prelude::Level::DEBUG,
+            },
+        ];
+        assert_eq!(r, expect);
     }
-}
+}

crates/holochain_deterministic_integrity/CHANGELOG.md

@@ -4,6 +4,8 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 
 ## Unreleased
 
+- Fix broken wasm tracing. [PR](https://github.com/holochain/holochain/pull/1389).
+
 ## 0.0.6
 
 ## 0.0.5

crates/holochain_deterministic_integrity/src/map_extern.rs

@@ -1,14 +1,27 @@
 use crate::prelude::*;
 
+#[cfg(feature = "trace")]
+#[doc(hidden)]
+pub fn make_subscriber() -> impl Drop {
+    crate::prelude::tracing::subscriber::set_default(crate::trace::WasmSubscriber::default())
+}
+
+#[cfg(not(feature = "trace"))]
+#[doc(hidden)]
+/// Needed as a noop for map_extern! when trace is off.
+pub fn make_subscriber() -> impl Drop {
+    struct Noop;
+    impl Drop for Noop {
+        fn drop(&mut self) {}
+    }
+    Noop
+}
+
 #[macro_export]
 macro_rules! map_extern_preamble {
     ( $guest_ptr:ident, $len:ident, $inner:ident, $input:ty, $output:ty ) => {
         // Setup tracing.
-        // @TODO feature flag this?
-        #[cfg(feature = "trace")]
-        let _subscriber_guard = $crate::prelude::tracing::subscriber::set_default(
-            $crate::trace::WasmSubscriber::default()
-        );
+        let _subscriber_guard = $crate::map_extern::make_subscriber();
 
         // Deserialize the input from the host.
         let extern_io: $crate::prelude::ExternIO = match $crate::prelude::host_args($guest_ptr, $len) {
@@ -19,7 +32,6 @@ macro_rules! map_extern_preamble {
             Ok(v) => v,
             Err(e) => {
                 let bytes = extern_io.0;
-                #[cfg(feature = "trace")]
                 $crate::prelude::error!(output_type = std::any::type_name::<$output>(), bytes = ?bytes, "{}", e);
                 return $crate::prelude::return_err_ptr($crate::prelude::WasmError::Deserialize(bytes));
             }

crates/holochain_deterministic_integrity/src/prelude.rs

@@ -42,6 +42,17 @@ pub use tracing;
 #[cfg(feature = "trace")]
 pub use tracing::{debug, error, info, instrument, trace, warn};
 
+#[cfg(not(feature = "trace"))]
+/// Needed as a noop for map_extern! when trace is off.
+pub use crate::error;
+
+#[cfg(not(feature = "trace"))]
+#[macro_export]
+/// Needed as a noop for map_extern! when trace is off.
+macro_rules! error {
+    ($($field:tt)*) => {};
+}
+
 #[cfg(feature = "mock")]
 pub use mockall;
 

crates/test_utils/wasm/wasm_workspace/integrity_zome/src/lib.rs

@@ -100,7 +100,6 @@ fn call_zome_info(zome_info_input: ()) -> ExternResult<ZomeInfo> {
     HDI.with(|i| i.borrow().zome_info(zome_info_input))
 }
 // Trace
-#[cfg(feature = "trace")]
 #[hdk_extern]
 fn call_trace(trace_msg: TraceMsg) -> ExternResult<()> {
     HDI.with(|i| i.borrow().trace(trace_msg))