[ffx] Add tracing to ffx

Change-Id: I81a8e60e8e782c5ad21879801ee77bc25c405443
Reviewed-on: https://fuchsia-review.googlesource.com/c/fuchsia/+/691143
Reviewed-by: Casey Dahlin <sadmac@google.com>
Fuchsia-Auto-Submit: Andrew Davies <awdavies@google.com>
Commit-Queue: Auto-Submit <auto-submit@fuchsia-infra.iam.gserviceaccount.com>
Reviewed-by: David Koloski <dkoloski@google.com>
Reviewed-by: Andrew Davies <awdavies@google.com>
diff --git a/src/connectivity/overnet/lib/core/src/router/mod.rs b/src/connectivity/overnet/lib/core/src/router/mod.rs
index 744b5bb..0ed190f 100644
--- a/src/connectivity/overnet/lib/core/src/router/mod.rs
+++ b/src/connectivity/overnet/lib/core/src/router/mod.rs
@@ -90,6 +90,7 @@
     }
 }
 
+#[derive(Debug)]
 enum PendingTransfer {
     Complete(FoundTransfer),
     Waiting(Waker),
@@ -109,6 +110,7 @@
     Remote(FramedStreamWriter, FramedStreamReader, Handle),
 }
 
+#[derive(Debug)]
 struct PeerMaps {
     clients: BTreeMap<NodeId, Arc<Peer>>,
     servers: BTreeMap<NodeId, Vec<Arc<Peer>>>,
@@ -207,6 +209,7 @@
 }
 
 /// Wrapper to get the right list_peers behavior.
+#[derive(Debug)]
 pub struct ListPeersContext(Mutex<Option<Observer<Vec<ListablePeer>>>>);
 
 static LIST_PEERS_CALL: AtomicU64 = AtomicU64::new(0);
diff --git a/src/connectivity/overnet/lib/hoist/BUILD.gn b/src/connectivity/overnet/lib/hoist/BUILD.gn
index c7bb1c8..9613114 100644
--- a/src/connectivity/overnet/lib/hoist/BUILD.gn
+++ b/src/connectivity/overnet/lib/hoist/BUILD.gn
@@ -17,6 +17,7 @@
     "//third_party/rust_crates:futures",
     "//third_party/rust_crates:lazy_static",
     "//third_party/rust_crates:thiserror",
+    "//third_party/rust_crates:tracing",
   ]
   test_deps = [ "//third_party/rust_crates:parking_lot" ]
   non_rust_deps = [ "//third_party/boringssl" ]
diff --git a/src/connectivity/overnet/lib/hoist/src/not_fuchsia.rs b/src/connectivity/overnet/lib/hoist/src/not_fuchsia.rs
index 57bc35a..4bea88e 100644
--- a/src/connectivity/overnet/lib/hoist/src/not_fuchsia.rs
+++ b/src/connectivity/overnet/lib/hoist/src/not_fuchsia.rs
@@ -73,6 +73,7 @@
     }
 }
 
+#[derive(Debug)]
 pub struct Hoist {
     host_overnet: HostOvernet,
     node: Arc<Router>,
@@ -216,6 +217,7 @@
     }
 }
 
+#[tracing::instrument(level = "info")]
 async fn handle_consumer_request(
     node: Arc<Router>,
     list_peers_context: Arc<ListPeersContext>,
@@ -236,6 +238,7 @@
     Ok(())
 }
 
+#[tracing::instrument(level = "info")]
 async fn handle_publisher_request(
     node: Arc<Router>,
     r: ServicePublisherRequest,
@@ -244,6 +247,7 @@
     node.register_service(service_name, provider).await
 }
 
+#[tracing::instrument(level = "info")]
 async fn handle_controller_request(
     node: Arc<Router>,
     r: MeshControllerRequest,
@@ -283,6 +287,7 @@
     }
 }
 
+#[tracing::instrument(level = "info")]
 async fn handle_request(node: Arc<Router>, req: HostOvernetRequest) -> Result<(), Error> {
     match req {
         HostOvernetRequest::ConnectServiceConsumer { svc, control_handle: _ } => {
@@ -319,6 +324,7 @@
     Ok(())
 }
 
+#[tracing::instrument(level = "info", skip(rx))]
 async fn run_overnet(node: Arc<Router>, rx: HostOvernetRequestStream) -> Result<(), Error> {
     // Run application loop
     rx.map_err(Into::into)
diff --git a/src/developer/ffx/build/ffx.gni b/src/developer/ffx/build/ffx.gni
index a176b06..4c4c708 100644
--- a/src/developer/ffx/build/ffx.gni
+++ b/src/developer/ffx/build/ffx.gni
@@ -91,6 +91,8 @@
              "//third_party/rust_crates:futures",
              "//third_party/rust_crates:log",
              "//third_party/rust_crates:simplelog",
+             "//third_party/rust_crates:tracing",
+             "//third_party/rust_crates:tracing-log",
            ]
     non_rust_deps = [
       "//src/lib/chunked-compression",
diff --git a/src/developer/ffx/config/BUILD.gn b/src/developer/ffx/config/BUILD.gn
index 57a2f81..4b56fe2 100644
--- a/src/developer/ffx/config/BUILD.gn
+++ b/src/developer/ffx/config/BUILD.gn
@@ -18,16 +18,21 @@
       "//third_party/rust_crates:anyhow",
       "//third_party/rust_crates:argh",
       "//third_party/rust_crates:async-lock",
+      "//third_party/rust_crates:chrono",
       "//third_party/rust_crates:futures",
       "//third_party/rust_crates:home",
       "//third_party/rust_crates:lazy_static",
       "//third_party/rust_crates:log",
+      "//third_party/rust_crates:rand",
       "//third_party/rust_crates:regex",
       "//third_party/rust_crates:serde",
       "//third_party/rust_crates:serde_json",
       "//third_party/rust_crates:simplelog",
       "//third_party/rust_crates:tempfile",
       "//third_party/rust_crates:thiserror",
+      "//third_party/rust_crates:tracing",
+      "//third_party/rust_crates:tracing-log",
+      "//third_party/rust_crates:tracing-subscriber",
     ]
 
     test_deps = [ "//src/lib/fuchsia-async" ]
diff --git a/src/developer/ffx/config/src/logging.rs b/src/developer/ffx/config/src/logging.rs
index 0c112b4..fc285d1 100644
--- a/src/developer/ffx/config/src/logging.rs
+++ b/src/developer/ffx/config/src/logging.rs
@@ -4,12 +4,17 @@
 
 use {
     anyhow::{Context as _, Result},
-    simplelog::{CombinedLogger, Config, ConfigBuilder, LevelFilter, SimpleLogger, WriteLogger},
+    rand::Rng,
     std::fs::{create_dir_all, remove_file, rename, File, OpenOptions},
     std::io::{ErrorKind, Read, Seek, SeekFrom, Write},
     std::path::PathBuf,
     std::str::FromStr,
     std::sync::atomic::{AtomicBool, Ordering},
+    std::sync::Mutex,
+    tracing::Metadata,
+    tracing_subscriber::filter::LevelFilter,
+    tracing_subscriber::prelude::*,
+    tracing_subscriber::Layer,
 };
 
 const LOG_DIR: &str = "log.dir";
@@ -22,70 +27,16 @@
 
 static LOG_ENABLED_FLAG: AtomicBool = AtomicBool::new(true);
 
-fn config() -> Config {
-    // Sets the target level to "Error" so that all logs show their module
-    // target in the logs.
-    ConfigBuilder::new()
-        .set_target_level(LevelFilter::Error)
-        .set_time_to_local(true)
-        .set_time_format_str(TIME_FORMAT)
-        .add_filter_ignore_str("hyper")
-        .add_filter_ignore_str("rustls")
-        .build()
-}
-
-struct DisableableSimpleLogger {
-    logger: Box<SimpleLogger>,
+lazy_static::lazy_static! {
+    static ref LOGGING_ID: u64 = generate_id();
 }
 
 pub fn disable_stdio_logging() {
     LOG_ENABLED_FLAG.store(false, Ordering::Relaxed);
 }
 
-impl DisableableSimpleLogger {
-    pub fn new(logger: Box<SimpleLogger>) -> Box<Self> {
-        Box::new(Self { logger })
-    }
-
-    pub fn is_enabled(&self) -> bool {
-        LOG_ENABLED_FLAG.load(Ordering::Relaxed)
-    }
-}
-
-impl log::Log for DisableableSimpleLogger {
-    fn enabled(&self, metadata: &log::Metadata<'_>) -> bool {
-        self.is_enabled() && self.logger.enabled(metadata)
-    }
-
-    fn log(&self, record: &log::Record<'_>) {
-        if self.is_enabled() {
-            self.logger.log(record);
-        }
-    }
-
-    fn flush(&self) {
-        if self.is_enabled() {
-            self.logger.flush();
-        }
-    }
-}
-
-impl simplelog::SharedLogger for DisableableSimpleLogger {
-    fn level(&self) -> log::LevelFilter {
-        if self.is_enabled() {
-            self.logger.level()
-        } else {
-            log::LevelFilter::Off
-        }
-    }
-
-    fn config(&self) -> Option<&Config> {
-        self.logger.config()
-    }
-
-    fn as_log(self: Box<Self>) -> Box<dyn log::Log> {
-        Box::new(*self)
-    }
+fn generate_id() -> u64 {
+    rand::thread_rng().gen::<u64>()
 }
 
 pub async fn log_file(name: &str, rotate: bool) -> Result<std::fs::File> {
@@ -193,9 +144,9 @@
         .ok()
         .map(|str| {
             // Ideally we could log here, but there may be no log sink, so fall back to a default
-            LevelFilter::from_str(&str).unwrap_or(LevelFilter::Debug)
+            LevelFilter::from_str(&str).unwrap_or(LevelFilter::DEBUG)
         })
-        .unwrap_or(LevelFilter::Debug)
+        .unwrap_or(LevelFilter::DEBUG)
 }
 
 pub async fn init(log_to_stdio: bool, log_to_file: bool) -> Result<()> {
@@ -207,64 +158,187 @@
 
     let level = filter_level().await;
 
-    CombinedLogger::init(get_loggers(log_to_stdio, file, level)).context("initializing logger")
+    configure_subscribers(log_to_stdio, file, level);
+
+    Ok(())
 }
 
-fn get_loggers(
-    stdio: bool,
-    file: Option<File>,
-    level: LevelFilter,
-) -> Vec<Box<dyn simplelog::SharedLogger>> {
-    let mut loggers: Vec<Box<dyn simplelog::SharedLogger>> = vec![];
+struct DisableableFilter;
 
-    // The daemon logs to stdio, and is redirected to file by spawn_daemon, which enables
-    // panics and backtraces to also be included.
-    if stdio {
-        loggers.push(DisableableSimpleLogger::new(SimpleLogger::new(level, config())));
+impl<S> tracing_subscriber::layer::Filter<S> for DisableableFilter {
+    fn enabled(
+        &self,
+        _meta: &Metadata<'_>,
+        _cx: &tracing_subscriber::layer::Context<'_, S>,
+    ) -> bool {
+        LOG_ENABLED_FLAG.load(Ordering::Relaxed)
     }
-
-    if let Some(file) = file {
-        let writer = std::io::LineWriter::new(file);
-        loggers.push(WriteLogger::new(level, config(), writer));
-    }
-
-    loggers
 }
 
-#[cfg(test)]
-mod test {
-    use super::*;
-    use log::Log;
+fn configure_subscribers(stdio: bool, file: Option<File>, level: LevelFilter) {
+    let stdio_layer = if stdio {
+        let event_format = LogFormat::new(*LOGGING_ID);
+        let format = tracing_subscriber::fmt::layer()
+            .event_format(event_format)
+            .with_filter(DisableableFilter)
+            .with_filter(level);
+        Some(format)
+    } else {
+        None
+    };
 
-    #[test]
-    fn test_get_loggers() {
-        let loggers = get_loggers(false, None, LevelFilter::Debug);
-        assert!(loggers.len() == 0);
+    let file_layer = file.map(|f| {
+        let event_format = LogFormat::new(*LOGGING_ID);
+        let writer = Mutex::new(std::io::LineWriter::new(f));
+        let format = tracing_subscriber::fmt::layer()
+            .event_format(event_format)
+            .with_writer(writer)
+            .with_filter(level);
+        format
+    });
 
-        // SimpleLogger (error logs to stderr, all other levels to stdout)
-        let loggers = get_loggers(true, None, LevelFilter::Debug);
-        assert!(loggers.len() == 1);
+    tracing_subscriber::registry().with(stdio_layer).with(file_layer).init();
+}
 
-        // WriteLogger (error logs to stderr, all other logs to file)
-        let loggers = get_loggers(false, Some(tempfile::tempfile().unwrap()), LevelFilter::Debug);
-        assert!(loggers.len() == 1);
+#[derive(Default, Debug, Copy, Clone, Eq, PartialEq)]
+struct LogTimer;
 
-        // SimpleLogger & WriteLogger (error logs to stderr, all other levels to stdout and file)
-        let loggers = get_loggers(true, Some(tempfile::tempfile().unwrap()), LevelFilter::Debug);
-        assert!(loggers.len() == 2);
+impl tracing_subscriber::fmt::time::FormatTime for LogTimer {
+    fn format_time(&self, w: &mut tracing_subscriber::fmt::format::Writer<'_>) -> std::fmt::Result {
+        let time = chrono::Local::now().format(TIME_FORMAT);
+        write!(w, "{}", time)
     }
+}
 
-    #[test]
-    fn test_disable_logger() {
-        let logger = DisableableSimpleLogger::new(SimpleLogger::new(LevelFilter::Debug, config()));
-        let metadata =
-            log::MetadataBuilder::new().level(log::Level::Error).target("test-target").build();
+#[derive(Default, Debug, Copy, Clone, Eq, PartialEq)]
+struct LogFormat {
+    id: u64,
+    display_thread_id: bool,
+    display_filename: bool,
+    display_line_number: bool,
+    display_target: bool,
+    timer: LogTimer,
+}
 
-        assert!(logger.enabled(&metadata));
-        disable_stdio_logging();
-        assert!(!logger.enabled(&metadata));
+impl LogFormat {
+    fn new(id: u64) -> Self {
+        LogFormat { id, ..Default::default() }
+    }
+}
 
-        // This might not be necessary but restores the shared state to what it was before the test
-        LOG_ENABLED_FLAG.store(true, Ordering::Relaxed);
+impl<S, N> tracing_subscriber::fmt::FormatEvent<S, N> for LogFormat
+where
+    S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
+    N: for<'a> tracing_subscriber::fmt::FormatFields<'a> + 'static,
+{
+    fn format_event(
+        &self,
+        ctx: &tracing_subscriber::fmt::FmtContext<'_, S, N>,
+        mut writer: tracing_subscriber::fmt::format::Writer<'_>,
+        event: &tracing::Event<'_>,
+    ) -> std::fmt::Result {
+        use tracing_log::NormalizeEvent;
+        use tracing_subscriber::fmt::time::FormatTime;
+        use tracing_subscriber::fmt::FormatFields;
+
+        let normalized_meta = event.normalized_metadata();
+        let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+
+        if self.timer.format_time(&mut writer).is_err() {
+            writer.write_str("<unknown time>")?;
+        }
+        writer.write_char(' ')?;
+
+        write!(writer, "[{:0>20?}] ", self.id)?;
+
+        match *meta.level() {
+            tracing::Level::TRACE => write!(writer, "TRACE ")?,
+            tracing::Level::DEBUG => write!(writer, "DEBUG ")?,
+            tracing::Level::INFO => write!(writer, "INFO ")?,
+            tracing::Level::WARN => write!(writer, "WARN ")?,
+            tracing::Level::ERROR => write!(writer, "ERROR ")?,
+        }
+
+        if self.display_thread_id {
+            write!(writer, "{:0>2?} ", std::thread::current().id())?;
+        }
+
+        let full_ctx = FullCtx::new(ctx, event.parent());
+        write!(writer, "{}", full_ctx)?;
+
+        if self.display_target {
+            write!(writer, "{}: ", meta.target())?;
+        }
+
+        let line_number = if self.display_line_number { meta.line() } else { None };
+
+        if self.display_filename {
+            if let Some(filename) = meta.file() {
+                write!(writer, "{}:{}", filename, if line_number.is_some() { "" } else { " " })?;
+            }
+        }
+
+        if let Some(line_number) = line_number {
+            write!(writer, "{}: ", line_number)?;
+        }
+
+        ctx.format_fields(writer.by_ref(), event)?;
+        writeln!(writer)
+    }
+}
+
+struct FullCtx<'a, S, N>
+where
+    S: tracing::Subscriber + for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
+    N: for<'writer> tracing_subscriber::fmt::FormatFields<'writer> + 'static,
+{
+    ctx: &'a tracing_subscriber::fmt::FmtContext<'a, S, N>,
+    span: Option<&'a tracing::span::Id>,
+}
+
+impl<'a, S, N: 'a> FullCtx<'a, S, N>
+where
+    S: tracing::Subscriber + for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
+    N: for<'writer> tracing_subscriber::fmt::FormatFields<'writer> + 'static,
+{
+    fn new(
+        ctx: &'a tracing_subscriber::fmt::FmtContext<'a, S, N>,
+        span: Option<&'a tracing::span::Id>,
+    ) -> Self {
+        Self { ctx, span }
+    }
+}
+
+impl<'a, S, N> std::fmt::Display for FullCtx<'a, S, N>
+where
+    S: tracing::Subscriber + for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
+    N: for<'writer> tracing_subscriber::fmt::FormatFields<'writer> + 'static,
+{
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        use std::fmt::Write;
+        let mut seen = false;
+
+        let span = self.span.and_then(|id| self.ctx.span(id)).or_else(|| self.ctx.lookup_current());
+
+        let scope = span.into_iter().flat_map(|span| span.scope().from_root());
+
+        for span in scope {
+            write!(f, "{}", span.metadata().name())?;
+            seen = true;
+
+            let ext = span.extensions();
+            let fields = &ext
+                .get::<tracing_subscriber::fmt::FormattedFields<N>>()
+                .expect("Unable to find FormattedFields in extensions; this is a bug");
+            if !fields.is_empty() {
+                write!(f, "{{{}}}", fields)?;
+            }
+            f.write_char(':')?;
+        }
+
+        if seen {
+            f.write_char(' ')?;
+        }
+        Ok(())
     }
 }
diff --git a/src/developer/ffx/daemon/BUILD.gn b/src/developer/ffx/daemon/BUILD.gn
index f4a676c..9b98e57 100644
--- a/src/developer/ffx/daemon/BUILD.gn
+++ b/src/developer/ffx/daemon/BUILD.gn
@@ -56,6 +56,7 @@
       "//third_party/rust_crates:serde_json",
       "//third_party/rust_crates:tempfile",
       "//third_party/rust_crates:thiserror",
+      "//third_party/rust_crates:tracing",
     ]
 
     test_deps = [ "//third_party/rust_crates:assert_matches" ]
diff --git a/src/developer/ffx/daemon/core/BUILD.gn b/src/developer/ffx/daemon/core/BUILD.gn
index 8cff72b..32237a7 100644
--- a/src/developer/ffx/daemon/core/BUILD.gn
+++ b/src/developer/ffx/daemon/core/BUILD.gn
@@ -22,6 +22,7 @@
       "//third_party/rust_crates:futures",
       "//third_party/rust_crates:log",
       "//third_party/rust_crates:pin-project",
+      "//third_party/rust_crates:tracing",
     ]
 
     sources = [
diff --git a/src/developer/ffx/daemon/core/src/events.rs b/src/developer/ffx/daemon/core/src/events.rs
index d3e41e0b..37f5746 100644
--- a/src/developer/ffx/daemon/core/src/events.rs
+++ b/src/developer/ffx/daemon/core/src/events.rs
@@ -77,6 +77,7 @@
 }
 
 impl<T: EventTrait + 'static> Dispatcher<T> {
+    #[tracing::instrument(level = "info", skip(inner))]
     async fn handler_helper(
         event: T,
         inner: Rc<DispatcherInner<T>>,
diff --git a/src/developer/ffx/daemon/protocols/target_collection/BUILD.gn b/src/developer/ffx/daemon/protocols/target_collection/BUILD.gn
index ecf8ffa..fb477e32 100644
--- a/src/developer/ffx/daemon/protocols/target_collection/BUILD.gn
+++ b/src/developer/ffx/daemon/protocols/target_collection/BUILD.gn
@@ -32,6 +32,7 @@
     "//third_party/rust_crates:futures",
     "//third_party/rust_crates:futures-lite",
     "//third_party/rust_crates:log",
+    "//third_party/rust_crates:tracing",
   ]
 
   test_deps = [
diff --git a/src/developer/ffx/daemon/protocols/target_collection/src/lib.rs b/src/developer/ffx/daemon/protocols/target_collection/src/lib.rs
index c21f7e1..21e134f 100644
--- a/src/developer/ffx/daemon/protocols/target_collection/src/lib.rs
+++ b/src/developer/ffx/daemon/protocols/target_collection/src/lib.rs
@@ -141,6 +141,7 @@
     type Protocol = ffx::TargetCollectionMarker;
     type StreamHandler = FidlStreamHandler<Self>;
 
+    #[tracing::instrument(level = "info", skip(self, cx))]
     async fn handle(&self, cx: &Context, req: ffx::TargetCollectionRequest) -> Result<()> {
         let target_collection = cx.get_target_collection().await?;
         match req {
diff --git a/src/developer/ffx/daemon/protocols/target_collection/src/target_handle.rs b/src/developer/ffx/daemon/protocols/target_collection/src/target_handle.rs
index df7ef53..6ee02b4 100644
--- a/src/developer/ffx/daemon/protocols/target_collection/src/target_handle.rs
+++ b/src/developer/ffx/daemon/protocols/target_collection/src/target_handle.rs
@@ -55,6 +55,7 @@
 }
 
 impl TargetHandleInner {
+    #[tracing::instrument(level = "info", skip(self, _cx))]
     async fn handle(&self, _cx: &Context, req: ffx::TargetRequest) -> Result<()> {
         match req {
             ffx::TargetRequest::GetSshLogs { responder } => {
diff --git a/src/developer/ffx/daemon/src/daemon.rs b/src/developer/ffx/daemon/src/daemon.rs
index 804496f..e2b45d1 100644
--- a/src/developer/ffx/daemon/src/daemon.rs
+++ b/src/developer/ffx/daemon/src/daemon.rs
@@ -66,6 +66,7 @@
         Self { target_collection }
     }
 
+    #[tracing::instrument(level = "info", skip(self))]
     async fn handle_overnet_peer(&self, node_id: u64) {
         let rcs = match RcsConnection::new(&mut NodeId { id: node_id }) {
             Ok(rcs) => rcs,
@@ -88,6 +89,7 @@
         target.run_logger();
     }
 
+    #[tracing::instrument(level = "info", skip(self))]
     async fn handle_overnet_peer_lost(&self, node_id: u64) {
         if let Some(target) = self
             .target_collection
@@ -197,6 +199,7 @@
         Ok(target.as_ref().into())
     }
 
+    #[tracing::instrument(level = "info", skip(self))]
     async fn open_remote_control(
         &self,
         target_identifier: Option<String>,
diff --git a/src/developer/ffx/daemon/target/BUILD.gn b/src/developer/ffx/daemon/target/BUILD.gn
index f77f3dc..2f72663 100644
--- a/src/developer/ffx/daemon/target/BUILD.gn
+++ b/src/developer/ffx/daemon/target/BUILD.gn
@@ -62,6 +62,7 @@
     "//third_party/rust_crates:socket2",
     "//third_party/rust_crates:tempfile",
     "//third_party/rust_crates:thiserror",
+    "//third_party/rust_crates:tracing",
   ]
 
   test_deps = [
diff --git a/src/developer/ffx/daemon/target/src/target.rs b/src/developer/ffx/daemon/target/src/target.rs
index a0bc647..cf359ab 100644
--- a/src/developer/ffx/daemon/target/src/target.rs
+++ b/src/developer/ffx/daemon/target/src/target.rs
@@ -553,6 +553,7 @@
     ///
     ///   RCS  ->   MDNS          =>  RCS (does not drop RCS state)
     ///   *    ->   Disconnected  =>  Manual if the device is manual
+    #[tracing::instrument(level = "info", skip(func))]
     pub fn update_connection_state<F>(&self, func: F)
     where
         F: FnOnce(TargetConnectionState) -> TargetConnectionState + Sized,
@@ -773,6 +774,7 @@
         }
     }
 
+    #[tracing::instrument(level = "info")]
     pub fn from_identify(identify: IdentifyHostResponse) -> Result<Rc<Self>, Error> {
         // TODO(raggi): allow targets to truly be created without a nodename.
         let nodename = match identify.nodename {
@@ -816,6 +818,7 @@
         Ok(target)
     }
 
+    #[tracing::instrument(level = "info")]
     pub async fn from_rcs_connection(rcs: RcsConnection) -> Result<Rc<Self>, RcsConnectionError> {
         let identify_result =
             timeout(Duration::from_millis(IDENTIFY_HOST_TIMEOUT_MILLIS), rcs.proxy.identify_host())
@@ -868,6 +871,7 @@
         self.preferred_ssh_address.borrow_mut().take();
     }
 
+    #[tracing::instrument(level = "info")]
     pub fn run_host_pipe(self: &Rc<Self>) {
         if self.host_pipe.borrow().is_some() {
             return;
diff --git a/src/developer/ffx/daemon/target/src/target_collection.rs b/src/developer/ffx/daemon/target/src/target_collection.rs
index 05b0531..3a15dd1 100644
--- a/src/developer/ffx/daemon/target/src/target_collection.rs
+++ b/src/developer/ffx/daemon/target/src/target_collection.rs
@@ -126,6 +126,7 @@
         to_update
     }
 
+    #[tracing::instrument(level = "info", skip(self))]
     pub fn merge_insert(&self, new_target: Rc<Target>) -> Rc<Target> {
         // Drop non-manual loopback address entries, as matching against
         // them could otherwise match every target in the collection.
diff --git a/src/developer/ffx/src/main.rs b/src/developer/ffx/src/main.rs
index 1b785bd..ede0035 100644
--- a/src/developer/ffx/src/main.rs
+++ b/src/developer/ffx/src/main.rs
@@ -50,12 +50,19 @@
     target: Once<Option<String>>,
 }
 
+impl std::fmt::Debug for Injection {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("Injection").finish()
+    }
+}
+
 impl Default for Injection {
     fn default() -> Self {
         Self { target: Once::new(), daemon_once: Once::new(), remote_once: Once::new() }
     }
 }
 
+#[tracing::instrument(level = "info")]
 fn open_target_with_fut<'a>(
     target: Option<String>,
     is_default_target: bool,
@@ -111,6 +118,7 @@
             .map(|s| s.clone())
     }
 
+    #[tracing::instrument(level = "info")]
     async fn init_remote_proxy(&self) -> Result<RemoteControlProxy> {
         let daemon_proxy = self.daemon_factory().await?;
         let target = self.target().await?;
@@ -198,6 +206,7 @@
 impl Injector for Injection {
     // This could get called multiple times by the plugin system via multiple threads - so make sure
     // the spawning only happens one thread at a time.
+    #[tracing::instrument(level = "info")]
     async fn daemon_factory(&self) -> Result<DaemonProxy> {
         self.daemon_once.get_or_try_init(init_daemon_proxy()).await.map(|proxy| proxy.clone())
     }
@@ -220,6 +229,7 @@
         })?
     }
 
+    #[tracing::instrument(level = "info")]
     async fn remote_factory(&self) -> Result<RemoteControlProxy> {
         let target = self.target().await?;
         let timeout_error = self.daemon_timeout_error().await?;
diff --git a/third_party/rust_crates/BUILD.gn b/third_party/rust_crates/BUILD.gn
index 17ab911..a9ffc7c 100644
--- a/third_party/rust_crates/BUILD.gn
+++ b/third_party/rust_crates/BUILD.gn
@@ -10883,6 +10883,7 @@
     "-Cmetadata=3c92bd8481194a1d",
     "-Cextra-filename=-3c92bd8481194a1d",
     "--cfg=feature=\"alloc\"",
+    "--cfg=feature=\"fmt\"",
     "--cfg=feature=\"registry\"",
     "--cfg=feature=\"sharded-slab\"",
     "--cfg=feature=\"std\"",
diff --git a/third_party/rust_crates/Cargo.toml b/third_party/rust_crates/Cargo.toml
index adbecef..ca3d72f 100644
--- a/third_party/rust_crates/Cargo.toml
+++ b/third_party/rust_crates/Cargo.toml
@@ -228,7 +228,7 @@
 [dependencies.tracing-subscriber]
 version = "0.3.1"
 default-features = false
-features = ["registry", "tracing-log"]
+features = ["registry", "tracing-log", "fmt", "std"]
 
 # Target-side only dependencies
 [target.'cfg(target_os = "fuchsia")'.dependencies]