diff --git a/presage-cli/Cargo.toml b/presage-cli/Cargo.toml index a8438d5ca..738d810ac 100644 --- a/presage-cli/Cargo.toml +++ b/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" diff --git a/presage-cli/src/main.rs b/presage-cli/src/main.rs index 8e7571264..112142e5b 100644 --- a/presage-cli/src/main.rs +++ b/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( .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( 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( .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( 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,14 +338,14 @@ fn print_message( 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; }; @@ -350,7 +353,7 @@ fn print_message( 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( }) => 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( 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( ) -> 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(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(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(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") + } } } } diff --git a/presage-store-sled/Cargo.toml b/presage-store-sled/Cargo.toml index f85496706..535748216 100644 --- a/presage-store-sled/Cargo.toml +++ b/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" diff --git a/presage-store-sled/src/content.rs b/presage-store-sled/src/content.rs index bfc713ff7..8f5d57d4f 100644 --- a/presage-store-sled/src/content.rs +++ b/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, ) -> Result { 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()..), diff --git a/presage-store-sled/src/error.rs b/presage-store-sled/src/error.rs index 56b21bf5f..12ca7d798 100644 --- a/presage-store-sled/src/error.rs +++ b/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 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()) } } diff --git a/presage-store-sled/src/lib.rs b/presage-store-sled/src/lib.rs index 89716bf87..24b47735e 100644 --- a/presage-store-sled/src/lib.rs +++ b/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), diff --git a/presage-store-sled/src/protocol.rs b/presage-store-sled/src/protocol.rs index 25e5ee31f..5036071bf 100644 --- a/presage-store-sled/src/protocol.rs +++ b/presage-store-sled/src/protocol.rs @@ -1,7 +1,6 @@ use std::marker::PhantomData; use async_trait::async_trait; -use log::{error, trace, warn}; use presage::{ libsignal_service::{ pre_keys::{KyberPreKeyStoreExt, PreKeysStore}, @@ -21,6 +20,7 @@ use presage::{ store::{ContentsStore, StateStore}, }; use sled::Batch; +use tracing::{error, trace, warn}; use crate::{OnNewIdentity, SledStore, SledStoreError}; @@ -56,8 +56,8 @@ impl SledProtocolStore { .read() .expect("poisoned mutex") .open_tree(tree) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("next_key_id", "sled error".into()) })? .into_iter() @@ -210,8 +210,8 @@ impl PreKeyStore for SledProtocolStore { ) -> Result<(), SignalProtocolError> { self.store .insert(T::pre_keys(), prekey_id.sled_key(), record.serialize()?) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("save_pre_key", "sled error".into()) })?; Ok(()) @@ -220,8 +220,8 @@ impl PreKeyStore for SledProtocolStore { async fn remove_pre_key(&mut self, prekey_id: PreKeyId) -> Result<(), SignalProtocolError> { self.store .remove(T::pre_keys(), prekey_id.sled_key()) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("remove_pre_key", "sled error".into()) })?; Ok(()) @@ -249,8 +249,8 @@ impl PreKeysStore for SledProtocolStore { .read() .expect("poisoned mutex") .open_tree(T::signed_pre_keys()) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("signed_pre_keys_count", "sled error".into()) })? .into_iter() @@ -271,8 +271,8 @@ impl PreKeysStore for SledProtocolStore { } else { T::kyber_pre_keys() }) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("save_signed_pre_key", "sled error".into()) })? .into_iter() @@ -308,8 +308,8 @@ impl SignedPreKeyStore for SledProtocolStore { signed_prekey_id.sled_key(), record.serialize()?, ) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("save_signed_pre_key", "sled error".into()) })?; Ok(()) @@ -342,8 +342,8 @@ impl KyberPreKeyStore for SledProtocolStore { kyber_prekey_id.sled_key(), record.serialize()?, ) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("save_kyber_pre_key", "sled error".into()) })?; Ok(()) @@ -356,12 +356,12 @@ impl KyberPreKeyStore for SledProtocolStore { let removed = self .store .remove(T::kyber_pre_keys(), kyber_prekey_id.sled_key()) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState("mark_kyber_pre_key_used", "sled error".into()) })?; if removed { - log::trace!("removed kyber pre-key {kyber_prekey_id}"); + trace!(%kyber_prekey_id, "removed kyber pre-key"); } Ok(()) } @@ -374,15 +374,15 @@ impl KyberPreKeyStoreExt for SledProtocolStore { kyber_prekey_id: KyberPreKeyId, record: &KyberPreKeyRecord, ) -> Result<(), SignalProtocolError> { - trace!("store_last_resort_kyber_pre_key"); + trace!(%kyber_prekey_id, "store_last_resort_kyber_pre_key"); self.store .insert( T::kyber_pre_keys_last_resort(), kyber_prekey_id.sled_key(), record.serialize()?, ) - .map_err(|e| { - log::error!("sled error: {}", e); + .map_err(|error| { + error!(%error, "sled error"); SignalProtocolError::InvalidState( "store_last_resort_kyber_pre_key", "sled error".into(), @@ -438,7 +438,11 @@ impl SessionStore for SledProtocolStore { address: &ProtocolAddress, ) -> Result, SignalProtocolError> { let session = self.store.get(T::sessions(), address.to_string())?; - trace!("loading session {} / exists={}", address, session.is_some()); + trace!( + %address, + session_exists = session.is_some(), + "loading session", + ); session .map(|b: Vec| SessionRecord::deserialize(&b)) .transpose() @@ -449,7 +453,7 @@ impl SessionStore for SledProtocolStore { address: &ProtocolAddress, record: &SessionRecord, ) -> Result<(), SignalProtocolError> { - trace!("storing session {}", address); + trace!(%address, "storing session"); self.store .insert(T::sessions(), address.to_string(), record.serialize()?)?; Ok(()) @@ -463,7 +467,7 @@ impl SessionStoreExt for SledProtocolStore { address: &ServiceAddress, ) -> Result, SignalProtocolError> { let session_prefix = format!("{}.", address.uuid); - trace!("get_sub_device_sessions {}", session_prefix); + trace!(session_prefix, "get_sub_device_sessions"); let session_ids: Vec = self .store .read() @@ -482,7 +486,7 @@ impl SessionStoreExt for SledProtocolStore { } async fn delete_session(&self, address: &ProtocolAddress) -> Result<(), SignalProtocolError> { - trace!("deleting session {}", address); + trace!(%address, "deleting session"); self.store .write() .open_tree(T::sessions()) @@ -554,9 +558,9 @@ impl IdentityKeyStore for SledProtocolStore { address.to_string(), identity_key.serialize(), ) - .map_err(|e| { - error!("error saving identity for {:?}: {}", address, e); - e + .map_err(|error| { + error!(%error, %address, "failed to save identity"); + error })?; self.store.save_trusted_identity_message( @@ -586,7 +590,7 @@ impl IdentityKeyStore for SledProtocolStore { { None => { // when we encounter a new identity, we trust it by default - warn!("trusting new identity {:?}", address); + warn!(%address, "trusting new identity"); Ok(true) } // when we encounter some identity we know, we need to decide whether we trust it or not diff --git a/presage/Cargo.toml b/presage/Cargo.toml index 69e5e9df8..809404f85 100644 --- a/presage/Cargo.toml +++ b/presage/Cargo.toml @@ -12,15 +12,15 @@ libsignal-service-hyper = { git = "https://github.com/whisperfish/libsignal-serv base64 = "0.22" futures = "0.3" -log = "0.4.20" +hex = "0.4.3" rand = "0.8" serde = "1.0" serde_json = "1.0" +sha2 = "0.10.8" thiserror = "1.0" -url = "2.5" tokio = { version = "1.35", default-features = false, features = ["sync", "time"] } -sha2 = "0.10.8" -hex = "0.4.3" +tracing = "0.1" +url = "2.5" [dev-dependencies] quickcheck = "1.0.3" diff --git a/presage/src/manager/confirmation.rs b/presage/src/manager/confirmation.rs index 30ba89a9e..dfd049696 100644 --- a/presage/src/manager/confirmation.rs +++ b/presage/src/manager/confirmation.rs @@ -10,8 +10,8 @@ use libsignal_service::push_service::{ use libsignal_service::zkgroup::profiles::ProfileKey; use libsignal_service::AccountManager; use libsignal_service_hyper::push_service::HyperPushService; -use log::trace; use rand::RngCore; +use tracing::trace; use crate::manager::registered::RegistrationData; use crate::store::Store; diff --git a/presage/src/manager/linking.rs b/presage/src/manager/linking.rs index bbda35e7a..d186b1d10 100644 --- a/presage/src/manager/linking.rs +++ b/presage/src/manager/linking.rs @@ -6,10 +6,10 @@ use libsignal_service::provisioning::{ link_device, NewDeviceRegistration, SecondaryDeviceProvisioning, }; use libsignal_service_hyper::push_service::HyperPushService; -use log::info; use rand::distributions::{Alphanumeric, DistString}; use rand::rngs::StdRng; use rand::{RngCore, SeedableRng}; +use tracing::info; use url::Url; use crate::manager::registered::RegistrationData; diff --git a/presage/src/manager/registered.rs b/presage/src/manager/registered.rs index 46744a034..330a35c04 100644 --- a/presage/src/manager/registered.rs +++ b/presage/src/manager/registered.rs @@ -36,12 +36,12 @@ use libsignal_service::zkgroup::groups::{GroupMasterKey, GroupSecretParams}; use libsignal_service::zkgroup::profiles::ProfileKey; use libsignal_service::{cipher, AccountManager, Profile, ServiceAddress}; use libsignal_service_hyper::push_service::HyperPushService; -use log::{debug, error, info, trace, warn}; use rand::rngs::StdRng; use rand::SeedableRng; use serde::{Deserialize, Serialize}; use sha2::Digest; use tokio::sync::Mutex; +use tracing::{debug, error, info, trace, warn}; use url::Url; use crate::serde::serde_profile_key; @@ -355,7 +355,7 @@ impl Manager { tokio::time::timeout(Duration::from_secs(60), async move { while let Some(msg) = messages.next().await { - log::trace!("got message while waiting for contacts sync: {msg:?}"); + trace!(?msg, "got message while waiting for contacts sync:"); } }) .await?; @@ -652,14 +652,16 @@ impl Manager { let _ = state.store.clear_contacts(); info!("saving contacts"); for contact in contacts.filter_map(Result::ok) { - if let Err(e) = state.store.save_contact(&contact) { - warn!("failed to save contacts: {e}"); + if let Err(error) = + state.store.save_contact(&contact) + { + warn!(%error, "failed to save contacts"); break; } } } - Err(e) => { - warn!("failed to retrieve contacts: {e}"); + Err(error) => { + warn!(%error, "failed to retrieve contacts"); } } @@ -698,7 +700,8 @@ impl Manager { ); } Err(error) => error!( - "failed to download sticker pack: {error}" + %error, + "failed to download sticker pack" ), } }); @@ -708,14 +711,13 @@ impl Manager { .store .remove_sticker_pack(operation.pack_id()) { - Ok(removed) => { - debug!( - "removed stick pack: present={removed}" - ) + Ok(was_present) => { + debug!(was_present, "removed stick pack") } Err(error) => { error!( - "failed to remove sticker pack: {error}" + %error, + "failed to remove sticker pack" ) } } @@ -763,11 +765,11 @@ impl Manager { ) .await { - trace!("{group:?}"); + trace!(?group, "upserted group"); } } - if let Err(e) = save_message( + if let Err(error) = save_message( &mut state.store, &mut state.push_service, content.clone(), @@ -775,16 +777,16 @@ impl Manager { ) .await { - error!("Error saving message to store: {}", e); + error!(%error, "error saving message to store"); } return Some((content, state)); } Ok(None) => { - debug!("Empty envelope..., message will be skipped!") + debug!("empty envelope..., message will be skipped!") } - Err(e) => { - error!("Error opening envelope: {:?}, message will be skipped!", e); + Err(error) => { + error!(%error, "error opening envelope, message will be skipped!"); } } } @@ -794,7 +796,9 @@ impl Manager { return None; } } - Some(Err(e)) => error!("Error: {}", e), + Some(Err(error)) => { + error!(%error, "unexpected error in message receiving loop") + } None => return None, } } @@ -952,7 +956,7 @@ impl Manager { Ok(_) => false, // Ignore any NotFound errors, those mean that e.g. some contact in a group deleted his account. Err(MessageSenderError::NotFound { addr }) => { - debug!("UUID {} not found, skipping sent message result", addr.uuid); + debug!(uuid = %addr.uuid, "UUID not found, skipping sent message result"); false } // return first error if any @@ -1028,8 +1032,8 @@ impl Manager { // We need the whole file for the crypto to check out let mut ciphertext = Vec::new(); - let len = attachment_stream.read_to_end(&mut ciphertext).await?; - trace!("downloaded encrypted attachment of {} bytes", len); + let size_bytes = attachment_stream.read_to_end(&mut ciphertext).await?; + trace!(size_bytes, "downloaded encrypted attachment"); let digest = sha2::Sha256::digest(&ciphertext); if &digest[..] != expected_digest { @@ -1144,7 +1148,7 @@ impl Manager { recipient: &ServiceAddress, timestamp: u64, ) -> Result<(), Error> { - trace!("Resetting session for address: {}", recipient.uuid); + trace!(%recipient.uuid, "resetting session for address"); let message = DataMessage { flags: Some(DataMessageFlags::EndSession as u32), ..Default::default() @@ -1215,8 +1219,8 @@ impl Manager { Thread::Contact(uuid) => { let contact = match self.store.contact_by_id(uuid) { Ok(contact) => contact, - Err(e) => { - info!("Error getting contact by id: {}, {:?}", e, uuid); + Err(error) => { + info!(%error, %uuid, "error getting contact by id"); None } }; @@ -1353,12 +1357,12 @@ async fn upsert_group( ) -> Result, Error> { let upsert_group = match store.group(master_key_bytes.try_into()?) { Ok(Some(group)) => { - debug!("loaded group from local db {}", group.title); + debug!(group_name =% group.title, "loaded group from local db"); group.revision < *revision } Ok(None) => true, - Err(e) => { - warn!("failed to retrieve group from local db {}", e); + Err(error) => { + warn!(%error, "failed to retrieve group from local db"); true } }; @@ -1368,12 +1372,12 @@ async fn upsert_group( match groups_manager.fetch_encrypted_group(master_key_bytes).await { Ok(encrypted_group) => { let group = decrypt_group(master_key_bytes, encrypted_group)?; - if let Err(e) = store.save_group(master_key_bytes.try_into()?, &group) { - error!("failed to save group {master_key_bytes:?}: {e}",); + if let Err(error) = store.save_group(master_key_bytes.try_into()?, &group) { + error!(%error, "failed to save group"); } } - Err(e) => { - warn!("failed to fetch encrypted group: {e}") + Err(error) => { + warn!(%error, "failed to fetch encrypted group") } } } @@ -1394,16 +1398,13 @@ async fn download_sticker_pack( let mut ciphertext = Vec::new(); - let len = push_service + let size_bytes = push_service .get_sticker_pack_manifest(&hex::encode(pack_id)) .await? .read_to_end(&mut ciphertext) .await?; - trace!( - "downloaded encrypted sticker pack manifest of {} bytes", - len - ); + trace!(size_bytes, "downloaded encrypted sticker pack manifest"); decrypt_in_place(key, &mut ciphertext)?; @@ -1415,10 +1416,10 @@ async fn download_sticker_pack( for sticker in &mut sticker_pack_manifest.stickers { match download_sticker(&mut store, &mut push_service, pack_id, pack_key, sticker.id).await { Ok(decrypted_sticker_bytes) => { - debug!("downloaded sticker {}", sticker.id); + debug!(id = sticker.id, "downloaded sticker"); sticker.bytes = Some(decrypted_sticker_bytes); } - Err(error) => error!("failed to download sticker {}: {error}", sticker.id), + Err(error) => error!(sticker.id, %error,"failed to download sticker"), } } @@ -1449,9 +1450,9 @@ async fn download_sticker( .await?; let mut ciphertext = Vec::new(); - let len = sticker_stream.read_to_end(&mut ciphertext).await?; + let size_bytes = sticker_stream.read_to_end(&mut ciphertext).await?; - trace!("downloaded encrypted sticker of {} bytes", len); + trace!(size_bytes, "downloaded encrypted sticker"); decrypt_in_place(key, &mut ciphertext)?; @@ -1495,7 +1496,7 @@ async fn save_message( if let Some(profile_key_bytes) = profile_key.clone().and_then(|p| p.try_into().ok()) { let sender_uuid = message.metadata.sender.uuid; let profile_key = ProfileKey::create(profile_key_bytes); - debug!("inserting profile key for {sender_uuid}"); + debug!(%sender_uuid, "inserting profile key for"); // Either: // - insert a new contact with the profile information @@ -1539,7 +1540,7 @@ async fn save_message( verified: Verified::default(), }; - info!("saved contact after seeing {sender_uuid} for the first time"); + info!(%sender_uuid, "saved contact on first sight"); store.save_contact(&contact)?; } @@ -1564,10 +1565,10 @@ async fn save_message( existing_msg.metadata.sender.uuid = Uuid::nil(); existing_msg.body = NullMessage::default().into(); store.save_message(&thread, existing_msg)?; - debug!("message in thread {thread} @ {ts} deleted"); + debug!(%thread, ts, "message in thread deleted"); None } else { - warn!("could not find message to delete in thread {thread} @ {ts}"); + warn!(%thread, ts, "could not find message to delete in thread"); None } } @@ -1594,10 +1595,10 @@ async fn save_message( existing_msg.metadata = message.metadata; existing_msg.body = ContentBody::DataMessage(data_message); // TODO: find a way to mark the message as edited (so that it's visible in a client) - trace!("message in thread {thread} @ {ts} edited"); + trace!(%thread, ts, "message in thread edited"); Some(existing_msg) } else { - warn!("could not find edited message {thread} @ {ts}"); + warn!(%thread, ts, "could not find edited message"); None } } diff --git a/presage/src/manager/registration.rs b/presage/src/manager/registration.rs index e70b7ab83..db8d1cc52 100644 --- a/presage/src/manager/registration.rs +++ b/presage/src/manager/registration.rs @@ -2,10 +2,10 @@ use libsignal_service::configuration::{ServiceConfiguration, SignalServers}; use libsignal_service::prelude::phonenumber::PhoneNumber; use libsignal_service::push_service::{PushService, VerificationTransport}; use libsignal_service_hyper::push_service::HyperPushService; -use log::trace; use rand::distributions::{Alphanumeric, DistString}; use rand::rngs::StdRng; use rand::SeedableRng; +use tracing::trace; use crate::store::Store; use crate::{Error, Manager}; diff --git a/presage/src/store.rs b/presage/src/store.rs index 8425aa9e6..77e1b3a34 100644 --- a/presage/src/store.rs +++ b/presage/src/store.rs @@ -17,8 +17,8 @@ use libsignal_service::{ zkgroup::GroupMasterKeyBytes, Profile, ServiceAddress, }; -use log::error; use serde::{Deserialize, Serialize}; +use tracing::{error, trace}; use crate::{manager::RegistrationData, AvatarBytes}; @@ -135,7 +135,7 @@ pub trait ContentsStore: Send + Sync { }; if let Err(error) = self.save_message(&thread, verified_sync_message) { - error!("failed to save the verified session message in thread: {error}"); + error!(%error, "failed to save the verified session message in thread"); } } @@ -187,12 +187,7 @@ pub trait ContentsStore: Send + Sync { timer: u32, version: u32, ) -> Result<(), Self::ContentsStoreError> { - log::trace!( - "update expire timer of {:?} to {} (version {})", - thread, - timer, - version - ); + trace!(%thread, timer, version, "updating expire timer"); match thread { Thread::Contact(uuid) => { let contact = self.contact_by_id(uuid)?;