Switch from log to tracing (#274)

* Use tracing instead of log
* Use tracing fields instead of string formatting

presage-cli/Cargo.toml

@@ -17,10 +17,11 @@ directories = "5.0"
 env_logger = "0.11"
 futures = "0.3"
 hex = "0.4"
-log = "0.4"
 mime_guess = "2.0"
+notify-rust = "4.10.0"
+qr2term = { version = "0.3.1" }
 tempfile = "3.9"
 tokio = { version = "1.35", features = ["macros", "rt-multi-thread", "io-std", "io-util"] }
-qr2term = { version = "0.3.1" }
-notify-rust = "4.10.0"
+tracing = "0.1"
+tracing-subscriber = { version = "0.3", default-features = false }
 url = "2.5"

presage-cli/src/main.rs

@@ -11,7 +11,6 @@ use directories::ProjectDirs;
 use env_logger::Env;
 use futures::StreamExt;
 use futures::{channel::oneshot, future, pin_mut};
-use log::{debug, error, info};
 use notify_rust::Notification;
 use presage::libsignal_service::configuration::SignalServers;
 use presage::libsignal_service::content::Reaction;
@@ -43,6 +42,8 @@ use tokio::{
     fs,
     io::{self, AsyncBufReadExt, BufReader},
 };
+use tracing::warn;
+use tracing::{debug, error, info};
 use url::Url;
 
 #[derive(Parser)]
@@ -213,7 +214,7 @@ async fn main() -> anyhow::Result<()> {
             .config_dir()
             .into()
     });
-    debug!("opening config database from {}", db_path.display());
+    debug!(db_path =% db_path.display(), "opening config database");
     let config_store = SledStore::open_with_passphrase(
         db_path,
         args.passphrase,
@@ -244,14 +245,14 @@ async fn send<S: Store>(
         .run_until(async move {
             let mut receiving_manager = manager.clone();
             task::spawn_local(async move {
-                if let Err(e) = receive(&mut receiving_manager, false).await {
-                    error!("error while receiving stuff: {e}");
+                if let Err(error) = receive(&mut receiving_manager, false).await {
+                    error!(%error, "error while receiving stuff");
                 }
             });
 
             match recipient {
                 Recipient::Contact(uuid) => {
-                    info!("sending message to contact");
+                    info!(recipient =% uuid, "sending message to contact");
                     manager
                         .send_message(ServiceAddress::new_aci(uuid), content_body, timestamp)
                         .await
@@ -285,7 +286,7 @@ async fn process_incoming_message<S: Store>(
     if let ContentBody::DataMessage(DataMessage { attachments, .. }) = &content.body {
         for attachment_pointer in attachments {
             let Ok(attachment_data) = manager.get_attachment(attachment_pointer).await else {
-                log::warn!("failed to fetch attachment");
+                warn!("failed to fetch attachment");
                 continue;
             };
 
@@ -302,10 +303,12 @@ async fn process_incoming_message<S: Store>(
                 .unwrap_or_else(|| Local::now().format("%Y-%m-%d-%H-%M-%s").to_string());
             let file_path = attachments_tmp_dir.join(format!("presage-{filename}.{extension}",));
             match fs::write(&file_path, &attachment_data).await {
-                Ok(_) => info!("saved attachment from {sender} to {}", file_path.display()),
+                Ok(_) => info!(%sender, file_path =% file_path.display(), "saved attachment"),
                 Err(error) => error!(
-                    "failed to write attachment from {sender} to {}: {error}",
-                    file_path.display()
+                    %sender,
+                    file_path =% file_path.display(),
+                    %error,
+                    "failed to write attachment"
                 ),
             }
         }
@@ -318,7 +321,7 @@ fn print_message<S: Store>(
     content: &Content,
 ) {
     let Ok(thread) = Thread::try_from(content) else {
-        log::warn!("failed to derive thread from content");
+        warn!("failed to derive thread from content");
         return;
     };
 
@@ -335,22 +338,22 @@ fn print_message<S: Store>(
         DataMessage {
             reaction:
                 Some(Reaction {
-                    target_sent_timestamp: Some(timestamp),
+                    target_sent_timestamp: Some(ts),
                     emoji: Some(emoji),
                     ..
                 }),
             ..
         } => {
-            let Ok(Some(message)) = manager.store().message(thread, *timestamp) else {
-                log::warn!("no message in {thread} sent at {timestamp}");
+            let Ok(Some(message)) = manager.store().message(thread, *ts) else {
+                warn!(%thread, sent_at = ts, "no message found in thread");
                 return None;
             };
 
             let ContentBody::DataMessage(DataMessage {
                 body: Some(body), ..
             }) = message.body
             else {
-                log::warn!("message reacted to has no body");
+                warn!("message reacted to has no body");
                 return None;
             };
 
@@ -422,8 +425,8 @@ fn print_message<S: Store>(
         }) => format_data_message(&thread, data_message).map(|body| Msg::Sent(&thread, body)),
         ContentBody::CallMessage(_) => Some(Msg::Received(&thread, "is calling!".into())),
         ContentBody::TypingMessage(_) => Some(Msg::Received(&thread, "is typing...".into())),
-        c => {
-            log::warn!("unsupported message {c:?}");
+        content_body => {
+            warn!(?content_body, "unsupported message");
             None
         }
     } {
@@ -451,13 +454,13 @@ fn print_message<S: Store>(
         println!("{prefix} / {body}");
 
         if notifications {
-            if let Err(e) = Notification::new()
+            if let Err(error) = Notification::new()
                 .summary(&prefix)
                 .body(&body)
                 .icon("presage")
                 .show()
             {
-                log::error!("failed to display desktop notification: {e}");
+                error!(%error, "failed to display desktop notification");
             }
         }
     }
@@ -469,8 +472,8 @@ async fn receive<S: Store>(
 ) -> anyhow::Result<()> {
     let attachments_tmp_dir = Builder::new().prefix("presage-attachments").tempdir()?;
     info!(
-        "attachments will be stored in {}",
-        attachments_tmp_dir.path().display()
+        path =% attachments_tmp_dir.path().display(),
+        "attachments will be stored"
     );
 
     let messages = manager
@@ -540,7 +543,7 @@ async fn run<S: Store>(subcommand: Cmd, config_store: S) -> anyhow::Result<()> {
                             qr2term::print_qr(url.to_string()).expect("failed to render qrcode");
                             println!("Alternatively, use the URL: {}", url);
                         }
-                        Err(e) => log::error!("Error linking device: {e}"),
+                        Err(error) => error!(%error, "linking device was cancelled"),
                     }
                 },
             )
@@ -667,7 +670,7 @@ async fn run<S: Store>(subcommand: Cmd, config_store: S) -> anyhow::Result<()> {
                         );
                     }
                     Err(error) => {
-                        error!("Error: failed to deserialize group, {error}");
+                        error!(%error, "failed to deserialize group");
                     }
                 };
             }
@@ -703,7 +706,9 @@ async fn run<S: Store>(subcommand: Cmd, config_store: S) -> anyhow::Result<()> {
                             )
                         }
                     }
-                    Err(error) => error!("error while deserializing sticker pack: {error}"),
+                    Err(error) => {
+                        error!(%error, "error while deserializing sticker pack")
+                    }
                 }
             }
         }

presage-store-sled/Cargo.toml

@@ -11,16 +11,16 @@ presage-store-cipher = { path = "../presage-store-cipher", optional = true }
 
 async-trait = "0.1"
 base64 = "0.22"
+chrono = "0.4.35"
 fs_extra = "1.3"
-log = "0.4.20"
-sled = { version = "0.34" }
+prost = "0.13"
+quickcheck_macros = "1.0.0"
 serde = { version = "1.0", features = ["derive"] }
 serde_json = "1.0"
-thiserror = "1.0"
-prost = "0.13"
 sha2 = "0.10"
-quickcheck_macros = "1.0.0"
-chrono = "0.4.35"
+sled = { version = "0.34" }
+thiserror = "1.0"
+tracing = "0.1"
 
 [build-dependencies]
 prost-build = "0.13"

presage-store-sled/src/content.rs

@@ -3,7 +3,6 @@ use std::{
     sync::Arc,
 };
 
-use log::debug;
 use presage::{
     libsignal_service::{
         content::Content,
@@ -20,6 +19,7 @@ use prost::Message;
 use serde::de::DeserializeOwned;
 use sha2::{Digest, Sha256};
 use sled::IVec;
+use tracing::{debug, trace};
 
 use crate::{protobuf::ContentProto, SledStore, SledStoreError};
 
@@ -155,7 +155,7 @@ impl ContentsStore for SledStore {
     }
 
     fn clear_thread(&mut self, thread: &Thread) -> Result<(), SledStoreError> {
-        log::trace!("clearing thread {thread}");
+        trace!(%thread, "clearing thread");
 
         let db = self.write();
         db.drop_tree(messages_thread_tree_name(thread))?;
@@ -166,7 +166,7 @@ impl ContentsStore for SledStore {
 
     fn save_message(&self, thread: &Thread, message: Content) -> Result<(), SledStoreError> {
         let ts = message.timestamp();
-        log::trace!("storing a message with thread: {thread}, timestamp: {ts}",);
+        trace!(%thread, ts, "storing a message with thread");
 
         let tree = messages_thread_tree_name(thread);
         let key = ts.to_be_bytes();
@@ -204,7 +204,7 @@ impl ContentsStore for SledStore {
         range: impl RangeBounds<u64>,
     ) -> Result<Self::MessagesIter, SledStoreError> {
         let tree_thread = self.read().open_tree(messages_thread_tree_name(thread))?;
-        debug!("{} messages in this tree", tree_thread.len());
+        debug!(%thread, count = tree_thread.len(), "loading message tree");
 
         let iter = match (range.start_bound(), range.end_bound()) {
             (Bound::Included(start), Bound::Unbounded) => tree_thread.range(start.to_be_bytes()..),

presage-store-sled/src/error.rs

@@ -1,4 +1,5 @@
 use presage::{libsignal_service::protocol::SignalProtocolError, store::StoreError};
+use tracing::error;
 
 #[derive(Debug, thiserror::Error)]
 pub enum SledStoreError {
@@ -31,7 +32,7 @@ impl StoreError for SledStoreError {}
 
 impl From<SledStoreError> for SignalProtocolError {
     fn from(error: SledStoreError) -> Self {
-        log::error!("presage store error: {error}");
+        error!(%error, "presage store error");
         Self::InvalidState("presage store error", error.to_string())
     }
 }

presage-store-sled/src/lib.rs

@@ -6,7 +6,6 @@ use std::{
 };
 
 use base64::prelude::*;
-use log::debug;
 use presage::{
     libsignal_service::{
         prelude::{ProfileKey, Uuid},
@@ -22,6 +21,7 @@ use presage::{
 use protocol::{AciSledStore, PniSledStore, SledProtocolStore, SledTrees};
 use serde::{de::DeserializeOwned, Deserialize, Serialize};
 use sha2::{Digest, Sha256};
+use tracing::{debug, error};
 
 mod content;
 mod error;
@@ -389,7 +389,7 @@ fn migrate(
                     };
 
                     if let Err(error) = run_step() {
-                        log::error!("failed to run v4 -> v5 migration: {error}");
+                        error!("failed to run v4 -> v5 migration: {error}");
                     }
                 }
                 SchemaVersion::V6 => {
@@ -424,7 +424,7 @@ fn migrate(
                             let _ = tree.insert(k.to_be_bytes(), v);
                         }
                         let num_keys_after = tree.len();
-                        debug!("migrated keys in {tree_name}: before {num_keys_before} -> after {num_keys_after}");
+                        debug!(tree_name, num_keys_before, num_keys_after, "migrated keys");
                     }
                 }
                 _ => return Err(SledStoreError::MigrationConflict),