diff --git a/src/error.rs b/src/error.rs index 13f6724..178c1f3 100644 --- a/src/error.rs +++ b/src/error.rs @@ -1,6 +1,48 @@ use axum::http::StatusCode; use axum::response::{IntoResponse, Response}; use bytes::Bytes; +use serde::Serialize; + +#[derive(Debug, Clone, Serialize)] +#[serde(rename_all = "snake_case")] +pub enum ScriptErrorType { + Syntax, + Runtime, + Timeout, + MissingHandle, +} + +impl std::fmt::Display for ScriptErrorType { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + ScriptErrorType::Syntax => write!(f, "syntax"), + ScriptErrorType::Runtime => write!(f, "runtime"), + ScriptErrorType::Timeout => write!(f, "timeout"), + ScriptErrorType::MissingHandle => write!(f, "missing_handle"), + } + } +} + +/// Parse a Lua error message to extract a line number. +/// +/// mlua errors look like: +/// - `[string "..."]:42: attempt to index a nil value` +/// - `runtime error: [string "..."]:10: bad argument` +/// +/// Returns `(Some(line), cleaned_message)` or `(None, original_message)`. +pub fn parse_lua_line(raw: &str) -> (Option, String) { + if let Some(bracket_pos) = raw.find("]:") { + let after_bracket = &raw[bracket_pos + 2..]; + if let Some(colon_pos) = after_bracket.find(": ") { + let line_str = &after_bracket[..colon_pos]; + if let Ok(line) = line_str.parse::() { + let message = after_bracket[colon_pos + 2..].to_string(); + return (Some(line), message); + } + } + } + (None, raw.to_string()) +} #[derive(Debug)] pub enum AppError { @@ -13,6 +55,12 @@ pub enum AppError { Internal(String), NotFound(String), PdsError(StatusCode, Bytes), + ScriptError { + error_type: ScriptErrorType, + message: String, + method: String, + line: Option, + }, } impl std::fmt::Display for AppError { @@ -26,6 +74,21 @@ impl std::fmt::Display for AppError { AppError::Internal(msg) => write!(f, "internal error: {msg}"), AppError::NotFound(msg) => write!(f, "not found: {msg}"), AppError::PdsError(status, _) => write!(f, "PDS error: {status}"), + AppError::ScriptError { + error_type, + message, + method, + line, + } => { + if let Some(l) = line { + write!( + f, + "script {error_type} error in {method} at line {l}: {message}" + ) + } else { + write!(f, "script {error_type} error in {method}: {message}") + } + } } } } @@ -47,6 +110,26 @@ impl IntoResponse for AppError { } response } + AppError::ScriptError { + error_type, + message, + method, + line, + } => { + let status = match &error_type { + ScriptErrorType::Timeout => StatusCode::REQUEST_TIMEOUT, + _ => StatusCode::INTERNAL_SERVER_ERROR, + }; + tracing::error!(%method, ?error_type, ?line, "{message}"); + let body = serde_json::json!({ + "error": "script_error", + "errorType": error_type, + "message": message, + "method": method, + "line": line, + }); + (status, axum::Json(body)).into_response() + } other => { let (status, message) = match &other { AppError::Auth(msg) => (StatusCode::UNAUTHORIZED, msg.clone()), @@ -56,13 +139,12 @@ impl IntoResponse for AppError { AppError::Forbidden(msg) => (StatusCode::FORBIDDEN, msg.clone()), AppError::Internal(msg) => { tracing::error!("{msg}"); - ( - StatusCode::INTERNAL_SERVER_ERROR, - "internal server error".into(), - ) + (StatusCode::INTERNAL_SERVER_ERROR, msg.clone()) } AppError::NotFound(msg) => (StatusCode::NOT_FOUND, msg.clone()), - AppError::PdsError(..) | AppError::AuthDpopNonce(..) => unreachable!(), + AppError::PdsError(..) + | AppError::AuthDpopNonce(..) + | AppError::ScriptError { .. } => unreachable!(), }; let body = serde_json::json!({ "error": message }); @@ -101,10 +183,57 @@ mod tests { } #[tokio::test] - async fn internal_error_returns_500_and_hides_detail() { + async fn internal_error_returns_500_with_message() { let (status, body) = response_parts(AppError::Internal("secret details".into())).await; assert_eq!(status, StatusCode::INTERNAL_SERVER_ERROR); - assert_eq!(body["error"], "internal server error"); + assert_eq!(body["error"], "secret details"); + } + + #[tokio::test] + async fn script_error_returns_500_with_structured_body() { + let (status, body) = response_parts(AppError::ScriptError { + error_type: ScriptErrorType::Runtime, + message: "attempt to index a nil value".into(), + method: "games.gamesgamesgamesgames.search".into(), + line: Some(42), + }) + .await; + assert_eq!(status, StatusCode::INTERNAL_SERVER_ERROR); + assert_eq!(body["error"], "script_error"); + assert_eq!(body["errorType"], "runtime"); + assert_eq!(body["message"], "attempt to index a nil value"); + assert_eq!(body["method"], "games.gamesgamesgamesgames.search"); + assert_eq!(body["line"], 42); + } + + #[tokio::test] + async fn script_error_timeout_returns_408() { + let (status, body) = response_parts(AppError::ScriptError { + error_type: ScriptErrorType::Timeout, + message: "script exceeded execution time limit".into(), + method: "test.method".into(), + line: None, + }) + .await; + assert_eq!(status, StatusCode::REQUEST_TIMEOUT); + assert_eq!(body["error"], "script_error"); + assert_eq!(body["errorType"], "timeout"); + assert!(body["line"].is_null()); + } + + #[tokio::test] + async fn script_error_syntax_returns_500() { + let (status, body) = response_parts(AppError::ScriptError { + error_type: ScriptErrorType::Syntax, + message: "unexpected symbol near ')'".into(), + method: "test.method".into(), + line: Some(5), + }) + .await; + assert_eq!(status, StatusCode::INTERNAL_SERVER_ERROR); + assert_eq!(body["error"], "script_error"); + assert_eq!(body["errorType"], "syntax"); + assert_eq!(body["line"], 5); } #[tokio::test] @@ -123,6 +252,47 @@ mod tests { assert_eq!(body, raw_body); } + #[test] + fn parse_lua_line_extracts_line_number() { + let (line, msg) = parse_lua_line("[string \"...\"]:42: attempt to index a nil value"); + assert_eq!(line, Some(42)); + assert_eq!(msg, "attempt to index a nil value"); + } + + #[test] + fn parse_lua_line_no_line_number() { + let (line, msg) = parse_lua_line("some other error"); + assert_eq!(line, None); + assert_eq!(msg, "some other error"); + } + + #[test] + fn parse_lua_line_runtime_error_prefix() { + let (line, msg) = parse_lua_line("runtime error: [string \"...\"]:10: bad argument"); + assert_eq!(line, Some(10)); + assert_eq!(msg, "bad argument"); + } + + #[test] + fn script_error_type_serializes() { + assert_eq!( + serde_json::to_string(&ScriptErrorType::Syntax).unwrap(), + "\"syntax\"" + ); + assert_eq!( + serde_json::to_string(&ScriptErrorType::Runtime).unwrap(), + "\"runtime\"" + ); + assert_eq!( + serde_json::to_string(&ScriptErrorType::Timeout).unwrap(), + "\"timeout\"" + ); + assert_eq!( + serde_json::to_string(&ScriptErrorType::MissingHandle).unwrap(), + "\"missing_handle\"" + ); + } + #[test] fn display_formats() { assert_eq!(AppError::Auth("x".into()).to_string(), "auth error: x"); @@ -139,5 +309,15 @@ mod tests { AppError::PdsError(StatusCode::BAD_GATEWAY, Bytes::new()).to_string(), "PDS error: 502 Bad Gateway" ); + assert_eq!( + AppError::ScriptError { + error_type: ScriptErrorType::Runtime, + message: "oops".into(), + method: "test.method".into(), + line: Some(5), + } + .to_string(), + "script runtime error in test.method at line 5: oops" + ); } } diff --git a/src/lua/execute.rs b/src/lua/execute.rs index daa7469..f5c5c2c 100644 --- a/src/lua/execute.rs +++ b/src/lua/execute.rs @@ -8,7 +8,7 @@ use std::time::Instant; use crate::AppState; use crate::auth::Claims; -use crate::error::AppError; +use crate::error::{AppError, ScriptErrorType, parse_lua_line}; use crate::event_log::{EventLog, Severity, log_event}; use crate::lexicon::ParsedLexicon; use crate::repo; @@ -39,6 +39,13 @@ pub async fn execute_procedure_script( script: &str, ) -> Result { let start = Instant::now(); + let span = tracing::info_span!( + "script.execute", + method = method, + script_type = "procedure", + caller_did = %claims.did(), + ); + span.in_scope(|| tracing::info!("script execution started")); let collection = lexicon.target_collection.as_deref().unwrap_or_default(); // Capture script source and input for error logging before anything is consumed. @@ -62,6 +69,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -87,6 +95,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -114,6 +123,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -136,6 +146,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -158,6 +169,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -180,6 +192,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -202,6 +215,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -225,11 +239,18 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) .await; - return Err(AppError::Internal("script execution failed".into())); + let (line, clean_msg) = parse_lua_line(&error_message); + return Err(AppError::ScriptError { + error_type: ScriptErrorType::Syntax, + message: clean_msg, + method: method.to_string(), + line, + }); } let handle: mlua::Function = match lua.globals().get("handle") { @@ -250,11 +271,17 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) .await; - return Err(AppError::Internal("script execution failed".into())); + return Err(AppError::ScriptError { + error_type: ScriptErrorType::MissingHandle, + message: "script does not define a handle() function".to_string(), + method: method.to_string(), + line: None, + }); } }; @@ -263,10 +290,21 @@ pub async fn execute_procedure_script( Err(e) => { let msg = e.to_string(); tracing::error!(method, error = %msg, "lua script execution failed"); + let (line, clean_msg) = parse_lua_line(&msg); let app_error = if msg.contains("execution limit") { - AppError::Internal("script exceeded execution time limit".into()) + AppError::ScriptError { + error_type: ScriptErrorType::Timeout, + message: "script exceeded execution time limit".to_string(), + method: method.to_string(), + line, + } } else { - AppError::Internal("script execution failed".into()) + AppError::ScriptError { + error_type: ScriptErrorType::Runtime, + message: clean_msg, + method: method.to_string(), + line, + } }; log_event( &state.db, @@ -281,6 +319,7 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -307,14 +346,26 @@ pub async fn execute_procedure_script( "input": input_json, "caller_did": claims.did(), "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) .await; - return Err(AppError::Internal("script execution failed".into())); + return Err(AppError::ScriptError { + error_type: ScriptErrorType::Runtime, + message: error_message, + method: method.to_string(), + line: None, + }); } }; + span.in_scope(|| { + tracing::info!( + duration_ms = start.elapsed().as_millis() as u64, + "script execution completed" + ); + }); log_event( &state.db, EventLog { @@ -326,6 +377,7 @@ pub async fn execute_procedure_script( "method": method, "caller_did": claims.did(), "duration_ms": start.elapsed().as_millis() as u64, + "response_size": json_value.to_string().len(), }), }, ) @@ -344,6 +396,8 @@ pub async fn execute_query_script( claims: Option<&Claims>, ) -> Result { let start = Instant::now(); + let span = tracing::info_span!("script.execute", method = method, script_type = "query",); + span.in_scope(|| tracing::info!("script execution started")); let collection = lexicon.target_collection.as_deref().unwrap_or_default(); // Capture script source for error logging. @@ -364,6 +418,7 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -387,6 +442,7 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -407,6 +463,7 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -429,6 +486,7 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -449,6 +507,7 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -470,11 +529,18 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) .await; - return Err(AppError::Internal("script execution failed".into())); + let (line, clean_msg) = parse_lua_line(&error_message); + return Err(AppError::ScriptError { + error_type: ScriptErrorType::Syntax, + message: clean_msg, + method: method.to_string(), + line, + }); } let handle: mlua::Function = match lua.globals().get("handle") { @@ -493,11 +559,17 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) .await; - return Err(AppError::Internal("script execution failed".into())); + return Err(AppError::ScriptError { + error_type: ScriptErrorType::MissingHandle, + message: "script does not define a handle() function".to_string(), + method: method.to_string(), + line: None, + }); } }; @@ -506,10 +578,21 @@ pub async fn execute_query_script( Err(e) => { let msg = e.to_string(); tracing::error!(method, error = %msg, "lua script execution failed"); + let (line, clean_msg) = parse_lua_line(&msg); let app_error = if msg.contains("execution limit") { - AppError::Internal("script exceeded execution time limit".into()) + AppError::ScriptError { + error_type: ScriptErrorType::Timeout, + message: "script exceeded execution time limit".to_string(), + method: method.to_string(), + line, + } } else { - AppError::Internal("script execution failed".into()) + AppError::ScriptError { + error_type: ScriptErrorType::Runtime, + message: clean_msg, + method: method.to_string(), + line, + } }; log_event( &state.db, @@ -522,6 +605,7 @@ pub async fn execute_query_script( "error": msg, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) @@ -546,14 +630,26 @@ pub async fn execute_query_script( "error": error_message, "script_source": script_source, "method": method, + "duration_ms": start.elapsed().as_millis() as u64, }), }, ) .await; - return Err(AppError::Internal("script execution failed".into())); + return Err(AppError::ScriptError { + error_type: ScriptErrorType::Runtime, + message: error_message, + method: method.to_string(), + line: None, + }); } }; + span.in_scope(|| { + tracing::info!( + duration_ms = start.elapsed().as_millis() as u64, + "script execution completed" + ); + }); log_event( &state.db, EventLog { @@ -564,6 +660,7 @@ pub async fn execute_query_script( detail: serde_json::json!({ "method": method, "duration_ms": start.elapsed().as_millis() as u64, + "response_size": json_value.to_string().len(), }), }, )