diff --git a/AGENTS.md b/AGENTS.md index 17c6e2d57..ac2aab5e5 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -95,6 +95,8 @@ If changes are needed in these files, that must happen in the separate Positron - Use fully qualified result types (`anyhow::Result`) instead of importing them. +- You can log `Result::Err` by using the `.log_err()` method from the extension trait `stdext::ResultExt`. Add some `.context()` if that would be helpful, but never do it for errors that are quite unexpected, such as from `.send()` to a channel (that would be too verbose). + - When writing tests, prefer simple assertion macros without custom error messages: - Use `assert_eq!(actual, expected);` instead of `assert_eq!(actual, expected, "custom message");` - Use `assert!(condition);` instead of `assert!(condition, "custom message");` diff --git a/Cargo.lock b/Cargo.lock index 3a674c34c..e1fe11dde 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -272,9 +272,9 @@ dependencies = [ [[package]] name = "anyhow" -version = "1.0.80" +version = "1.0.100" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5ad32ce52e4161730f7098c077cd2ed6229b5804ccf99e5366be1ab72a98b4e1" +checksum = "a23eb6b1614318a8071c9b2521f36b424b2c83db5eb3a0fead4a6c0809af6e61" [[package]] name = "ark" @@ -2703,6 +2703,7 @@ checksum = "a2eb9349b6444b326872e140eb1cf5e7c522154d69e7a0ffb0fb81c06b37543f" name = "stdext" version = "0.1.0" dependencies = [ + "anyhow", "log", ] diff --git a/crates/amalthea/src/comm/comm_manager.rs b/crates/amalthea/src/comm/comm_manager.rs index 089f45f28..cd6d6314f 100644 --- a/crates/amalthea/src/comm/comm_manager.rs +++ b/crates/amalthea/src/comm/comm_manager.rs @@ -12,7 +12,7 @@ use crossbeam::channel::Select; use crossbeam::channel::Sender; use log::info; use log::warn; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use stdext::spawn; use crate::comm::comm_channel::CommMsg; @@ -161,9 +161,7 @@ impl CommManager { if let Some(index) = index { // Notify the comm that it's been closed let comm = self.open_comms.get(index).unwrap(); - comm.incoming_tx - .send(CommMsg::Close) - .or_log_error("Failed to send comm_close to comm."); + comm.incoming_tx.send(CommMsg::Close).log_err(); // Remove it from our list of open comms self.open_comms.remove(index); diff --git a/crates/amalthea/src/socket/shell.rs b/crates/amalthea/src/socket/shell.rs index 37aa2459d..f2302543a 100644 --- a/crates/amalthea/src/socket/shell.rs +++ b/crates/amalthea/src/socket/shell.rs @@ -14,7 +14,7 @@ use std::sync::Mutex; use crossbeam::channel::Receiver; use crossbeam::channel::Sender; use futures::executor::block_on; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use crate::comm::comm_channel::comm_rpc_message; use crate::comm::comm_channel::Comm; @@ -429,10 +429,7 @@ impl Shell { // comm has been opened self.comm_manager_tx .send(CommManagerEvent::Opened(comm_socket.clone(), comm_data)) - .or_log_warning(&format!( - "Failed to send '{}' comm open notification to listener thread", - comm_socket.comm_name - )); + .log_err(); // If the comm wraps a server, send notification once the server is ready to // accept connections. This also sends back the port number to connect on. Failing diff --git a/crates/ark/src/dap/dap.rs b/crates/ark/src/dap/dap.rs index 4b8d54acd..10719f519 100644 --- a/crates/ark/src/dap/dap.rs +++ b/crates/ark/src/dap/dap.rs @@ -15,7 +15,7 @@ use amalthea::comm::server_comm::ServerStartedMessage; use amalthea::language::server_handler::ServerHandler; use crossbeam::channel::Sender; use harp::object::RObject; -use stdext::log_error; +use stdext::result::ResultExt; use stdext::spawn; use crate::dap::dap_r_main::FrameInfo; @@ -134,14 +134,15 @@ impl Dap { if self.is_debugging { if let Some(tx) = &self.backend_events_tx { - log_error!(tx.send(DapBackendEvent::Stopped(DapStoppedEvent { preserve_focus }))); + tx.send(DapBackendEvent::Stopped(DapStoppedEvent { preserve_focus })) + .log_err(); } } else { if let Some(tx) = &self.comm_tx { // Ask frontend to connect to the DAP log::trace!("DAP: Sending `start_debug` event"); let msg = amalthea::comm_rpc_message!("start_debug"); - log_error!(tx.send(msg)); + tx.send(msg).log_err(); } self.is_debugging = true; @@ -162,7 +163,7 @@ impl Dap { // terminate the debugging session and disconnect. if let Some(tx) = &self.backend_events_tx { log::trace!("DAP: Sending `stop_debug` event"); - log_error!(tx.send(DapBackendEvent::Terminated)); + tx.send(DapBackendEvent::Terminated).log_err(); } } // else: If not connected to a frontend, the DAP client should diff --git a/crates/ark/src/dap/dap_r_main.rs b/crates/ark/src/dap/dap_r_main.rs index 2943bde85..3b9d96a70 100644 --- a/crates/ark/src/dap/dap_r_main.rs +++ b/crates/ark/src/dap/dap_r_main.rs @@ -27,7 +27,7 @@ use libr::INTSXP; use libr::SET_INTEGER_ELT; use libr::SEXP; use libr::VECTOR_ELT; -use stdext::log_error; +use stdext::result::ResultExt; use crate::dap::dap::DapBackendEvent; use crate::dap::Dap; @@ -180,7 +180,7 @@ impl RMainDap { pub fn send_dap(&self, event: DapBackendEvent) { let dap = self.dap.lock().unwrap(); if let Some(tx) = &dap.backend_events_tx { - log_error!(tx.send(event)); + tx.send(event).log_err(); } } diff --git a/crates/ark/src/dap/dap_server.rs b/crates/ark/src/dap/dap_server.rs index 788cf0c33..f5153f082 100644 --- a/crates/ark/src/dap/dap_server.rs +++ b/crates/ark/src/dap/dap_server.rs @@ -28,7 +28,7 @@ use dap::requests::*; use dap::responses::*; use dap::server::ServerOutput; use dap::types::*; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use stdext::spawn; use super::dap::Dap; @@ -73,7 +73,7 @@ pub fn start_dap( // Send the port back to `Shell` and eventually out to the frontend so it can connect server_started_tx .send(ServerStartedMessage::new(port)) - .or_log_error("DAP: Can't send init notification"); + .log_err(); loop { log::trace!("DAP: Waiting for client"); diff --git a/crates/ark/src/data_explorer/r_data_explorer.rs b/crates/ark/src/data_explorer/r_data_explorer.rs index 251d99f65..d0f1db1b5 100644 --- a/crates/ark/src/data_explorer/r_data_explorer.rs +++ b/crates/ark/src/data_explorer/r_data_explorer.rs @@ -66,6 +66,7 @@ use amalthea::socket::comm::CommInitiator; use amalthea::socket::comm::CommSocket; use anyhow::anyhow; use anyhow::bail; +use anyhow::Context; use crossbeam::channel::unbounded; use crossbeam::channel::Sender; use crossbeam::select; @@ -84,7 +85,7 @@ use libr::*; use serde::Deserialize; use serde::Serialize; use stdext::local; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use stdext::spawn; use stdext::unwrap; use tracing::Instrument; @@ -236,7 +237,7 @@ impl RDataExplorer { // the schema comm_manager_tx .send(CommManagerEvent::Closed(comm.comm_id)) - .or_log_error("Error sending comm closed event") + .log_err(); }, } }); @@ -680,7 +681,8 @@ impl RDataExplorer { handle_columns_profiles_requests(params, comm) .instrument(tracing::info_span!("get_columns_profile", ns = id)) .await - .or_log_error("Unable to handle get_columns_profile"); + .context("Unable to handle get_columns_profile") + .log_err(); }); } diff --git a/crates/ark/src/interface.rs b/crates/ark/src/interface.rs index 7c6f7e3d8..dcc26f0fc 100644 --- a/crates/ark/src/interface.rs +++ b/crates/ark/src/interface.rs @@ -87,7 +87,7 @@ use libr::SEXP; use once_cell::sync::Lazy; use regex::Regex; use serde_json::json; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use stdext::*; use tokio::sync::mpsc::UnboundedReceiver as AsyncUnboundedReceiver; use uuid::Uuid; @@ -440,7 +440,8 @@ impl RMain { // Optionally run a frontend specified R startup script (after harp init) if let Some(file) = &startup_file { harp::source(file) - .or_log_error(&format!("Failed to source startup file '{file}' due to")); + .context(format!("Failed to source startup file '{file}' due to")) + .log_err(); } // Initialize support functions (after routine registration, after r_task initialization) diff --git a/crates/ark/src/lsp/backend.rs b/crates/ark/src/lsp/backend.rs index 9b418f51d..1974545e2 100644 --- a/crates/ark/src/lsp/backend.rs +++ b/crates/ark/src/lsp/backend.rs @@ -14,9 +14,10 @@ use amalthea::comm::server_comm::ServerStartMessage; use amalthea::comm::server_comm::ServerStartedMessage; use amalthea::comm::ui_comm::ShowMessageParams as UiShowMessageParams; use amalthea::comm::ui_comm::UiFrontendEvent; +use anyhow::Context; use crossbeam::channel::Sender; use serde_json::Value; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use tokio::net::TcpListener; use tokio::runtime::Runtime; use tokio::sync::mpsc::unbounded_channel as tokio_unbounded_channel; @@ -501,7 +502,8 @@ pub fn start_lsp( // Send the port back to `Shell` and eventually out to the frontend so it can connect server_started_tx .send(ServerStartedMessage::new(port)) - .or_log_error("LSP: Can't send server started notification"); + .context("LSP: Can't send server started notification") + .log_err(); log::trace!("LSP: Waiting for client"); let (stream, address) = listener.accept().await.unwrap(); diff --git a/crates/ark/src/plots/graphics_device.rs b/crates/ark/src/plots/graphics_device.rs index ac18acc28..c1ba1b5c0 100644 --- a/crates/ark/src/plots/graphics_device.rs +++ b/crates/ark/src/plots/graphics_device.rs @@ -31,6 +31,7 @@ use amalthea::wire::display_data::DisplayData; use amalthea::wire::update_display_data::TransientValue; use amalthea::wire::update_display_data::UpdateDisplayData; use anyhow::anyhow; +use anyhow::Context; use base64::engine::general_purpose; use base64::Engine; use crossbeam::channel::Select; @@ -43,7 +44,7 @@ use libr::pGEcontext; use libr::R_NilValue; use libr::SEXP; use serde_json::json; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use stdext::unwrap; use tokio::sync::mpsc::UnboundedReceiver as AsyncUnboundedReceiver; use uuid::Uuid; @@ -567,7 +568,7 @@ impl DeviceContext { metadata, transient, })) - .or_log_warning(&format!("Could not publish display data on IOPub.")); + .log_err(); } fn process_update_plot(&self, id: &PlotId) { @@ -620,7 +621,8 @@ impl DeviceContext { socket .outgoing_tx .send(CommMsg::Data(value)) - .or_log_error("Failed to send update message for id {id}."); + .context("Failed to send update message for id {id}.") + .log_err(); } #[tracing::instrument(level = "trace", skip_all, fields(id = %id))] @@ -647,7 +649,7 @@ impl DeviceContext { metadata, transient, })) - .or_log_warning(&format!("Could not publish update display data on IOPub.")); + .log_err(); } fn create_display_data_plot(&self, id: &PlotId) -> Result { diff --git a/crates/ark/src/reticulate.rs b/crates/ark/src/reticulate.rs index 123d2a448..118e40661 100644 --- a/crates/ark/src/reticulate.rs +++ b/crates/ark/src/reticulate.rs @@ -7,13 +7,14 @@ use amalthea::comm::event::CommManagerEvent; use amalthea::comm_rpc_message; use amalthea::socket::comm::CommInitiator; use amalthea::socket::comm::CommSocket; +use anyhow::Context; use crossbeam::channel::Sender; use harp::utils::r_is_null; use harp::RObject; use libr::R_NilValue; use libr::SEXP; use serde_json::json; -use stdext::result::ResultOrLog; +use stdext::result::ResultExt; use stdext::spawn; use stdext::unwrap; use uuid::Uuid; @@ -63,15 +64,13 @@ impl ReticulateService { "reticulate_id": (*RETICULATE_ID).clone(), }), ); - service - .comm_manager_tx - .send(event) - .or_log_error("Reticulate: Could not open comm."); + service.comm_manager_tx.send(event).log_err(); spawn!(format!("ark-reticulate-{}", comm_id), move || { service .handle_messages() - .or_log_error("Reticulate: Error handling messages"); + .context("Reticulate: Error handling messages") + .log_err(); }); Ok(()) @@ -92,10 +91,7 @@ impl ReticulateService { } // before finalizing the thread we make sure to send a close message to the front end - self.comm - .outgoing_tx - .send(CommMsg::Close) - .or_log_error("Reticulate: Could not send close message to the front-end"); + self.comm.outgoing_tx.send(CommMsg::Close).log_err(); // Reset the global soccket before closing log::info!("Reticulate Thread closing {:?}", self.comm.comm_id); diff --git a/crates/stdext/Cargo.toml b/crates/stdext/Cargo.toml index 987c05b7e..5bdc611ea 100644 --- a/crates/stdext/Cargo.toml +++ b/crates/stdext/Cargo.toml @@ -11,6 +11,7 @@ license.workspace = true rust-version.workspace = true [dependencies] +anyhow = "1.0.100" log = "0.4.18" [features] diff --git a/crates/stdext/src/result.rs b/crates/stdext/src/result.rs index b0fb91642..65af19af1 100644 --- a/crates/stdext/src/result.rs +++ b/crates/stdext/src/result.rs @@ -5,59 +5,91 @@ // // -use std::fmt::Display; - -// Since this is a macro, this correctly records call site information. -// TODO: Should we retire the `ResultOrLog` trait? -#[macro_export(local_inner_macros)] -macro_rules! log_error { - ($res:expr) => { - if let Err(err) = $res { - log::error!("{err}"); - } - }; - ($prefix:expr, $res:expr) => { - if let Err(err) = $res { - log::error!("{}: {err}", $prefix); +#[macro_export] +macro_rules! debug_panic { + ( $($fmt_arg:tt)* ) => { + if cfg!(debug_assertions) { + panic!( $($fmt_arg)* ); + } else { + let backtrace = std::backtrace::Backtrace::capture(); + log::error!("{}\n{:?}", format_args!($($fmt_arg)*), backtrace); } }; } -pub trait ResultOrLog { - /// If `self` is an error, log an error, else do nothing and consume self. - fn or_log_error(self, prefix: &str); - - /// If `self` is an error, log a warning, else do nothing and consume self. - fn or_log_warning(self, prefix: &str); +// From https://github.com/zed-industries/zed/blob/a910c594/crates/util/src/util.rs#L554 +pub trait ResultExt { + type Ok; - /// If `self` is an error, log info, else do nothing and consume self. - fn or_log_info(self, prefix: &str); + fn log_err(self) -> Option; + /// Assert that this result should never be an error in development or tests + fn debug_assert_ok(self, reason: &str) -> Self; + fn warn_on_err(self) -> Option; + fn log_with_level(self, level: log::Level) -> Option; + fn anyhow(self) -> anyhow::Result + where + E: Into; } -// Implemented for "empty" results that never contain values, -// but may contain errors -impl ResultOrLog for Result +impl ResultExt for Result where - E: Display, + E: std::fmt::Debug, { - fn or_log_error(self, prefix: &str) { - match self { - Ok(_) => return, - Err(err) => log::error!("{}: {}", prefix, err), - } + type Ok = T; + + #[track_caller] + fn log_err(self) -> Option { + self.log_with_level(log::Level::Error) } - fn or_log_warning(self, prefix: &str) { + #[track_caller] + fn warn_on_err(self) -> Option { + self.log_with_level(log::Level::Warn) + } + + #[track_caller] + fn log_with_level(self, level: log::Level) -> Option { match self { - Ok(_) => return, - Err(err) => log::warn!("{}: {}", prefix, err), + Ok(value) => Some(value), + Err(error) => { + let location = std::panic::Location::caller(); + let file = location.file(); + let line = location.line(); + log::logger().log( + &log::Record::builder() + // Unlike direct calls to `log::error!`, we're propagating an + // error object that typically contains backtrace information. + // The file/line information displayed by log is at the bottom, + // which can be hard to find in case of a long backtrace, so + // we mention these again before the error message to + // make it easier to identify where the log message was + // emitted from. + .args(format_args!("at {file}:{line}: {error:?}")) + .level(level) + .file(Some(file)) + .line(Some(line)) + // Can't get the module path from tracked caller so + // leave it blank + .module_path(None) + .build(), + ); + None + }, } } - fn or_log_info(self, prefix: &str) { - match self { - Ok(_) => return, - Err(err) => log::info!("{}: {}", prefix, err), + #[track_caller] + fn debug_assert_ok(self, reason: &str) -> Self { + if let Err(error) = &self { + debug_panic!("{reason} - {error:?}"); } + self + } + + fn anyhow(self) -> anyhow::Result + where + E: Into, + { + self.map_err(Into::into) } }