feat: add tracing (port from #8289) (#8607)

* feat(tracing): add IPC tracing

* span for deserialization

* trace spans for IPC command handlers

* fix spans usage

* app tracing [skip ci]

* window tracing

* fix run never resolving all spans

* fix draw not entered

* change level

* feat(core): Manager::emit_filter and optimize serialization (#7512)

Co-authored-by: Lucas Nogueira <lucas@tauri.studio>

* event spans

* lint & fix tests

* change eval to run sync

* fix instrument

* update wry

* change separator

* Update core/tauri/src/plugin.rs

Co-authored-by: Jonas Kruckenberg <118265418+CrabNejonas@users.noreply.github.com>

* Update core/tauri/src/window.rs

Co-authored-by: Jonas Kruckenberg <118265418+CrabNejonas@users.noreply.github.com>

* Update core/tauri/src/window.rs

Co-authored-by: Jonas Kruckenberg <118265418+CrabNejonas@users.noreply.github.com>

* Update core/tauri/src/window.rs

Co-authored-by: Jonas Kruckenberg <118265418+CrabNejonas@users.noreply.github.com>

* Update core/tauri/src/window.rs

Co-authored-by: Jonas Kruckenberg <118265418+CrabNejonas@users.noreply.github.com>

* instrument separators

* remove on_event trace

* skip all arguments on App::build tracing

* ipc spans adjustments

* delete change file

* improve how request and response are added as values (serialize)

* do not run evalScript sync on android :( freezes the app

* wry 0.35.2

* add change file

---------

Co-authored-by: Lucas Nogueira <lucas@tauri.studio>
Co-authored-by: Jonas Kruckenberg <118265418+CrabNejonas@users.noreply.github.com>

Author: 3 people

.changes/tracing.md

@@ -0,0 +1,7 @@
+---
+"tauri": patch:enhance
+"tauri-runtime-wry": patch:enhance
+"tauri-macros": patch:enhance
+---
+
+Added tracing for window startup, plugins, `Window::eval`, events, IPC, updater and custom protocol request handlers behind the `tracing` feature flag.

core/tauri-runtime-wry/Cargo.toml

@@ -13,7 +13,7 @@ edition = { workspace = true }
 rust-version = { workspace = true }
 
 [dependencies]
-wry = { version = "0.35", default-features = false, features = [ "file-drop", "protocol", "os-webview" ] }
+wry = { version = "0.35.2", default-features = false, features = [ "file-drop", "protocol", "os-webview" ] }
 tao = { version = "0.24", default-features = false, features = [ "rwh_05" ] }
 tauri-runtime = { version = "1.0.0-alpha.7", path = "../tauri-runtime" }
 tauri-utils = { version = "2.0.0-alpha.12", path = "../tauri-utils" }
@@ -48,4 +48,4 @@ macos-private-api = [
 ]
 objc-exception = [ "wry/objc-exception" ]
 linux-protocol-body = [ "wry/linux-body", "webkit2gtk/v2_40" ]
-tracing = [ "dep:tracing" ]
+tracing = [ "dep:tracing", "wry/tracing" ]

core/tauri-runtime-wry/src/lib.rs

@@ -1070,9 +1070,9 @@ pub enum WindowMessage {
 
 #[derive(Debug, Clone)]
 pub enum WebviewMessage {
-  #[cfg(not(feature = "tracing"))]
+  #[cfg(not(all(feature = "tracing", not(target_os = "android"))))]
   EvaluateScript(String),
-  #[cfg(feature = "tracing")]
+  #[cfg(all(feature = "tracing", not(target_os = "android")))]
   EvaluateScript(String, Sender<()>, tracing::Span),
   #[allow(dead_code)]
   WebviewEvent(WebviewEvent),
@@ -1583,7 +1583,7 @@ impl<T: UserEvent> Dispatch<T> for WryDispatcher<T> {
     )
   }
 
-  #[cfg(feature = "tracing")]
+  #[cfg(all(feature = "tracing", not(target_os = "android")))]
   fn eval_script<S: Into<String>>(&self, script: S) -> Result<()> {
     // use a channel so the EvaluateScript task uses the current span as parent
     let (tx, rx) = channel();
@@ -1597,7 +1597,7 @@ impl<T: UserEvent> Dispatch<T> for WryDispatcher<T> {
     )
   }
 
-  #[cfg(not(feature = "tracing"))]
+  #[cfg(not(all(feature = "tracing", not(target_os = "android"))))]
   fn eval_script<S: Into<String>>(&self, script: S) -> Result<()> {
     send_user_message(
       &self.context,
@@ -2429,7 +2429,7 @@ fn handle_user_message<T: UserEvent>(
       }
     }
     Message::Webview(id, webview_message) => match webview_message {
-      #[cfg(feature = "tracing")]
+      #[cfg(all(feature = "tracing", not(target_os = "android")))]
       WebviewMessage::EvaluateScript(script, tx, span) => {
         let _span = span.entered();
         if let Some(WindowHandle::Webview { inner: webview, .. }) =
@@ -2441,7 +2441,7 @@ fn handle_user_message<T: UserEvent>(
         }
         tx.send(()).unwrap();
       }
-      #[cfg(not(feature = "tracing"))]
+      #[cfg(not(all(feature = "tracing", not(target_os = "android"))))]
       WebviewMessage::EvaluateScript(script) => {
         if let Some(WindowHandle::Webview { inner: webview, .. }) =
           windows.borrow().get(&id).and_then(|w| w.inner.as_ref())

core/tauri/src/app.rs

@@ -762,6 +762,10 @@ shared_app_impl!(App<R>);
 shared_app_impl!(AppHandle<R>);
 
 impl<R: Runtime> App<R> {
+  #[cfg_attr(
+    feature = "tracing",
+    tracing::instrument(name = "app::core_plugins::register")
+  )]
   fn register_core_plugins(&self) -> crate::Result<()> {
     self.handle.plugin(crate::path::plugin::init())?;
     self.handle.plugin(crate::event::plugin::init())?;
@@ -1663,6 +1667,7 @@ unsafe impl<R: Runtime> HasRawDisplayHandle for App<R> {
   }
 }
 
+#[cfg_attr(feature = "tracing", tracing::instrument(name = "app::setup"))]
 fn setup<R: Runtime>(app: &mut App<R>) -> crate::Result<()> {
   let pending_windows = app.pending_windows.take();
   if let Some(pending_windows) = pending_windows {

core/tauri/src/ipc/mod.rs

@@ -204,6 +204,19 @@ pub enum InvokeResponse {
   Err(InvokeError),
 }
 
+impl Serialize for InvokeResponse {
+  fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
+  where
+    S: serde::Serializer,
+  {
+    match self {
+      Self::Ok(InvokeBody::Json(j)) => j.serialize(serializer),
+      Self::Ok(InvokeBody::Raw(b)) => b.serialize(serializer),
+      Self::Err(e) => e.0.serialize(serializer),
+    }
+  }
+}
+
 impl<T: IpcResponse, E: Into<InvokeError>> From<Result<T, E>> for InvokeResponse {
   #[inline]
   fn from(result: Result<T, E>) -> Self {

core/tauri/src/ipc/protocol.rs

@@ -4,16 +4,15 @@
 
 use std::{borrow::Cow, sync::Arc};
 
-use http::{
-  header::{ACCESS_CONTROL_ALLOW_HEADERS, ACCESS_CONTROL_ALLOW_ORIGIN, CONTENT_TYPE},
-  HeaderValue, Method, StatusCode,
-};
-
 use crate::{
   manager::AppManager,
   window::{InvokeRequest, UriSchemeProtocolHandler},
   Runtime,
 };
+use http::{
+  header::{ACCESS_CONTROL_ALLOW_HEADERS, ACCESS_CONTROL_ALLOW_ORIGIN, CONTENT_TYPE},
+  HeaderValue, Method, StatusCode,
+};
 
 use super::{CallbackFn, InvokeBody, InvokeResponse};
 
@@ -29,6 +28,14 @@ pub fn message_handler<R: Runtime>(
 
 pub fn get<R: Runtime>(manager: Arc<AppManager<R>>, label: String) -> UriSchemeProtocolHandler {
   Box::new(move |request, responder| {
+    #[cfg(feature = "tracing")]
+    let span = tracing::trace_span!(
+      "ipc::request",
+      kind = "custom-protocol",
+      request = tracing::field::Empty
+    )
+    .entered();
+
     let manager = manager.clone();
     let label = label.clone();
 
@@ -44,9 +51,35 @@ pub fn get<R: Runtime>(manager: Arc<AppManager<R>>, label: String) -> UriSchemeP
         if let Some(window) = manager.get_window(&label) {
           match parse_invoke_request(&manager, request) {
             Ok(request) => {
+              #[cfg(feature = "tracing")]
+              span.record(
+                "request",
+                match &request.body {
+                  InvokeBody::Json(j) => serde_json::to_string(j).unwrap(),
+                  InvokeBody::Raw(b) => serde_json::to_string(b).unwrap(),
+                },
+              );
+              #[cfg(feature = "tracing")]
+              let request_span = tracing::trace_span!("ipc::request::handle", cmd = request.cmd);
+
               window.on_message(
                 request,
                 Box::new(move |_window, _cmd, response, _callback, _error| {
+                  #[cfg(feature = "tracing")]
+                  let _respond_span = tracing::trace_span!(
+                    parent: &request_span,
+                    "ipc::request::respond"
+                  )
+                  .entered();
+
+                  #[cfg(feature = "tracing")]
+                  let response_span = tracing::trace_span!(
+                    "ipc::request::response",
+                    response = serde_json::to_string(&response).unwrap(),
+                    mime_type = tracing::field::Empty
+                  )
+                  .entered();
+
                   let (mut response, mime_type) = match response {
                     InvokeResponse::Ok(InvokeBody::Json(v)) => (
                       http::Response::new(serde_json::to_vec(&v).unwrap().into()),
@@ -64,6 +97,9 @@ pub fn get<R: Runtime>(manager: Arc<AppManager<R>>, label: String) -> UriSchemeP
                     }
                   };
 
+                  #[cfg(feature = "tracing")]
+                  response_span.record("mime_type", mime_type.essence_str());
+
                   response.headers_mut().insert(
                     CONTENT_TYPE,
                     HeaderValue::from_str(mime_type.essence_str()).unwrap(),
@@ -129,6 +165,10 @@ pub fn get<R: Runtime>(manager: Arc<AppManager<R>>, label: String) -> UriSchemeP
 #[cfg(any(target_os = "macos", target_os = "ios", not(ipc_custom_protocol)))]
 fn handle_ipc_message<R: Runtime>(message: String, manager: &AppManager<R>, label: &str) {
   if let Some(window) = manager.get_window(label) {
+    #[cfg(feature = "tracing")]
+    let _span =
+      tracing::trace_span!("ipc::request", kind = "post-message", request = message).entered();
+
     use serde::{Deserialize, Deserializer};
 
     pub(crate) struct HeaderMap(http::HeaderMap);
@@ -185,6 +225,9 @@ fn handle_ipc_message<R: Runtime>(message: String, manager: &AppManager<R>, labe
       }
 
       if let crate::Pattern::Isolation { crypto_keys, .. } = &*manager.pattern {
+        #[cfg(feature = "tracing")]
+        let _span = tracing::trace_span!("ipc::request::decrypt_isolation_payload").entered();
+
         invoke_message.replace(
           serde_json::from_str::<IsolationMessage<'_>>(&message)
             .map_err(Into::into)
@@ -201,18 +244,25 @@ fn handle_ipc_message<R: Runtime>(message: String, manager: &AppManager<R>, labe
       }
     }
 
-    match invoke_message
-      .unwrap_or_else(|| serde_json::from_str::<Message>(&message).map_err(Into::into))
-    {
+    match invoke_message.unwrap_or_else(|| {
+      #[cfg(feature = "tracing")]
+      let _span = tracing::trace_span!("ipc::request::deserialize").entered();
+      serde_json::from_str::<Message>(&message).map_err(Into::into)
+    }) {
       Ok(message) => {
+        let request = InvokeRequest {
+          cmd: message.cmd,
+          callback: message.callback,
+          error: message.error,
+          body: message.payload.into(),
+          headers: message.options.map(|o| o.headers.0).unwrap_or_default(),
+        };
+
+        #[cfg(feature = "tracing")]
+        let request_span = tracing::trace_span!("ipc::request::handle", cmd = request.cmd);
+
         window.on_message(
-          InvokeRequest {
-            cmd: message.cmd,
-            callback: message.callback,
-            error: message.error,
-            body: message.payload.into(),
-            headers: message.options.map(|o| o.headers.0).unwrap_or_default(),
-          },
+          request,
           Box::new(move |window, cmd, response, callback, error| {
             use crate::ipc::{
               format_callback::{
@@ -222,6 +272,13 @@ fn handle_ipc_message<R: Runtime>(message: String, manager: &AppManager<R>, labe
             };
             use serde_json::Value as JsonValue;
 
+            #[cfg(feature = "tracing")]
+            let _respond_span = tracing::trace_span!(
+              parent: &request_span,
+              "ipc::request::respond"
+            )
+            .entered();
+
             // the channel data command is the only command that uses a custom protocol on Linux
             if window.manager.window.invoke_responder.is_none()
               && cmd != crate::ipc::channel::FETCH_CHANNEL_DATA_COMMAND
@@ -240,6 +297,19 @@ fn handle_ipc_message<R: Runtime>(message: String, manager: &AppManager<R>, labe
                 let _ = window.eval(&eval_js);
               }
 
+              #[cfg(feature = "tracing")]
+              let _response_span = tracing::trace_span!(
+                "ipc::request::response",
+                response = serde_json::to_string(&response).unwrap(),
+                mime_type = match &response {
+                  InvokeResponse::Ok(InvokeBody::Json(_)) => mime::APPLICATION_JSON,
+                  InvokeResponse::Ok(InvokeBody::Raw(_)) => mime::APPLICATION_OCTET_STREAM,
+                  InvokeResponse::Err(_) => mime::TEXT_PLAIN,
+                }
+                .essence_str()
+              )
+              .entered();
+
               match &response {
                 InvokeResponse::Ok(InvokeBody::Json(v)) => {
                   if !(cfg!(target_os = "macos") || cfg!(target_os = "ios"))
@@ -277,6 +347,9 @@ fn handle_ipc_message<R: Runtime>(message: String, manager: &AppManager<R>, labe
         );
       }
       Err(e) => {
+        #[cfg(feature = "tracing")]
+        tracing::trace!("ipc.request.error {}", e);
+
         let _ = window.eval(&format!(
           r#"console.error({})"#,
           serde_json::Value::String(e.to_string())
@@ -301,6 +374,9 @@ fn parse_invoke_request<R: Runtime>(
   // the body is not set if ipc_custom_protocol is not enabled so we'll just ignore it
   #[cfg(all(feature = "isolation", ipc_custom_protocol))]
   if let crate::Pattern::Isolation { crypto_keys, .. } = &*manager.pattern {
+    #[cfg(feature = "tracing")]
+    let _span = tracing::trace_span!("ipc::request::decrypt_isolation_payload").entered();
+
     body = crate::utils::pattern::isolation::RawIsolationPayload::try_from(&body)
       .and_then(|raw| crypto_keys.decrypt(raw))
       .map_err(|e| e.to_string())?;
@@ -334,6 +410,10 @@ fn parse_invoke_request<R: Runtime>(
     .map(|mime| mime.parse())
     .unwrap_or(Ok(mime::APPLICATION_OCTET_STREAM))
     .map_err(|_| "unknown content type")?;
+
+  #[cfg(feature = "tracing")]
+  let span = tracing::trace_span!("ipc::request::deserialize").entered();
+
   let body = if content_type == mime::APPLICATION_OCTET_STREAM {
     body.into()
   } else if content_type == mime::APPLICATION_JSON {
@@ -349,6 +429,9 @@ fn parse_invoke_request<R: Runtime>(
     return Err(format!("content type {content_type} is not implemented"));
   };
 
+  #[cfg(feature = "tracing")]
+  drop(span);
+
   let payload = InvokeRequest {
     cmd,
     callback,

core/tauri/src/manager/mod.rs

@@ -480,6 +480,9 @@ impl<R: Runtime> AppManager<R> {
   {
     assert_event_name_is_valid(event);
 
+    #[cfg(feature = "tracing")]
+    let _span = tracing::debug_span!("emit::run").entered();
+
     let emit_args = EmitArgs::from(event, source_window_label, payload)?;
 
     self
@@ -506,6 +509,9 @@ impl<R: Runtime> AppManager<R> {
   ) -> crate::Result<()> {
     assert_event_name_is_valid(event);
 
+    #[cfg(feature = "tracing")]
+    let _span = tracing::debug_span!("emit::run").entered();
+
     let emit_args = EmitArgs::from(event, source_window_label, payload)?;
 
     self

core/tauri/src/plugin.rs

@@ -750,6 +750,9 @@ impl<R: Runtime> PluginStore<R> {
 
   pub(crate) fn on_navigation(&mut self, window: &Window<R>, url: &Url) -> bool {
     for plugin in self.store.iter_mut() {
+      #[cfg(feature = "tracing")]
+      let _span =
+        tracing::trace_span!("plugin::hooks::on_navigation", name = plugin.name()).entered();
       if !plugin.on_navigation(window, url) {
         return false;
       }

core/tauri/src/window/mod.rs

@@ -2410,6 +2410,8 @@ impl<R: Runtime> Window<R> {
           load_channels(&payload, &message.window);
 
           let resolver_ = resolver.clone();
+          #[cfg(feature = "span")]
+          let _span = tracing::debug_span!("ipc::request::mobile_plugin").entered();
           if let Err(e) = crate::plugin::mobile::run_command(
             plugin,
             &app_handle,