Audit of warn! and error!

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<T: Authorization> Authorization for Arc<T> {
     }
 }
 
+// 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()

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::info!("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<S: ControlStateDelegate + NodeDeleg
     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
         })?;
 
@@ -1528,7 +1540,7 @@ async fn get_timestamp<S: ControlStateDelegate>(
     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
         })?;
 

crates/client-api/src/routes/energy.rs

@@ -44,7 +44,7 @@ pub async fn add_energy<S: ControlStateDelegate>(
 ) -> axum::response::Result<impl IntoResponse> {
     // Nb.: Negative amount withdraws
     let amount = amount.map(|s| s.parse::<u128>()).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<S: ControlStateDelegate>(
         .map(|balance| balance.parse::<i128>())
         .transpose()
         .map_err(|err| {
-            log::error!("Failed to parse balance: {err:?}");
+            log::debug!("Failed to parse balance: {err:?}");
             StatusCode::BAD_REQUEST
         })?
         .unwrap_or(0);

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;
             }
         };
@@ -855,7 +855,8 @@ async fn ws_recv_task<MessageHandler>(
             if ws_version == WsVersion::V1
                 && let MessageHandleError::Execution(err) = e
             {
-                log::error!("{err:#}");
+                // TODO: Review log level after guest/client execution errors can be distinguished from internal failures.
+                log::warn!("{err:#}");
                 // If the send task has exited, also exit this recv task.
                 if unordered_tx.send(err.into()).is_err() {
                     break;

crates/commitlog/src/commitlog.rs

@@ -880,7 +880,7 @@ impl<R: Repo> Commits<R> {
                     // 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<R: Repo> Commits<R> {
                         }
                     // 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,

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}")
+                }),
             );
         }
     }

crates/core/src/auth/token_validation.rs

@@ -213,6 +213,7 @@ impl async_cache::Fetcher<Arc<JwksValidator>> 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?;

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.

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(())
         }

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}");
                     }

crates/core/src/host/module_host.rs

@@ -480,7 +480,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();
             });
 
@@ -506,7 +506,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();
             });
 
@@ -1896,7 +1896,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)();
         });
 
@@ -1940,7 +1940,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)();
         });
 
@@ -1986,7 +1986,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)();
         });
 
@@ -2032,6 +2032,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:#}");
                         }
                     },
@@ -2642,7 +2643,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)();
         });
 
@@ -2664,7 +2665,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)();
                         }
                     }
@@ -3292,7 +3293,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();
                     });
 

crates/core/src/host/scheduler.rs

@@ -404,7 +404,7 @@ impl SchedulerActor {
         let result = match result {
             Ok(result) => result,
             Err(_) => {
-                log::warn!("scheduled function panicked");
+                log::error!("scheduled function panicked");
                 return;
             }
         };
@@ -529,6 +529,10 @@ fn prepare_scheduled_procedure_call(
         Ok(Some(params)) => params,
         Err(err) => {
             // All we can do here is log an error.
+            // This can fail because the schedule row could not be read from the datastore,
+            // the row could not be BSATN-encoded, the scheduled function no longer exists,
+            // or its arguments do not match the current function definition.
+            // TODO: Use a typed error to log internal failures at error! and stale/invalid schedules at warn! or lower.
             log::error!("could not determine scheduled procedure or its parameters: {err:#}");
             let reschedule = id.and_then(|id| {
                 let reschedule_from = (Timestamp::now(), Instant::now());
@@ -572,6 +576,10 @@ fn call_scheduled_reducer_until_done(
         Ok(Some(params)) => params,
         Err(err) => {
             // All we can do here is log an error.
+            // This can fail because the schedule row could not be read from the datastore,
+            // the row could not be BSATN-encoded, the scheduled function no longer exists,
+            // or its arguments do not match the current function definition.
+            // TODO: Use a typed error to log internal failures at error! and stale/invalid schedules at warn! or lower.
             log::error!("could not determine scheduled reducer or its parameters: {err:#}");
             let reschedule = id.and_then(|id| {
                 let reschedule_from = (Timestamp::now(), Instant::now());

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<T>(ctx: &str, reply_tx: JsReplyTx<T>, 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<T>(ctx: &str, reply_tx: JsReplyTx<T>, 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
         }
@@ -1650,7 +1650,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");
@@ -1660,7 +1660,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:#}");
@@ -1673,7 +1673,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;
                         }
 

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()
         );

crates/core/src/host/wasm_common/module_host_actor.rs

@@ -682,6 +682,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);
@@ -1392,7 +1393,8 @@ impl InstanceCommon {
                 match outcome {
                     Ok(outcome) => outcome,
                     Err(err) => {
-                        log::error!("Error materializing view `{view_name}`: {err:?}");
+                        // TODO: Review log level after guest view errors can be distinguished from materialization failures.
+                        log::warn!("Error materializing view `{view_name}`: {err:?}");
                         ViewOutcome::Failed(format!("Error materializing view `{view_name}`: {err}"))
                     }
                 }