diff --git a/.config/semgrep.yaml b/.config/semgrep.yaml index 5d6d3aa9e90..47ccda75d9a 100644 --- a/.config/semgrep.yaml +++ b/.config/semgrep.yaml @@ -111,6 +111,8 @@ rules: include: - fedimint-server/ - fedimint-core/ + - fedimint-cli/ + - fedimint-client/ - id: use-client-log-targets languages: diff --git a/fedimint-cli/src/client.rs b/fedimint-cli/src/client.rs index 41f5344521c..c7cf2e735fc 100644 --- a/fedimint-cli/src/client.rs +++ b/fedimint-cli/src/client.rs @@ -233,7 +233,10 @@ pub async fn handle_command( timeout, include_invite, } => { - warn!("The client will try to double-spend these notes after the duration specified by the --timeout option to recover any unclaimed e-cash."); + warn!( + target: LOG_CLIENT, + "The client will try to double-spend these notes after the duration specified by the --timeout option to recover any unclaimed e-cash." + ); let mint_module = client.get_first_module::()?; let timeout = Duration::from_secs(timeout); @@ -251,6 +254,7 @@ pub async fn handle_command( let overspend_amount = notes.total_amount() - amount; if overspend_amount != Amount::ZERO { warn!( + target: LOG_CLIENT, "Selected notes {} worth more than requested", overspend_amount ); @@ -268,7 +272,7 @@ pub async fn handle_command( ) .await? }; - info!("Spend e-cash operation: {}", operation.fmt_short()); + info!(target: LOG_CLIENT, "Spend e-cash operation: {}", operation.fmt_short()); Ok(json!({ "notes": notes, @@ -337,7 +341,10 @@ pub async fn handle_command( gateway_id, force_internal, } => { - warn!("Command deprecated. Use `fedimint-cli module ln invoice` instead."); + warn!( + target: LOG_CLIENT, + "Command deprecated. Use `fedimint-cli module ln invoice` instead." + ); let lightning_module = client.get_first_module::()?; let ln_gateway = lightning_module .get_gateway(gateway_id, force_internal) @@ -392,10 +399,13 @@ pub async fn handle_command( gateway_id, force_internal, } => { - warn!("Command deprecated. Use `fedimint-cli module ln pay` instead."); + warn!( + target: LOG_CLIENT, + "Command deprecated. Use `fedimint-cli module ln pay` instead." + ); let bolt11 = fedimint_ln_client::get_invoice(&payment_info, amount, lnurl_comment).await?; - info!("Paying invoice: {bolt11}"); + info!(target: LOG_CLIENT, "Paying invoice: {bolt11}"); let lightning_module = client.get_first_module::()?; let ln_gateway = lightning_module .get_gateway(gateway_id, force_internal) @@ -411,6 +421,7 @@ pub async fn handle_command( .await?; let operation_id = payment_type.operation_id(); info!( + target: LOG_CLIENT, "Gateway fee: {fee}, payment operation id: {}", operation_id.fmt_short() ); @@ -419,7 +430,10 @@ pub async fn handle_command( .get_first_module::()? .wait_for_ln_payment(payment_type, contract_id, true) .await?; - info!("Payment will finish in background, use await-ln-pay to get the result"); + info!( + target: LOG_CLIENT, + "Payment will finish in background, use await-ln-pay to get the result" + ); Ok(serde_json::json! { { "operation_id": operation_id, @@ -564,7 +578,10 @@ pub async fn handle_command( }; let absolute_fees = fees.amount(); - info!("Attempting withdraw with fees: {fees:?}"); + info!( + target: LOG_CLIENT, + "Attempting withdraw with fees: {fees:?}" + ); let operation_id = wallet_module.withdraw(address, amount, fees, ()).await?; diff --git a/fedimint-cli/src/lib.rs b/fedimint-cli/src/lib.rs index f2e010b4386..6c140dfb198 100644 --- a/fedimint-cli/src/lib.rs +++ b/fedimint-cli/src/lib.rs @@ -301,7 +301,10 @@ async fn load_or_generate_mnemonic(db: &Database) -> Result if let Ok(entropy) = Client::load_decodable_client_secret::>(db).await { Mnemonic::from_entropy(&entropy).map_err_cli()? } else { - info!("Generating mnemonic and writing entropy to client storage"); + info!( + target: LOG_CLIENT, + "Generating mnemonic and writing entropy to client storage" + ); let mnemonic = Bip39RootSecretStrategy::<12>::random(&mut thread_rng()); Client::store_encodable_client_secret(db, mnemonic.to_entropy()) .await diff --git a/fedimint-client/src/backup.rs b/fedimint-client/src/backup.rs index 7133465c8b4..ee215ca02ea 100644 --- a/fedimint-client/src/backup.rs +++ b/fedimint-client/src/backup.rs @@ -141,6 +141,7 @@ impl ClientBackup { { let size_previous = last_module_backup.consensus_encode_to_len(); warn!( + target: LOG_CLIENT_BACKUP, size, limit, %module_id, @@ -150,6 +151,7 @@ impl ClientBackup { modules.insert(module_id, last_module_backup.clone()); } else { warn!( + target: LOG_CLIENT_BACKUP, size, limit, %module_id, diff --git a/fedimint-client/src/lib.rs b/fedimint-client/src/lib.rs index 473e49d1177..663dcd1f355 100644 --- a/fedimint-client/src/lib.rs +++ b/fedimint-client/src/lib.rs @@ -680,7 +680,10 @@ impl ClientHandle { async fn shutdown_inner(&mut self) { let Some(inner) = self.inner.take() else { - error!("ClientHandleShared::shutdown called twice"); + error!( + target: LOG_CLIENT, + "ClientHandleShared::shutdown called twice" + ); return; }; inner.executor.stop_executor(); @@ -1004,6 +1007,7 @@ impl Client { pub fn start_executor(self: &Arc) { debug!( + target: LOG_CLIENT, "Starting fedimint client executor (version: {})", fedimint_build_code_version_env!() ); @@ -1645,7 +1649,10 @@ impl Client { .get_value(&CachedApiVersionSetKey) .await { - debug!("Found existing cached common api versions"); + debug!( + target: LOG_CLIENT, + "Found existing cached common api versions" + ); let config = config.clone(); let client_module_init = module_init.clone(); let api = api.clone(); @@ -1665,14 +1672,20 @@ impl Client { ) .await { - warn!(%error, "Failed to discover common api versions"); + warn!( + target: LOG_CLIENT, + %error, "Failed to discover common api versions" + ); } }); return Ok(v.0); } - debug!("No existing cached common api versions found, waiting for initial discovery"); + debug!( + target: LOG_CLIENT, + "No existing cached common api versions found, waiting for initial discovery" + ); Self::refresh_common_api_version_static(config, module_init, api, db, task_group.clone()) .await } @@ -1684,7 +1697,10 @@ impl Client { db: &Database, task_group: TaskGroup, ) -> anyhow::Result { - debug!("Refreshing common api versions"); + debug!( + target: LOG_CLIENT, + "Refreshing common api versions" + ); let (num_responses_sender, mut num_responses_receiver) = tokio::sync::watch::channel(0); let num_peers = NumPeers::from(config.global.api_endpoints.len()); @@ -1719,6 +1735,7 @@ impl Client { )?; debug!( + target: LOG_CLIENT, value = ?common_api_versions, "Updating the cached common api versions" ); @@ -1743,7 +1760,10 @@ impl Client { .get_value(&ClientMetadataKey) .await .unwrap_or_else(|| { - warn!("Missing existing metadata. This key should have been set on Client init"); + warn!( + target: LOG_CLIENT, + "Missing existing metadata. This key should have been set on Client init" + ); Metadata::empty() }) } @@ -1880,7 +1900,7 @@ impl Client { watch::Receiver, >, ) { - debug!(target:LOG_CLIENT_RECOVERY, num_modules=%module_recovery_progress_receivers.len(), "Staring module recoveries"); + debug!(target: LOG_CLIENT_RECOVERY, num_modules=%module_recovery_progress_receivers.len(), "Staring module recoveries"); let mut completed_stream = Vec::new(); let progress_stream = futures::stream::FuturesUnordered::new(); @@ -1889,7 +1909,10 @@ impl Client { match f.await { Ok(()) => (module_instance_id, None), Err(err) => { - warn!(%err, module_instance_id, "Module recovery failed"); + warn!( + target: LOG_CLIENT, + %err, module_instance_id, "Module recovery failed" + ); // a module recovery that failed reports and error and // just never finishes, so we don't need a separate state // for it @@ -1932,6 +1955,7 @@ impl Client { if !prev_progress.is_done() && progress.is_done() { info!( + target: LOG_CLIENT, module_instance_id, prev_progress = format!("{}/{}", prev_progress.complete, prev_progress.total), progress = format!("{}/{}", progress.complete, progress.total), @@ -1947,6 +1971,7 @@ impl Client { .await; } else { info!( + target: LOG_CLIENT, module_instance_id, prev_progress = format!("{}/{}", prev_progress.complete, prev_progress.total), progress = format!("{}/{}", progress.complete, progress.total), @@ -2046,7 +2071,10 @@ impl Client { .expect("Will never return on error"); let Some(guardian_pub_keys) = fetched_config.global.broadcast_public_keys else { - warn!("Guardian public keys not found in fetched config, server not updated to 0.4 yet"); + warn!( + target: LOG_CLIENT, + "Guardian public keys not found in fetched config, server not updated to 0.4 yet" + ); pending::<()>().await; unreachable!("Pending will never return"); }; @@ -2719,7 +2747,7 @@ impl ClientBuilder { modules: BTreeMap::new(), }); - debug!(?common_api_versions, "Completed api version negotiation"); + debug!(target: LOG_CLIENT, ?common_api_versions, "Completed api version negotiation"); let mut module_recoveries: BTreeMap< ModuleInstanceId, @@ -2739,13 +2767,22 @@ impl ClientBuilder { for (module_instance_id, module_config) in config.modules.clone() { let kind = module_config.kind().clone(); let Some(module_init) = self.module_inits.get(&kind).cloned() else { - debug!("Module kind {kind} of instance {module_instance_id} not found in module gens, skipping"); + debug!( + target: LOG_CLIENT, + kind=%kind, + instance_id=%module_instance_id, + "Module kind of instance not found in module gens, skipping"); continue; }; let Some(&api_version) = common_api_versions.modules.get(&module_instance_id) else { - warn!("Module kind {kind} of instance {module_instance_id} has not compatible api version, skipping"); + warn!( + target: LOG_CLIENT, + kind=%kind, + instance_id=%module_instance_id, + "Module kind of instance has incompatible api version, skipping" + ); continue; }; @@ -2788,8 +2825,9 @@ impl ClientBuilder { .await .map_err(|err| { warn!( - module_id = module_instance_id, %kind, %err, "Module failed to recover" - ); + target: LOG_CLIENT, + module_id = module_instance_id, %kind, %err, "Module failed to recover" + ); err }) }), @@ -2995,7 +3033,10 @@ impl ClientBuilder { .unwrap_or_else(|| { // could be turned in a hard error in the future, but for now // no need to break backward compat. - warn!("Client missing ClientRequiresRecovery: assuming complete"); + warn!( + target: LOG_CLIENT, + "Client missing ClientRequiresRecovery: assuming complete" + ); db::InitState::Complete(db::InitModeComplete::Fresh) }) } diff --git a/fedimint-client/src/meta.rs b/fedimint-client/src/meta.rs index 08306ab764b..e6f85742e56 100644 --- a/fedimint-client/src/meta.rs +++ b/fedimint-client/src/meta.rs @@ -12,6 +12,7 @@ use fedimint_core::task::waiter::Waiter; use fedimint_core::task::{MaybeSend, MaybeSync}; use fedimint_core::util::{backoff_util, retry}; use fedimint_core::{apply, async_trait_maybe_send}; +use fedimint_logging::LOG_CLIENT; use serde::de::DeserializeOwned; use serde::{Deserialize, Serialize}; use tokio::sync::Notify; @@ -187,7 +188,7 @@ impl MetaService { let failed_initial = meta_values.is_err(); match meta_values { Ok(meta_values) => self.save_meta_values(client, &meta_values).await, - Err(error) => warn!(%error, "failed to fetch source"), + Err(error) => warn!(target: LOG_CLIENT, %error, "failed to fetch source"), }; self.initial_fetch_waiter.done(); @@ -314,7 +315,7 @@ pub async fn fetch_meta_overrides( if let serde_json::Value::String(value_str) = value { Some((MetaFieldKey(key), MetaFieldValue(value_str))) } else { - warn!("Meta override map contained non-string key: {key}, ignoring"); + warn!(target: LOG_CLIENT, "Meta override map contained non-string key: {key}, ignoring"); None } }) diff --git a/fedimint-client/src/module/init.rs b/fedimint-client/src/module/init.rs index b94718ec28d..d2f8eb48bc4 100644 --- a/fedimint-client/src/module/init.rs +++ b/fedimint-client/src/module/init.rs @@ -15,6 +15,7 @@ use fedimint_core::module::{ use fedimint_core::task::{MaybeSend, MaybeSync, TaskGroup}; use fedimint_core::{apply, async_trait_maybe_send, dyn_newtype_define, NumPeers}; use fedimint_derive_secret::DerivableSecret; +use fedimint_logging::LOG_CLIENT; use tokio::sync::watch; use tracing::warn; @@ -196,13 +197,13 @@ where if progress.is_done() { // Recovery is complete when the recovery function finishes. To avoid // confusing any downstream code, we never send completed process. - warn!("Module trying to send a completed recovery progress. Ignoring"); + warn!(target: LOG_CLIENT, "Module trying to send a completed recovery progress. Ignoring"); } else if progress.is_none() { // Recovery starts with "none" none progress. To avoid // confusing any downstream code, we never send none process afterwards. - warn!("Module trying to send a none recovery progress. Ignoring"); + warn!(target: LOG_CLIENT, "Module trying to send a none recovery progress. Ignoring"); } else if self.progress_tx.send(progress).is_err() { - warn!("Module trying to send a recovery progress but nothing is listening"); + warn!(target: LOG_CLIENT, "Module trying to send a recovery progress but nothing is listening"); } } } @@ -226,6 +227,7 @@ pub trait ClientModuleInit: ModuleInit + Sized { _snapshot: Option<&::Backup>, ) -> anyhow::Result<()> { warn!( + target: LOG_CLIENT, kind = %::kind(), "Module does not support recovery, completing without doing anything" ); diff --git a/fedimint-client/src/module/init/recovery.rs b/fedimint-client/src/module/init/recovery.rs index 294f5dc6ab1..5fbd5b1c998 100644 --- a/fedimint-client/src/module/init/recovery.rs +++ b/fedimint-client/src/module/init/recovery.rs @@ -266,7 +266,10 @@ where // is not being polled, and possibly can increase the fetching performance. task_group.spawn_cancellable("recovery fetch block", async move { - info!(session_idx, "Fetching epoch"); + info!( + target: LOG_CLIENT_RECOVERY, + session_idx, "Fetching epoch" + ); let mut retry_sleep = Duration::from_millis(10); let block = loop { @@ -390,7 +393,10 @@ where // again and moves to finalization // 6. module runs finalization again and probably fails because it's actually // not idempotent and doesn't expect the already existing state. - warn!("Previously finalized, exiting"); + warn!( + target: LOG_CLIENT_RECOVERY, + "Previously finalized, exiting" + ); return Ok(()); } let current_session_count = client_ctx.global_api().session_count().await?; diff --git a/fedimint-client/src/oplog.rs b/fedimint-client/src/oplog.rs index 4d9d19e68ab..be41c610e73 100644 --- a/fedimint-client/src/oplog.rs +++ b/fedimint-client/src/oplog.rs @@ -10,6 +10,7 @@ use fedimint_core::module::registry::ModuleDecoderRegistry; use fedimint_core::task::{MaybeSend, MaybeSync}; use fedimint_core::time::now; use fedimint_core::util::BoxStream; +use fedimint_logging::LOG_CLIENT; use futures::{stream, Stream, StreamExt}; use serde::de::DeserializeOwned; use serde::{Deserialize, Serialize}; @@ -150,7 +151,10 @@ impl OperationLog { outcome: &(impl Serialize + Debug), ) { if let Err(e) = Self::set_operation_outcome(db, operation_id, outcome).await { - warn!("Error setting operation outcome: {e}"); + warn!( + target: LOG_CLIENT, + "Error setting operation outcome: {e}" + ); } } } @@ -331,7 +335,10 @@ where } let Some(last_update) = last_update else { - error!("Stream ended without any updates, this should not happen!"); + error!( + target: LOG_CLIENT, + "Stream ended without any updates, this should not happen!" + ); return; }; diff --git a/fedimint-client/src/sm/executor.rs b/fedimint-client/src/sm/executor.rs index 891863a057a..a89f5fea351 100644 --- a/fedimint-client/src/sm/executor.rs +++ b/fedimint-client/src/sm/executor.rs @@ -104,7 +104,7 @@ impl ExecutorState { // Replace the previous state, undoing the `mem::replace` above. *self = previous_state; - debug!("Executor already started, ignoring start request"); + debug!(target: LOG_CLIENT_REACTOR, "Executor already started, ignoring start request"); None } } @@ -119,14 +119,14 @@ impl ExecutorState { } = previous_state { if shutdown_sender.send(()).is_err() { - warn!("Failed to send shutdown signal to executor, already dead?"); + warn!(target: LOG_CLIENT_REACTOR, "Failed to send shutdown signal to executor, already dead?"); } Some(()) } else { // Replace the previous state, undoing the `mem::replace` above. *self = previous_state; - debug!("Executor not running, ignoring stop request"); + debug!(target: LOG_CLIENT_REACTOR, "Executor not running, ignoring stop request"); None } } @@ -361,20 +361,29 @@ impl Executor { let task_group_shutdown_rx = task_handle.make_shutdown_rx(); select! { () = task_group_shutdown_rx => { - debug!("Shutting down state machine executor runner due to task group shutdown signal"); + debug!( + target: LOG_CLIENT_REACTOR, + "Shutting down state machine executor runner due to task group shutdown signal" + ); }, shutdown_happened_sender = shutdown_receiver => { match shutdown_happened_sender { Ok(()) => { - debug!("Shutting down state machine executor runner due to explicit shutdown signal"); + debug!( + target: LOG_CLIENT_REACTOR, + "Shutting down state machine executor runner due to explicit shutdown signal" + ); }, Err(_) => { - warn!("Shutting down state machine executor runner because the shutdown signal channel was closed (the executor object was dropped)"); + warn!( + target: LOG_CLIENT_REACTOR, + "Shutting down state machine executor runner because the shutdown signal channel was closed (the executor object was dropped)" + ); } } }, () = executor_runner => { - error!("State machine executor runner exited unexpectedly!"); + error!(target: LOG_CLIENT_REACTOR, "State machine executor runner exited unexpectedly!"); }, }; }); @@ -429,6 +438,7 @@ impl ExecutorInner { .await { warn!( + target: LOG_CLIENT_REACTOR, %err, "An unexpected error occurred during a state transition" ); @@ -473,7 +483,10 @@ impl ExecutorInner { // In certain cases a terminal (no transitions) state could get here due to // module bug. Inactivate it to prevent accumulation of such states. // See [`Self::add_state_machines_dbtx`]. - warn!(module_id = module_instance, "A terminal state where only active states are expected. Please report this bug upstream."); + warn!( + target: LOG_CLIENT_REACTOR, + module_id = module_instance, "A terminal state where only active states are expected. Please report this bug upstream." + ); self.db .autocommit::<_, _, anyhow::Error>( |dbtx, _| { @@ -878,6 +891,7 @@ impl ExecutorBuilder { }); debug!( + target: LOG_CLIENT_REACTOR, instances = ?inner.module_contexts.keys().copied().collect::>(), "Initialized state machine executor with module instances" ); @@ -1250,6 +1264,7 @@ mod tests { use fedimint_core::module::registry::ModuleDecoderRegistry; use fedimint_core::runtime; use fedimint_core::task::TaskGroup; + use fedimint_logging::LOG_CLIENT_REACTOR; use tokio::sync::broadcast::Sender; use tracing::{info, trace}; @@ -1379,7 +1394,10 @@ mod tests { executor_builder.build(db.clone(), Notifier::new(db.clone()), TaskGroup::new()); executor.start_executor(Arc::new(|_, _| DynGlobalClientContext::new_fake())); - info!("Initialized test executor"); + info!( + target: LOG_CLIENT_REACTOR, + "Initialized test executor" + ); (executor, broadcast, db) } diff --git a/fedimint-client/src/sm/notifier.rs b/fedimint-client/src/sm/notifier.rs index 375e7a67722..abd47432775 100644 --- a/fedimint-client/src/sm/notifier.rs +++ b/fedimint-client/src/sm/notifier.rs @@ -5,6 +5,7 @@ use fedimint_core::core::{ModuleInstanceId, OperationId}; use fedimint_core::db::{Database, IDatabaseTransactionOpsCoreTyped}; use fedimint_core::util::broadcaststream::BroadcastStream; use fedimint_core::util::BoxStream; +use fedimint_logging::LOG_CLIENT; use futures::StreamExt; use tracing::{debug, error, trace}; @@ -207,7 +208,7 @@ where BroadcastStream::new(self.broadcast.subscribe()) .take_while(|res| { let cont = if let Err(err) = res { - error!(?err, "ModuleNotifier stream stopped on error"); + error!(target: LOG_CLIENT, ?err, "ModuleNotifier stream stopped on error"); false } else { true