From 205216bc7f9e4df932d38cddeb69673e104fe9bc Mon Sep 17 00:00:00 2001 From: Jason Larabie Date: Fri, 31 Jul 2026 11:24:06 -0700 Subject: [PATCH 1/2] Audit of warn! and error! --- crates/client-api/src/routes/database.rs | 28 +++++++++++++------ crates/client-api/src/routes/energy.rs | 4 +-- crates/client-api/src/routes/subscribe.rs | 4 +-- crates/commitlog/src/commitlog.rs | 4 +-- crates/commitlog/src/stream/writer.rs | 6 ++-- crates/core/src/client/message_handlers_v1.rs | 2 +- crates/core/src/client/message_handlers_v2.rs | 2 +- crates/core/src/host/disk_storage.rs | 2 +- crates/core/src/host/module_host.rs | 16 +++++------ crates/core/src/host/scheduler.rs | 2 +- crates/core/src/host/v8/mod.rs | 16 +++++------ crates/core/src/host/v8/syscall/common.rs | 4 +-- crates/core/src/replica_context.rs | 4 +-- .../subscription/module_subscription_actor.rs | 4 +-- .../module_subscription_manager.rs | 6 ++-- crates/core/src/util/jobs.rs | 8 +++--- crates/core/src/util/mod.rs | 2 +- crates/core/src/worker_metrics/mod.rs | 2 +- .../src/locking_tx_datastore/mut_tx.rs | 12 ++++---- crates/durability/src/imp/local.rs | 2 +- crates/pg/src/pg_server.rs | 4 +-- crates/snapshot/src/lib.rs | 4 +-- crates/standalone/src/subcommands/start.rs | 2 +- 23 files changed, 77 insertions(+), 63 deletions(-) diff --git a/crates/client-api/src/routes/database.rs b/crates/client-api/src/routes/database.rs index 8c13f3975c2..52eeff737b8 100644 --- a/crates/client-api/src/routes/database.rs +++ b/crates/client-api/src/routes/database.rs @@ -119,20 +119,32 @@ pub(crate) fn map_reducer_error(e: ReducerCallError, reducer: &str) -> (StatusCo } fn map_procedure_error(e: ProcedureCallError, procedure: &str) -> (StatusCode, String) { - let status_code = match e { + let status_code = match &e { ProcedureCallError::Args(_) => { + // TODO: Remove this host log once the error is logged to the guest log instead. log::debug!("Attempt to call procedure {procedure} with invalid arguments"); StatusCode::BAD_REQUEST } - ProcedureCallError::NoSuchModule(_) => StatusCode::NOT_FOUND, + ProcedureCallError::NoSuchModule(_) => { + log::debug!("Attempt to call procedure {procedure} on a module that is not available"); + StatusCode::NOT_FOUND + } ProcedureCallError::NoSuchProcedure => { + // TODO: Remove this host log once the error is logged to the guest log instead. log::debug!("Attempt to call non-existent procedure OR reducer {procedure}"); StatusCode::NOT_FOUND } - ProcedureCallError::OutOfEnergy => StatusCode::PAYMENT_REQUIRED, - ProcedureCallError::InternalError(_) => StatusCode::INTERNAL_SERVER_ERROR, + ProcedureCallError::OutOfEnergy => { + // TODO: Remove this host log once the error is logged to the guest log instead. + log::info!("Procedure {procedure} could not run because the module is out of energy"); + StatusCode::PAYMENT_REQUIRED + } + ProcedureCallError::InternalError(_) => { + // TODO: May need to split this from module errors vs host errors + log::warn!("Internal error while invoking procedure {procedure}: {e:#}"); + StatusCode::INTERNAL_SERVER_ERROR + } }; - log::error!("Error while invoking procedure {e:#}"); (status_code, format!("{:#}", anyhow::anyhow!(e))) } @@ -422,7 +434,7 @@ fn reducer_outcome_response( (StatusCode::from_u16(530).unwrap(), *errmsg) } ReducerOutcome::BudgetExceeded => { - log::warn!("Node's energy budget exceeded for identity: {owner_identity} while executing {reducer}"); + log::info!("Node's energy budget exceeded for identity: {owner_identity} while executing {reducer}"); (StatusCode::PAYMENT_REQUIRED, "Module energy budget exhausted.".into()) } } @@ -468,7 +480,7 @@ pub(crate) async fn find_leader_and_database( let _database = worker_ctx_find_database(&worker_ctx, &db_identity) .await? .ok_or_else(|| { - log::error!("Could not find database: {}", db_identity.to_hex()); + log::debug!("Could not find database: {}", db_identity.to_hex()); NO_SUCH_DATABASE })?; diff --git a/crates/client-api/src/routes/energy.rs b/crates/client-api/src/routes/energy.rs index a554c418ad9..205ec068c4d 100644 --- a/crates/client-api/src/routes/energy.rs +++ b/crates/client-api/src/routes/energy.rs @@ -44,7 +44,7 @@ pub async fn add_energy( ) -> axum::response::Result { // Nb.: Negative amount withdraws let amount = amount.map(|s| s.parse::()).transpose().map_err(|e| { - log::error!("Failed to parse amount: {e:?}"); + log::debug!("Failed to parse amount: {e:?}"); StatusCode::BAD_REQUEST })?; @@ -102,7 +102,7 @@ pub async fn set_energy_balance( .map(|balance| balance.parse::()) .transpose() .map_err(|err| { - log::error!("Failed to parse balance: {err:?}"); + log::debug!("Failed to parse balance: {err:?}"); StatusCode::BAD_REQUEST })? .unwrap_or(0); diff --git a/crates/client-api/src/routes/subscribe.rs b/crates/client-api/src/routes/subscribe.rs index df1aa15d21d..3b221a3b712 100644 --- a/crates/client-api/src/routes/subscribe.rs +++ b/crates/client-api/src/routes/subscribe.rs @@ -240,7 +240,7 @@ where Ok(ws) => ws, Err(err) => { record_client_rejection(db_identity, ClientRejectCause::WebsocketUpgradeError); - log::error!("websocket: WebSocket init error: {err}"); + log::warn!("websocket: WebSocket init error: {err}"); return; } }; @@ -1001,7 +1001,7 @@ fn ws_recv_queue( reason: Utf8Bytes::from_static("too many requests"), }); let on_message_after_close = move |client_id| { - log::warn!("client {client_id} sent message after close or error"); + log::debug!("client {client_id} sent message after close or error"); }; let max_incoming_queue_length = state.config.incoming_queue_length.get(); diff --git a/crates/commitlog/src/commitlog.rs b/crates/commitlog/src/commitlog.rs index 9082000dcfd..77ec4a7a448 100644 --- a/crates/commitlog/src/commitlog.rs +++ b/crates/commitlog/src/commitlog.rs @@ -880,7 +880,7 @@ impl Commits { // Same offset: ignore if duplicate (same crc), else report a "fork". } else if self.last_commit.same_offset_as(&commit) { if !self.last_commit.same_checksum_as(&commit) { - warn!( + error!( "forked: commit={:?} last-error={:?} last-crc={:?}", commit, prev_error, @@ -895,7 +895,7 @@ impl Commits { } // Not the expected offset: report out-of-order. } else if self.last_commit.expected_offset() != &commit.min_tx_offset { - warn!("out-of-order: commit={commit:?} last-error={prev_error:?}"); + error!("out-of-order: commit={commit:?} last-error={prev_error:?}"); return Some(Err(error::Traversal::OutOfOrder { expected_offset: *self.last_commit.expected_offset(), actual_offset: commit.min_tx_offset, diff --git a/crates/commitlog/src/stream/writer.rs b/crates/commitlog/src/stream/writer.rs index b99622b83f4..afc14a15c46 100644 --- a/crates/commitlog/src/stream/writer.rs +++ b/crates/commitlog/src/stream/writer.rs @@ -379,9 +379,9 @@ where if let Some(current_segment) = self.current_segment.take() { trace!("closing current segment on writer drop"); tokio::spawn( - current_segment - .close() - .inspect_err(|e| warn!("error closing segment on drop: {e}")), + current_segment.close().inspect_err(|e| { + error!("failed to flush commitlog segment while closing dropped stream writer: {e}") + }), ); } } diff --git a/crates/core/src/client/message_handlers_v1.rs b/crates/core/src/client/message_handlers_v1.rs index 60d8eafdb28..a93478dbe23 100644 --- a/crates/core/src/client/message_handlers_v1.rs +++ b/crates/core/src/client/message_handlers_v1.rs @@ -92,7 +92,7 @@ pub async fn handle(client: &ClientConnection, message: DataMessage, timer: Inst }) => { let res = client.call_procedure(procedure, args, request_id, timer).await; if let Err(e) = res { - log::warn!("Procedure call failed: {e:#}"); + log::warn!("Failed to send procedure response to client: {e:#}"); } // `ClientConnection::call_procedure` handles sending the error message to the client if the call fails, // so we don't need to return an `Err` here. diff --git a/crates/core/src/client/message_handlers_v2.rs b/crates/core/src/client/message_handlers_v2.rs index d228fda9fcd..5bef4da58ac 100644 --- a/crates/core/src/client/message_handlers_v2.rs +++ b/crates/core/src/client/message_handlers_v2.rs @@ -81,7 +81,7 @@ pub(super) async fn handle_decoded_message( .call_procedure_v2(procedure, args, request_id, timer, flags) .await; if let Err(e) = res { - log::warn!("Procedure call failed: {e:#}"); + log::warn!("Failed to send procedure response to client: {e:#}"); } Ok(()) } diff --git a/crates/core/src/host/disk_storage.rs b/crates/core/src/host/disk_storage.rs index 3c55472aa16..32baaeae272 100644 --- a/crates/core/src/host/disk_storage.rs +++ b/crates/core/src/host/disk_storage.rs @@ -36,7 +36,7 @@ impl DiskStorage { if actual_hash == *key { Ok(Some(bytes.into())) } else { - log::warn!("hash mismatch: {actual_hash} stored at {key}"); + log::error!("hash mismatch: {actual_hash} stored at {key}"); if let Err(e) = self.prune(key).await { log::warn!("prune error: {e}"); } diff --git a/crates/core/src/host/module_host.rs b/crates/core/src/host/module_host.rs index 35f88434330..320ddad84c1 100644 --- a/crates/core/src/host/module_host.rs +++ b/crates/core/src/host/module_host.rs @@ -434,7 +434,7 @@ impl WasmtimeModuleHost { let label = label.to_owned(); self.executor.enqueue_sync_job(move |state| { scopeguard::defer_on_unwind!({ - log::warn!("wasm main operation {label} panicked"); + log::error!("wasm main operation {label} panicked"); on_panic(); }); @@ -460,7 +460,7 @@ impl WasmtimeModuleHost { let label = label.to_owned(); self.executor.enqueue_async_job(async move || { scopeguard::defer_on_unwind!({ - log::warn!("wasm procedure {label} panicked"); + log::error!("wasm procedure {label} panicked"); on_panic(); }); @@ -1828,7 +1828,7 @@ impl ModuleHost { let timer_guard = self.start_call_timer(label); scopeguard::defer_on_unwind!({ - log::warn!("module operation {label} panicked"); + log::error!("module operation {label} panicked"); (self.on_panic)(); }); @@ -1872,7 +1872,7 @@ impl ModuleHost { let timer_guard = self.start_call_timer(label); scopeguard::defer_on_unwind!({ - log::warn!("pooled operation {label} panicked"); + log::error!("pooled operation {label} panicked"); (self.on_panic)(); }); @@ -1918,7 +1918,7 @@ impl ModuleHost { { let panic_label = label.to_owned(); scopeguard::defer_on_unwind!({ - log::warn!("{panic_kind} {panic_label} panicked"); + log::error!("{panic_kind} {panic_label} panicked"); (self.on_panic)(); }); @@ -2572,7 +2572,7 @@ impl ModuleHost { let guard_procedure_name = procedure_name.clone(); scopeguard::defer_on_unwind!({ - log::warn!("websocket procedure operation {guard_procedure_name} panicked"); + log::error!("websocket procedure operation {guard_procedure_name} panicked"); (self.on_panic)(); }); @@ -2594,7 +2594,7 @@ impl ModuleHost { } } JsProcedureCallCompletion::Panicked | JsProcedureCallCompletion::WorkerExited => { - log::warn!("detached JS procedure worker failed before returning a result"); + log::error!("detached JS procedure worker failed before returning a result"); (module.on_panic)(); } } @@ -3205,7 +3205,7 @@ impl ModuleHost { let label = label.to_owned(); executor.enqueue_sync_job(move |_| { scopeguard::defer_on_unwind!({ - log::warn!("websocket one-off query operation {label} panicked"); + log::error!("websocket one-off query operation {label} panicked"); on_panic(); }); diff --git a/crates/core/src/host/scheduler.rs b/crates/core/src/host/scheduler.rs index a64a39aa9a2..b49a2db923f 100644 --- a/crates/core/src/host/scheduler.rs +++ b/crates/core/src/host/scheduler.rs @@ -401,7 +401,7 @@ impl SchedulerActor { let result = match result { Ok(result) => result, Err(_) => { - log::warn!("scheduled function panicked"); + log::error!("scheduled function panicked"); return; } }; diff --git a/crates/core/src/host/v8/mod.rs b/crates/core/src/host/v8/mod.rs index 52abf373e48..267807280de 100644 --- a/crates/core/src/host/v8/mod.rs +++ b/crates/core/src/host/v8/mod.rs @@ -405,13 +405,13 @@ impl JsInstanceEnv { let leftover_iters = self.iters.len(); if leftover_iters > 0 { - log::warn!("force-clearing {leftover_iters} row iterator(s) left open by JS call `{func_name}`"); + log::debug!("force-clearing {leftover_iters} row iterator(s) left open by JS call `{func_name}`"); self.iters.clear(); } let leftover_timing_spans = self.timing_spans.len(); if leftover_timing_spans > 0 { - log::warn!("force-clearing {leftover_timing_spans} timing span(s) left open by JS call `{func_name}`"); + log::debug!("force-clearing {leftover_timing_spans} timing span(s) left open by JS call `{func_name}`"); self.timing_spans.clear(); } @@ -890,13 +890,13 @@ static_assert_size!(CallReducerParams, 192); fn send_worker_reply(ctx: &str, reply_tx: JsReplyTx, value: T) { if reply_tx.send(Ok(value)).is_err() { - log::error!("should have receiver for `{ctx}` response"); + log::warn!("should have receiver for `{ctx}` response"); } } fn send_worker_panic_reply(ctx: &str, reply_tx: JsReplyTx, panic: JsPanicPayload) { if reply_tx.send(Err(panic)).is_err() { - log::error!("should have receiver for `{ctx}` response"); + log::warn!("should have receiver for `{ctx}` response"); } } @@ -950,7 +950,7 @@ fn handle_detached_worker_request( } } Err(_) => { - log::warn!("detached JS worker request `{ctx}` panicked"); + log::error!("detached JS worker request `{ctx}` panicked"); on_panic(); WorkerRequestOutcome::Fatal } @@ -1641,7 +1641,7 @@ where .send(Err(anyhow::anyhow!("JS worker panicked during startup"))) .is_err() { - log::error!("startup result receiver disconnected"); + log::warn!("startup result receiver disconnected"); } } else { log::error!("JS worker panicked while recreating isolate"); @@ -1651,7 +1651,7 @@ where Ok(Err(err)) => { if let Some(result_tx) = startup_result_tx.take() { if result_tx.send(Err(err)).is_err() { - log::error!("startup result receiver disconnected"); + log::warn!("startup result receiver disconnected"); } } else { log::error!("failed to restart JS worker: {err:#}"); @@ -1664,7 +1664,7 @@ where if let Some(result_tx) = startup_result_tx.take() && result_tx.send(Ok(module_common.clone())).is_err() { - log::error!("startup result receiver disconnected"); + log::warn!("startup result receiver disconnected"); return; } diff --git a/crates/core/src/host/v8/syscall/common.rs b/crates/core/src/host/v8/syscall/common.rs index e6e287c545b..130a0867e31 100644 --- a/crates/core/src/host/v8/syscall/common.rs +++ b/crates/core/src/host/v8/syscall/common.rs @@ -466,8 +466,8 @@ pub fn console_log<'scope>( }; let env = get_env(scope).inspect_err(|_| { - tracing::warn!( - "{}:{} {msg}", + tracing::error!( + "`JsInstanceEnv` unavailable while processing guest log at {}:{}: {msg}", filename.as_deref().unwrap_or("unknown"), frame.get_line_number() ); diff --git a/crates/core/src/replica_context.rs b/crates/core/src/replica_context.rs index af54b78ac11..76d040dae17 100644 --- a/crates/core/src/replica_context.rs +++ b/crates/core/src/replica_context.rs @@ -43,7 +43,7 @@ impl ReplicaContext { durability: self .durability_size_on_disk() .inspect_err(|e| { - log::error!( + log::warn!( "database={} replica={}: failed to obtain durability size on disk: {:#}", self.database.database_identity, self.replica_id, @@ -54,7 +54,7 @@ impl ReplicaContext { logs: self .log_file_size() .inspect_err(|e| { - log::error!( + log::warn!( "database={} replica={}: failed to obtain log file size: {:#}", self.database.database_identity, self.replica_id, diff --git a/crates/core/src/subscription/module_subscription_actor.rs b/crates/core/src/subscription/module_subscription_actor.rs index ed364c8bcc8..47886ef4eb4 100644 --- a/crates/core/src/subscription/module_subscription_actor.rs +++ b/crates/core/src/subscription/module_subscription_actor.rs @@ -1714,7 +1714,7 @@ impl ModuleSubscriptions { // TODO(perf): Removing a subscriber is currently O(subscribed_queries). // Instead we should maintain an index to make this O(subscribed_views). if let Err(err) = self.unsubscribe_views(&removed_queries, client_id.identity) { - log::error!( + log::warn!( "failed to unsubscribe views for disconnected client ({}, {}): {err}", client_id.identity, client_id.connection_id @@ -1826,7 +1826,7 @@ impl ModuleSubscriptions { }; for (client_id, query_set_id) in failed_v2_subscriptions { if let Err(err) = subscriptions.remove_subscription_v2(client_id, query_set_id) { - tracing::warn!(?client_id, ?query_set_id, "failed to remove v2 subscription: {err}"); + tracing::debug!(?client_id, ?query_set_id, "failed to remove v2 subscription: {err}"); } } } diff --git a/crates/core/src/subscription/module_subscription_manager.rs b/crates/core/src/subscription/module_subscription_manager.rs index 0fe707a5582..f974e190e4f 100644 --- a/crates/core/src/subscription/module_subscription_manager.rs +++ b/crates/core/src/subscription/module_subscription_manager.rs @@ -1478,7 +1478,8 @@ impl SubscriptionManager { let table_name = plan.subscribed_table_name().clone(); match eval_delta(tx, &mut acc.metrics, plan) { Err(err) => { - tracing::error!( + // TODO: Redirect subscription query errors attributable to user SQL to guest logs. + tracing::warn!( message = "Query errored during tx update", sql = qstate.query.sql, reason = ?err, @@ -1635,7 +1636,8 @@ impl SubscriptionManager { match eval_delta(tx, &mut acc.metrics, plan) { Err(err) => { - tracing::error!( + // TODO: Redirect subscription query errors attributable to user SQL to guest logs. + tracing::warn!( message = "Query errored during tx update", sql = qstate.query.sql, reason = ?err, diff --git a/crates/core/src/util/jobs.rs b/crates/core/src/util/jobs.rs index 9943c505d0c..32cc5ab0002 100644 --- a/crates/core/src/util/jobs.rs +++ b/crates/core/src/util/jobs.rs @@ -375,7 +375,7 @@ impl SingleThreadedExecutor { async move { let result = AssertUnwindSafe(f().instrument(span)).catch_unwind().await; if let Err(Err(_panic)) = tx.send(result) { - tracing::warn!("uncaught panic on `SingleThreadedExecutor`") + tracing::error!("uncaught panic on `SingleThreadedExecutor`") } } .boxed_local() @@ -400,7 +400,7 @@ impl SingleThreadedExecutor { .send(ExecutorJob::Async(Box::new(move || { async move { if AssertUnwindSafe(f().instrument(span)).catch_unwind().await.is_err() { - tracing::warn!("uncaught panic on `SingleThreadedExecutor`") + tracing::error!("uncaught panic on `SingleThreadedExecutor`") } } .boxed_local() @@ -425,7 +425,7 @@ impl SingleThreadedExecutor { f(state) })); if let Err(Err(_panic)) = tx.send(result) { - tracing::warn!("uncaught panic on `SingleThreadedExecutor`") + tracing::error!("uncaught panic on `SingleThreadedExecutor`") } }))) .unwrap_or_else(|_| panic!("job thread exited")); @@ -452,7 +452,7 @@ impl SingleThreadedExecutor { })) .is_err() { - tracing::warn!("uncaught panic on `SingleThreadedExecutor`") + tracing::error!("uncaught panic on `SingleThreadedExecutor`") } }))) .unwrap_or_else(|_| panic!("job thread exited")); diff --git a/crates/core/src/util/mod.rs b/crates/core/src/util/mod.rs index a0894163d51..079579b7dba 100644 --- a/crates/core/src/util/mod.rs +++ b/crates/core/src/util/mod.rs @@ -26,7 +26,7 @@ pub fn spawn_rayon(f: impl FnOnce() -> R + Send + 'static) -> let _entered = span.entered(); let result = std::panic::catch_unwind(std::panic::AssertUnwindSafe(f)); if let Err(Err(_panic)) = tx.send(result) { - tracing::warn!("uncaught panic on threadpool") + tracing::error!("uncaught panic on threadpool") } }); rx.map(|res| res.unwrap().unwrap_or_else(|err| std::panic::resume_unwind(err))) diff --git a/crates/core/src/worker_metrics/mod.rs b/crates/core/src/worker_metrics/mod.rs index 50a5fe7f312..66b29b40b32 100644 --- a/crates/core/src/worker_metrics/mod.rs +++ b/crates/core/src/worker_metrics/mod.rs @@ -747,7 +747,7 @@ pub fn spawn_bsatn_rlb_pool_stats(node_id: String, pool: BsatnRowListBuilderPool // but it is simpler to just skip all the tokio metrics if they aren't set. #[cfg(not(all(target_has_atomic = "64", tokio_unstable)))] pub fn spawn_tokio_stats(node_id: String, _: String, _: tokio::runtime::Handle) { - log::warn!("Skipping tokio metrics for {node_id}, as they are not enabled in this build."); + log::info!("Skipping tokio metrics for {node_id}, as they are not enabled in this build."); } #[cfg(all(target_has_atomic = "64", tokio_unstable))] diff --git a/crates/datastore/src/locking_tx_datastore/mut_tx.rs b/crates/datastore/src/locking_tx_datastore/mut_tx.rs index d230c40c7fe..5253051cd11 100644 --- a/crates/datastore/src/locking_tx_datastore/mut_tx.rs +++ b/crates/datastore/src/locking_tx_datastore/mut_tx.rs @@ -3056,7 +3056,7 @@ impl MutTxId { ) { // This is possible on restart if the database was previously running a version // before this system table was added. - log::error!( + log::warn!( "[{database_identity}]: delete_st_client_credentials: attempting to delete credentials for missing connection id ({connection_id}), error: {e}" ); } @@ -3086,7 +3086,7 @@ impl MutTxId { { Some(ptr) => self.delete(ST_CLIENT_ID, ptr).map(drop)?, _ => { - log::error!( + log::warn!( "[{database_identity}]: delete_st_client: attempting to delete client ({identity}, {connection_id}), but no st_client row for that client is resident" ); } @@ -3785,9 +3785,9 @@ fn unindexed_iter_by_col_range_warn( ) { match table_row_count(tx_state, committed_state, table_id) { // TODO(ux): log these warnings to the module logs rather than host logs. - None => log::error!("iter_by_col_range on unindexed column, but couldn't fetch table `{table_id}`s row count",), + None => log::debug!("iter_by_col_range on unindexed column, but couldn't fetch table `{table_id}`s row count",), Some(num_rows) => too_many_rows_for_scan_do(committed_state, num_rows, table_id, cols, |name, cols| { - log::warn!("iter_by_col_range without index: table {name} has {num_rows} rows; scanning columns {cols:?}",); + log::info!("iter_by_col_range without index: table {name} has {num_rows} rows; scanning columns {cols:?}",); }), } } @@ -3827,9 +3827,9 @@ fn unindexed_iter_by_col_eq_warn( ) { match table_row_count(tx_state, committed_state, table_id) { // TODO(ux): log these warnings to the module logs rather than host logs. - None => log::error!("iter_by_col_eq on unindexed column, but couldn't fetch table `{table_id}`s row count",), + None => log::debug!("iter_by_col_eq on unindexed column, but couldn't fetch table `{table_id}`s row count",), Some(num_rows) => too_many_rows_for_scan_do(committed_state, num_rows, table_id, cols, |name, cols| { - log::warn!("iter_by_col_eq without index: table {name} has {num_rows} rows; scanning columns {cols:?}",); + log::info!("iter_by_col_eq without index: table {name} has {num_rows} rows; scanning columns {cols:?}",); }), } } diff --git a/crates/durability/src/imp/local.rs b/crates/durability/src/imp/local.rs index 4411523da6a..53e0d2a6845 100644 --- a/crates/durability/src/imp/local.rs +++ b/crates/durability/src/imp/local.rs @@ -335,7 +335,7 @@ where clog.flush_and_sync() }) .await - .inspect_err(|e| warn!("error flushing commitlog: {e:#}")) + .inspect_err(|e| log::error!("error flushing commitlog: {e:#}")) .inspect(|maybe_offset| { if let Some(new_offset) = maybe_offset { trace!("synced to offset {new_offset}"); diff --git a/crates/pg/src/pg_server.rs b/crates/pg/src/pg_server.rs index 15170a35866..b1edeb00007 100644 --- a/crates/pg/src/pg_server.rs +++ b/crates/pg/src/pg_server.rs @@ -124,7 +124,7 @@ async fn response(res: axum::response::Result, database: &str) -> Result { let res = err.into_response(); if res.status() == StatusCode::NOT_FOUND { - log::error!("PG: Database not found: {database}"); + log::debug!("PG: Database not found: {database}"); return Err(PgWireError::UserError(Box::new(ErrorInfo::new( "FATAL".to_string(), "3D000".to_string(), @@ -383,7 +383,7 @@ where }); } Err(e) => { - log::error!("PG: Accept error: {e}"); + log::warn!("PG: Accept error: {e}"); } } } diff --git a/crates/snapshot/src/lib.rs b/crates/snapshot/src/lib.rs index b04ee20216f..aa589fab75f 100644 --- a/crates/snapshot/src/lib.rs +++ b/crates/snapshot/src/lib.rs @@ -23,7 +23,7 @@ #![allow(clippy::result_large_err)] -use log::warn; +use log::error; use spacetimedb_data_structures::map::{HashCollectionExt as _, HashMap}; use spacetimedb_durability::TxOffset; use spacetimedb_fs_utils::compression::{ @@ -249,7 +249,7 @@ impl Drop for UnflushedSnapshot { if let Some(inner) = self.inner.take() && let Err(e) = inner.sync_all() { - warn!("failed to sync unflushed snapshot dropped without syncing: {e}"); + error!("failed to sync unflushed snapshot dropped without syncing: {e}"); } } } diff --git a/crates/standalone/src/subcommands/start.rs b/crates/standalone/src/subcommands/start.rs index 8961d55bc42..2a5b1155ec6 100644 --- a/crates/standalone/src/subcommands/start.rs +++ b/crates/standalone/src/subcommands/start.rs @@ -282,7 +282,7 @@ pub async fn exec(args: &ArgMatches, db_cores: JobCores) -> anyhow::Result<()> { } } } else { - log::warn!("PostgreSQL wire protocol server disabled"); + log::info!("PostgreSQL wire protocol server disabled"); axum::serve(tcp, service) .with_graceful_shutdown(async { tokio::signal::ctrl_c().await.expect("failed to install Ctrl+C handler"); From 724a92766eddbdc06bd21f7686dd0b519727efb8 Mon Sep 17 00:00:00 2001 From: Jason Larabie Date: Fri, 31 Jul 2026 13:44:12 -0700 Subject: [PATCH 2/2] Areas of concern for alerts --- crates/client-api/src/lib.rs | 2 ++ crates/client-api/src/routes/subscribe.rs | 1 + crates/core/src/auth/token_validation.rs | 2 ++ crates/core/src/host/module_host.rs | 1 + crates/core/src/host/scheduler.rs | 2 ++ crates/core/src/host/wasm_common/module_host_actor.rs | 2 ++ crates/durability/src/imp/local.rs | 1 + crates/engine/src/relational_db.rs | 1 + crates/engine/src/snapshot.rs | 1 + crates/pg/src/pg_server.rs | 3 +++ 10 files changed, 16 insertions(+) diff --git a/crates/client-api/src/lib.rs b/crates/client-api/src/lib.rs index 7fd6f238128..a032100563f 100644 --- a/crates/client-api/src/lib.rs +++ b/crates/client-api/src/lib.rs @@ -164,6 +164,7 @@ impl Host { ) .await .map_err(|e| { + // TODO: Review log level after user SQL errors can be distinguished from internal database failures. log::warn!("{e}"); (StatusCode::BAD_REQUEST, e.to_string()) })?; @@ -638,6 +639,7 @@ impl Authorization for Arc { } } +// TODO: Review each caller and split this helper by the appropriate log severity. pub fn log_and_500(e: impl std::fmt::Display) -> ErrorResponse { log::error!("internal error: {e:#}"); (StatusCode::INTERNAL_SERVER_ERROR, format!("{e:#}")).into() diff --git a/crates/client-api/src/routes/subscribe.rs b/crates/client-api/src/routes/subscribe.rs index 3b221a3b712..2030fc7d564 100644 --- a/crates/client-api/src/routes/subscribe.rs +++ b/crates/client-api/src/routes/subscribe.rs @@ -855,6 +855,7 @@ async fn ws_recv_task( if ws_version == WsVersion::V1 && let MessageHandleError::Execution(err) = e { + // TODO: Review log level after guest/client execution errors can be distinguished from internal failures. log::error!("{err:#}"); // If the send task has exited, also exit this recv task. if unordered_tx.send(err.into()).is_err() { diff --git a/crates/core/src/auth/token_validation.rs b/crates/core/src/auth/token_validation.rs index c38d732882d..c813efc97f5 100644 --- a/crates/core/src/auth/token_validation.rs +++ b/crates/core/src/auth/token_validation.rs @@ -213,6 +213,7 @@ impl async_cache::Fetcher> for KeyFetcher { // TODO: We should probably add debouncing to avoid spamming the logs. // Alternatively we could add a backoff before retrying. if let Err(e) = &key_or_error { + // TODO: Review log level after configured issuers can be distinguished from arbitrary token issuers. log::warn!("Error fetching public key for issuer {raw_issuer}: {e:?}"); } let keys = key_or_error?; @@ -265,6 +266,7 @@ impl TokenValidator for OidcTokenValidator { // TODO: We should probably add debouncing to avoid spamming the logs. // Alternatively we could add a backoff before retrying. if let Err(e) = &key_or_error { + // TODO: Review log level after configured issuers can be distinguished from arbitrary token issuers. log::warn!("Error fetching public key for issuer {raw_issuer}: {e:?}"); } let keys = key_or_error?; diff --git a/crates/core/src/host/module_host.rs b/crates/core/src/host/module_host.rs index 320ddad84c1..835675dfb60 100644 --- a/crates/core/src/host/module_host.rs +++ b/crates/core/src/host/module_host.rs @@ -1964,6 +1964,7 @@ impl ModuleHost { let result = inst.call_view(cmd); ModuleHost::record_view_command_round_trip(&info, metric); if let Err(err) = result { + // TODO: Review log level after guest view errors can be distinguished from internal database failures. log::warn!("websocket view operation failed: {err:#}"); } }, diff --git a/crates/core/src/host/scheduler.rs b/crates/core/src/host/scheduler.rs index b49a2db923f..04b9fd92cb3 100644 --- a/crates/core/src/host/scheduler.rs +++ b/crates/core/src/host/scheduler.rs @@ -516,6 +516,7 @@ fn prepare_scheduled_procedure_call( Ok(Some(params)) => params, Err(err) => { // All we can do here is log an error. + // TODO: Review log level after stale/invalid schedules can be distinguished from internal failures. log::error!("could not determine scheduled procedure or its parameters: {err:#}"); let reschedule = id.and_then(|id| { let reschedule_from = (Timestamp::now(), Instant::now()); @@ -552,6 +553,7 @@ fn call_scheduled_reducer_until_done( Ok(Some(params)) => params, Err(err) => { // All we can do here is log an error. + // TODO: Review log level after stale/invalid schedules can be distinguished from internal failures. log::error!("could not determine scheduled reducer or its parameters: {err:#}"); let reschedule = id.and_then(|id| { let reschedule_from = (Timestamp::now(), Instant::now()); diff --git a/crates/core/src/host/wasm_common/module_host_actor.rs b/crates/core/src/host/wasm_common/module_host_actor.rs index ae1849582ad..965bb52fa7f 100644 --- a/crates/core/src/host/wasm_common/module_host_actor.rs +++ b/crates/core/src/host/wasm_common/module_host_actor.rs @@ -679,6 +679,7 @@ impl InstanceCommon { match res { Err(e) => { + // TODO: Review log level after migration/user errors can be distinguished from internal database failures. log::warn!("Database update failed: {} @ {}", e, stdb.database_identity()); system_logger.warn(&format!("Database update failed: {e}")); let (_, tx_metrics, reducer) = stdb.rollback_mut_tx(tx); @@ -1399,6 +1400,7 @@ impl InstanceCommon { match outcome { Ok(outcome) => outcome, Err(err) => { + // TODO: Review log level after guest view errors can be distinguished from materialization failures. log::error!("Error materializing view `{view_name}`: {err:?}"); ViewOutcome::Failed(format!("Error materializing view `{view_name}`: {err}")) } diff --git a/crates/durability/src/imp/local.rs b/crates/durability/src/imp/local.rs index 53e0d2a6845..0fef5f76466 100644 --- a/crates/durability/src/imp/local.rs +++ b/crates/durability/src/imp/local.rs @@ -385,6 +385,7 @@ where { // Will print "durability actor: task was cancelled" // or "durability actor: task panicked [...]" + // TODO: Review log level after JoinError exposes panic versus cancellation. warn!("durability actor: {e}"); } // Don't abort if the actor completed. diff --git a/crates/engine/src/relational_db.rs b/crates/engine/src/relational_db.rs index 7edb9fe20fc..a1eee3c3aaf 100644 --- a/crates/engine/src/relational_db.rs +++ b/crates/engine/src/relational_db.rs @@ -1171,6 +1171,7 @@ pub fn spawn_view_cleanup_loop( result.backlog } Err(e) => { + // TODO: Review log level after retryable cleanup errors can be distinguished from internal database failures. log::error!( "[{}] DATABASE: failed to clear expired views: {}", db.database_identity(), diff --git a/crates/engine/src/snapshot.rs b/crates/engine/src/snapshot.rs index 11b08727b7d..08d57b2850c 100644 --- a/crates/engine/src/snapshot.rs +++ b/crates/engine/src/snapshot.rs @@ -205,6 +205,7 @@ impl SnapshotWorkerActor { let res = self .maybe_take_snapshot(database_state.as_ref()) .await + // TODO: Review log level after lifecycle errors can be distinguished from snapshot creation failures. .inspect_err(|e| warn!("database={database_identity} SnapshotWorker: {e:#}")); if let Ok(snapshot_offset) = res { self.maybe_compress_snapshots(snapshot_offset).await; diff --git a/crates/pg/src/pg_server.rs b/crates/pg/src/pg_server.rs index b1edeb00007..c8cf484dc41 100644 --- a/crates/pg/src/pg_server.rs +++ b/crates/pg/src/pg_server.rs @@ -136,6 +136,7 @@ async fn response(res: axum::response::Result, database: &str) -> Result claims, Err(err) => { + // TODO: Do not log the supplied password/token; then classify credential errors separately from provider failures. log::error!( "PG: Authentication failed for identity `{}` on database {database}: {err}", pwd.password @@ -378,6 +380,7 @@ where let factory_ref = factory.clone(); tokio::spawn(async move { process_socket(stream, None, factory_ref).await.inspect_err(|err|{ + // TODO: Review log level after client/disconnect errors can be distinguished from internal failures. log::error!("PG: Error processing socket: {err:?}"); }) });