Integrate Tracing into Query Executor

Cargo.toml

@@ -16,10 +16,11 @@ cfg-if = "1"
 js-sys = {version = "0.3.64", optional = true}
 gloo-timers = { version = "0.2.6", optional = true, features = ["futures"] }
 tokio = { version = "1.29.1", optional = true, features = ["time"]}
+tracing = "0.1.37"
 
 [features]
 hydrate = ["dep:js-sys", "dep:gloo-timers"] 
 ssr = ["dep:tokio"]
 
 [package.metadata.docs.rs]
-all-features = true
+all-features = true

example/start-axum/Cargo.toml

@@ -26,9 +26,18 @@ tracing = { version = "0.1.37", optional = true }
 http = "0.2.8"
 serde = "1.0.171"
 leptos_query = { path = "../../"}
+tracing-subscriber = { version = "0.3.17", optional = true } 
+tracing-subscriber-wasm = { version = "0.1.0", optional = true }
 
 [features]
-hydrate = ["leptos/hydrate", "leptos_meta/hydrate", "leptos_router/hydrate", "leptos_query/hydrate"]
+hydrate = [
+    "leptos/hydrate", 
+    "leptos_meta/hydrate", 
+    "leptos_router/hydrate", 
+    "leptos_query/hydrate", 
+    "tracing-subscriber",
+    "tracing-subscriber-wasm"
+]
 ssr = [
     "dep:axum",
     "dep:tokio",

example/start-axum/src/app.rs

@@ -194,7 +194,8 @@ fn Post(cx: Scope, #[prop(into)] post_id: MaybeSignal<u32>) -> impl IntoView {
         refetch,
     } = use_post_query(cx, post_id);
 
-    create_effect(cx, move |_| log!("State: {:#?}", state.get()));
+    // Log the state of the query.
+    // create_effect(cx, move |_| log!("State: {:#?}", state.get()));
 
     view! { cx,
         <div class="container">
@@ -222,16 +223,15 @@ fn Post(cx: Scope, #[prop(into)] post_id: MaybeSignal<u32>) -> impl IntoView {
                     view! { cx, <h2>"Loading..."</h2> }
                 }>
                     <h2>
-                        {
-                           data
-                            .get()
-                            .map(|post| {
-                                match post {
-                                    Some(post) => post,
-                                    None => "Not Found".into(),
-                                }
-                            })
-                        }
+                        {move || {
+                            data.get()
+                                .map(|post| {
+                                    match post {
+                                        Some(post) => post,
+                                        None => "Not Found".into(),
+                                    }
+                                })
+                        }}
                     </h2>
                 </Transition>
             </div>

example/start-axum/src/lib.rs

@@ -11,12 +11,23 @@ cfg_if! { if #[cfg(feature = "hydrate")] {
 
     #[wasm_bindgen]
     pub fn hydrate() {
-        // initializes logging using the `log` crate
-        _ = console_log::init_with_level(log::Level::Debug);
-        console_error_panic_hook::set_once();
-
+        setup_logging();
         leptos::mount_to_body(move |cx| {
             view! { cx, <App/> }
         });
     }
+
+    /// Setup browser console logging using [tracing_subscriber_wasm]
+    fn setup_logging() {
+        tracing_subscriber::fmt()
+          .with_writer(
+            // To avoide trace events in the browser from showing their
+            // JS backtrace, which is very annoying, in my opinion
+            tracing_subscriber_wasm::MakeConsoleWriter::default().map_trace_level_to(tracing::Level::DEBUG),
+          )
+          // For some reason, if we don't do this in the browser, we get
+          // a runtime error.
+          .without_time()
+          .init();
+    }
 }}

example/start-axum/src/main.rs

@@ -7,7 +7,7 @@ async fn main() {
     use start_axum::app::*;
     use start_axum::fileserv::file_and_error_handler;
 
-    simple_logger::init_with_level(log::Level::Info).expect("couldn't initialize logging");
+    simple_logger::init_with_level(log::Level::Debug).expect("couldn't initialize logging");
 
     // Setting get_configuration(None) means we'll be using cargo-leptos's env values
     // For deployment these variables are:

example/start-axum/src/todo.rs

@@ -3,7 +3,7 @@ use leptos_query::*;
 use leptos_router::ActionForm;
 
 use serde::*;
-#[derive(Serialize, Deserialize, Clone)]
+#[derive(Debug, Serialize, Deserialize, Clone)]
 pub struct Todo {
     id: u32,
     content: String,

src/query_client.rs

@@ -9,6 +9,7 @@ use std::{
     cell::RefCell,
     collections::hash_map::Entry,
     collections::HashMap,
+    fmt::Debug,
     future::Future,
     hash::Hash,
     rc::Rc,
@@ -115,8 +116,8 @@ impl QueryClient {
         isomorphic: bool,
     ) -> QueryResult<V, impl RefetchFn>
     where
-        K: Hash + Eq + Clone + 'static,
-        V: Clone + 'static,
+        K: Debug + Hash + Eq + Clone + 'static,
+        V: Debug + Clone + 'static,
         Fu: Future<Output = V> + 'static,
     {
         let state = self.get_query_signal(cx, key);
@@ -159,8 +160,8 @@ impl QueryClient {
         query: impl Fn(K) -> Fu + 'static,
         isomorphic: bool,
     ) where
-        K: Hash + Eq + Clone + 'static,
-        V: Clone + 'static,
+        K: Debug + Hash + Eq + Clone + 'static,
+        V: Debug + Clone + 'static,
         Fu: Future<Output = V> + 'static,
     {
         let state = self.get_query_signal(cx, key);

src/query_executor.rs

@@ -1,7 +1,9 @@
 use leptos::*;
+use tracing::{field::debug, Instrument, debug_span};
 use std::{
     cell::{Cell, RefCell},
     collections::HashMap,
+    fmt::Debug,
     future::Future,
     hash::Hash,
     rc::Rc,
@@ -29,43 +31,84 @@ pub(crate) fn create_executor<K, V, Fu>(
     fetcher: impl Fn(K) -> Fu + 'static,
 ) -> impl Fn() + Clone
 where
-    K: Clone + Hash + Eq + 'static,
-    V: Clone + 'static,
+    K: Debug + Clone + Hash + Eq + 'static,
+    V: Debug + Clone + 'static,
     Fu: Future<Output = V> + 'static,
 {
     let fetcher = Rc::new(fetcher);
     move || {
         let fetcher = fetcher.clone();
+
         SUPPRESS_QUERY_LOAD.with(|supressed| {
             if !supressed.get() {
-                spawn_local(async move {
-                    let query = query.get_untracked();
-                    let data_state = query.state.get_untracked();
-                    match data_state {
-                        QueryState::Fetching(_) | QueryState::Loading => (),
-                        // First load.
-                        QueryState::Created => {
-                            query.state.set(QueryState::Loading);
-                            let data = fetcher(query.key.clone()).await;
-                            let updated_at = crate::Instant::now();
-                            let data = QueryData { data, updated_at };
-                            query.state.set(QueryState::Loaded(data));
-                        }
-                        // Subsequent loads.
-                        QueryState::Loaded(data) | QueryState::Invalid(data) => {
-                            query.state.set(QueryState::Fetching(data));
-                            let data = fetcher(query.key.clone()).await;
-                            let updated_at = crate::Instant::now();
-                            let data = QueryData { data, updated_at };
-                            query.state.set(QueryState::Loaded(data));
-                        }
-                    }
-                })
+                let query = query.get_untracked();
+                spawn_local(query_executor(query, fetcher))
             }
         })
     }
 }
 
+#[tracing::instrument(
+    level = "info", 
+    skip(query, fetcher),
+    fields(
+        key_type = std::any::type_name::<K>(), 
+        value_type = std::any::type_name::<V>(),
+        key = ?query.key,
+    )
+)]
+async fn query_executor<K, V, F, Fu>(
+    query: Query<K, V>,
+    fetcher: Rc<F>,
+) where
+    K: Debug + Clone + Hash + Eq + 'static,
+    V: Debug + Clone + 'static,
+    F: Fn(K) -> Fu + 'static,
+    Fu: Future<Output = V> + 'static,
+{
+    let state = query.state.get_untracked();
+
+    let span = tracing::Span::current();
+
+    match state {
+        QueryState::Loading  => {
+            tracing::info!("Query load in progress");
+        }
+        QueryState::Fetching(_) => {
+            tracing::info!("Query fetch in progress");
+        }
+        // First load.
+        QueryState::Created => {
+            tracing::info!("Query loading");
+
+            query.state.set(QueryState::Loading);
+            let data = fetcher(query.key.clone()).instrument(span).await;
+
+            let updated_at = crate::Instant::now();
+            let data = QueryData { data, updated_at };
+            let state = QueryState::Loaded(data);
+
+            tracing::info!("Query load complete");
+            query.state.set(state);
+        }
+        // Subsequent loads.
+        QueryState::Loaded(data) | QueryState::Invalid(data) => {
+            let state = QueryState::Fetching(data);
+            tracing::info!("Query fetching");
+
+            query.state.set(state);
+            let data = fetcher(query.key.clone()).instrument(span).await;
+
+            let updated_at = crate::Instant::now();
+            let data = QueryData { data, updated_at };
+            let state = QueryState::Loaded(data);
+
+            tracing::info!("Query fetch complete");
+            query.state.set(state);
+        }
+    }
+}
+
 // Start synchronization effects.
 pub(crate) fn synchronize_state<K, V>(
     cx: Scope,
@@ -253,8 +296,8 @@ where
                                 let dispose = {
                                     let query = query.clone();
                                     move || {
-                                        let removed =
-                                            use_query_client(root_scope).evict_and_notify::<K, V>(&query.key);
+                                        let removed = use_query_client(root_scope)
+                                            .evict_and_notify::<K, V>(&query.key);
                                         if let Some(query) = removed {
                                             if query.observers.get() == 0 {
                                                 query.dispose();

src/use_query.rs

@@ -5,9 +5,7 @@ use crate::{
     ResourceOption,
 };
 use leptos::*;
-use std::future::Future;
-use std::hash::Hash;
-use std::time::Duration;
+use std::{fmt::Debug, future::Future, hash::Hash, time::Duration};
 
 /// Creates a query. Useful for data fetching, caching, and synchronization with server state.
 ///
@@ -63,8 +61,8 @@ pub fn use_query<K, V, Fu>(
     options: QueryOptions<V>,
 ) -> QueryResult<V, impl RefetchFn>
 where
-    K: Hash + Eq + Clone + 'static,
-    V: Clone + Serializable + 'static,
+    K: Debug + Hash + Eq + Clone + 'static,
+    V: Debug + Clone + Serializable + 'static,
     Fu: Future<Output = V> + 'static,
 {
     // Find relevant state.