Throw logging and spans everywhere (#70)

Cargo.toml

@@ -53,7 +53,7 @@ tracing = { version = "0.1.37", features = [
     "release_max_level_debug",
     "valuable",
 ] }
-tracing-subscriber = "0.3.16"
+tracing-subscriber = { version = "0.3.16", features = ["env-filter", "fmt"] }
 tracing-unwrap = "0.10.0"
 valuable = { version = "0.1.0", features = ["derive"] }
 which = "4.4.0"

src/burn/child.rs

@@ -131,7 +131,7 @@ fn for_each_block(
     Ok(())
 }
 
-#[tracing::instrument(fields(msg = msg.as_value()))]
+#[tracing::instrument(level = "debug", fields(msg = msg.as_value()))]
 pub fn send_msg(msg: StatusMessage) {
     let mut stdout = std::io::stdout();
     write_msg(&mut stdout, &msg).expect("Failed to write message");

src/burn/state_tracking.rs

@@ -1,6 +1,6 @@
 use std::time::Instant;
 
-use tracing::{debug, info};
+use tracing::{info, trace};
 
 use crate::byteseries::{ByteSeries, EstimatedTime};
 
@@ -24,26 +24,39 @@ pub enum ChildState {
 }
 
 impl ChildState {
+    #[tracing::instrument]
     pub fn initial(now: Instant, is_input_compressed: bool, input_file_bytes: u64) -> Self {
+        info!("Entering initial state");
         ChildState::Burning(Burning::new(now, is_input_compressed, input_file_bytes))
     }
 
+    #[tracing::instrument(skip_all, fields(msg), level = "debug")]
     pub fn on_status(mut self, now: Instant, msg: Option<StatusMessage>) -> Self {
         match msg {
             Some(StatusMessage::TotalBytes { src, dest }) => {
+                trace!("Received total bytes notification");
                 self.on_total_bytes(now, src, dest);
                 self
             }
             Some(StatusMessage::FinishedWriting { verifying }) => {
-                debug!(verifying, "Got FinishedWriting");
+                info!("Received finished writing notification");
                 match self {
                     ChildState::Burning(st) => st.into_finished(now, verifying),
                     c => c,
                 }
             }
-            Some(StatusMessage::Error(reason)) => self.into_finished(now, Some(reason)),
-            Some(StatusMessage::Success) => self.into_finished(now, None),
-            None => self.into_finished(now, Some(ErrorType::UnexpectedTermination)),
+            Some(StatusMessage::Error(reason)) => {
+                info!("Received error notification");
+                self.into_finished(now, Some(reason))
+            }
+            Some(StatusMessage::Success) => {
+                info!("Received success notification");
+                self.into_finished(now, None)
+            }
+            None => {
+                info!("Messages terminated unexpectedly");
+                self.into_finished(now, Some(ErrorType::UnexpectedTermination))
+            }
             other => panic!(
                 "Recieved nexpected child status {:#?}\nCurrent state: {:#?}",
                 other, self

src/logging.rs

@@ -7,6 +7,7 @@ use std::{path::PathBuf, sync::Mutex};
 use crossterm::terminal::disable_raw_mode;
 use static_cell::StaticCell;
 use tracing::{error, Level};
+use tracing_subscriber::EnvFilter;
 
 #[derive(Debug, Clone)]
 pub struct LogPaths {
@@ -37,20 +38,25 @@ pub fn init_logging_parent() {
 
     let write_path = get_log_paths().main.clone();
 
-    let writer = File::create(write_path).unwrap();
-
-    tracing_subscriber::fmt()
-        .with_writer(Mutex::new(writer))
-        .with_max_level(FILE_LOG_LEVEL)
-        .init();
+    init_tracing_subscriber(write_path);
 }
 
 pub fn init_logging_child(write_path: impl AsRef<Path>) {
+    init_tracing_subscriber(write_path);
+}
+
+fn init_tracing_subscriber(write_path: impl AsRef<Path>) {
     let writer = File::create(write_path).unwrap();
 
     tracing_subscriber::fmt()
+        .compact()
+        .with_ansi(false)
         .with_writer(Mutex::new(writer))
-        .with_max_level(FILE_LOG_LEVEL)
+        .with_env_filter(
+            EnvFilter::builder()
+                .with_default_directive(FILE_LOG_LEVEL.into())
+                .from_env_lossy(),
+        )
         .init();
 }
 

src/ui/ask_hash.rs

@@ -16,6 +16,7 @@ use crate::{
 
 use super::cli::{BurnArgs, HashArg, HashOf};
 
+#[tracing::instrument(skip_all, fields(cf))]
 pub fn ask_hash(args: &BurnArgs, cf: CompressionFormat) -> anyhow::Result<Option<FileHashInfo>> {
     let hash_params = match &args.hash {
         HashArg::Skip => None,
@@ -54,6 +55,7 @@ pub fn ask_hash(args: &BurnArgs, cf: CompressionFormat) -> anyhow::Result<Option
     Ok(Some(hash_result))
 }
 
+#[tracing::instrument]
 fn ask_hash_loop(cf: CompressionFormat) -> anyhow::Result<Option<BeginHashParams>> {
     loop {
         match ask_hash_once(cf) {
@@ -72,6 +74,7 @@ fn ask_hash_loop(cf: CompressionFormat) -> anyhow::Result<Option<BeginHashParams
     }
 }
 
+#[tracing::instrument]
 fn ask_hash_once(cf: CompressionFormat) -> anyhow::Result<BeginHashParams> {
     let input_hash = Text::new("What is the file's hash?")
         .with_help_message(
@@ -118,6 +121,7 @@ fn ask_hash_once(cf: CompressionFormat) -> anyhow::Result<BeginHashParams> {
     })
 }
 
+#[tracing::instrument]
 fn ask_hasher_compression(
     cf: CompressionFormat,
     hash_of: Option<HashOf>,
@@ -140,6 +144,7 @@ fn ask_hasher_compression(
     })
 }
 
+#[tracing::instrument(skip_all, fields(path))]
 fn do_hashing(path: &Path, params: &BeginHashParams) -> anyhow::Result<FileHashInfo> {
     let mut file = File::open(path)?;
 
@@ -170,6 +175,7 @@ fn do_hashing(path: &Path, params: &BeginHashParams) -> anyhow::Result<FileHashI
     }
 }
 
+#[derive(Debug)]
 struct BeginHashParams {
     expected_hash: Vec<u8>,
     alg: HashAlg,

src/ui/ask_outfile.rs

@@ -11,6 +11,7 @@ use crate::{
 
 use super::burn::start::BeginParams;
 
+#[tracing::instrument(skip_all)]
 pub fn ask_compression(args: &BurnArgs) -> anyhow::Result<CompressionFormat> {
     let cf = match args.compression {
         CompressionArg::Auto | CompressionArg::Ask => {
@@ -53,6 +54,7 @@ pub fn ask_compression(args: &BurnArgs) -> anyhow::Result<CompressionFormat> {
     return Ok(format);
 }
 
+#[tracing::instrument(skip_all)]
 pub fn ask_outfile(args: &BurnArgs) -> anyhow::Result<BurnTarget> {
     let mut show_all_disks = args.show_all_disks;
 
@@ -83,6 +85,7 @@ pub fn ask_outfile(args: &BurnArgs) -> anyhow::Result<BurnTarget> {
     }
 }
 
+#[tracing::instrument(skip_all)]
 pub fn confirm_write(args: &BurnArgs, begin_params: &BeginParams) -> Result<bool, InquireError> {
     if args.force {
         debug!("Skipping confirm because of --force");
@@ -127,6 +130,7 @@ impl fmt::Display for ListOption {
     }
 }
 
+#[tracing::instrument]
 fn enumerate_options(show_all_disks: bool) -> anyhow::Result<Vec<ListOption>> {
     let mut burn_targets: Vec<BurnTarget> = enumerate_devices()
         .filter(|d| show_all_disks || d.removable == Removable::Yes)

src/ui/burn/fancy/display.rs

@@ -35,6 +35,7 @@ impl<'a, B> FancyUI<'a, B>
 where
     B: Backend,
 {
+    #[tracing::instrument(skip_all)]
     pub fn new(params: &BeginParams, handle: burn::Handle, terminal: &'a mut Terminal<B>) -> Self {
         let input_file_bytes = handle.initial_info().input_file_bytes;
         Self {
@@ -45,6 +46,7 @@ where
         }
     }
 
+    #[tracing::instrument(skip_all, level = "debug")]
     pub async fn show(mut self) -> anyhow::Result<()> {
         loop {
             match self.get_and_handle_events().await {
@@ -57,12 +59,13 @@ where
         Ok(())
     }
 
+    #[tracing::instrument(skip_all, level = "trace")]
     async fn get_and_handle_events(mut self) -> anyhow::Result<FancyUI<'a, B>> {
         let msg = {
             if let Some(handle) = &mut self.handle {
-                child_active(&mut self.events, handle).await
+                get_event_child_active(&mut self.events, handle).await
             } else {
-                child_dead(&mut self.events).await
+                get_event_child_dead(&mut self.events).await
             }?
         };
         self.state = self.state.on_event(msg)?;
@@ -77,20 +80,24 @@ where
     }
 }
 
-async fn child_dead(events: &mut EventStream) -> anyhow::Result<UIEvent> {
-    Ok(UIEvent::RecvTermEvent(events.next().await.unwrap()?))
+async fn get_event_child_dead(ui_events: &mut EventStream) -> anyhow::Result<UIEvent> {
+    Ok(UIEvent::RecvTermEvent(ui_events.next().await.unwrap()?))
 }
 
-async fn child_active(events: &mut EventStream, handle: &mut Handle) -> anyhow::Result<UIEvent> {
+#[tracing::instrument(skip_all, level = "trace")]
+async fn get_event_child_active(
+    ui_events: &mut EventStream,
+    child_events: &mut Handle,
+) -> anyhow::Result<UIEvent> {
     let sleep = tokio::time::sleep(time::Duration::from_millis(250));
     select! {
         _ = sleep => {
             return Ok(UIEvent::SleepTimeout);
         }
-        msg = handle.next_message() => {
+        msg = child_events.next_message() => {
             return Ok(UIEvent::RecvChildStatus(Instant::now(), msg?));
         }
-        event = events.next() => {
+        event = ui_events.next() => {
             return Ok(UIEvent::RecvTermEvent(event.unwrap()?));
         }
     }

src/ui/burn/fancy/state.rs

@@ -1,7 +1,7 @@
 use std::time::Instant;
 
 use crossterm::event::{Event, KeyCode, KeyEvent, KeyEventKind, KeyModifiers};
-use tracing::{info, trace};
+use tracing::info;
 
 use crate::{
     burn::{ipc::StatusMessage, state_tracking::ChildState},
@@ -34,9 +34,9 @@ impl State {
             child: ChildState::initial(now, !params.compression.is_identity(), input_file_bytes),
         }
     }
-    pub fn on_event(self, ev: UIEvent) -> anyhow::Result<Self> {
-        trace!("Handling {ev:?}");
 
+    #[tracing::instrument(skip_all, level = "debug", fields(ev))]
+    pub fn on_event(self, ev: UIEvent) -> anyhow::Result<Self> {
         Ok(match ev {
             UIEvent::SleepTimeout => self,
             UIEvent::RecvChildStatus(t, m) => Self {
@@ -47,6 +47,7 @@ impl State {
         })
     }
 
+    #[tracing::instrument(skip_all, level = "debug", fields(ev))]
     fn on_term_event(self, ev: Event) -> anyhow::Result<Self> {
         match ev {
             Event::Key(KeyEvent {

src/ui/burn/start.rs

@@ -55,6 +55,7 @@ impl BeginParams {
     }
 }
 
+#[tracing::instrument(skip_all, fields(root, interactive))]
 pub async fn try_start_burn(
     args: &BurnConfig,
     root: UseSudo,