From 673de0972700ad9ece1a4e9dcf899395fd438587 Mon Sep 17 00:00:00 2001 From: Chris Pardy Date: Fri, 1 May 2026 10:02:00 -0400 Subject: [PATCH] feat(scripts): promote log() to write into event_logs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Lua `log("...")` primitive used to call `tracing::debug!` only — fine for ops who tail server stderr, useless for operators who use the dashboard. Wire it into `event_logs` so script output is queryable from `/dashboard/events` without shell access. New `register_log_event_api(lua, state, trigger_id, caller_did)` in `src/lua/scripts.rs` registers a Lua `log(msg)` global that does both: - Emits `tracing::debug!(lua_log = msg, trigger = trigger_id, ...)` for ops who do tail. - Inserts a row into `event_logs` with: event_type = "script.log" severity = Info actor_did = caller_did (XRPC handlers; None for record / label) subject = trigger_id (queryable per script) detail = { trigger, message } This intentionally OVERRIDES the basic `log()` from `sandbox::create_sandbox()`. All four script runners (record-event, label-applied, xrpc.procedure, xrpc.query) now wire it through: - `register_default_apis(lua, state, trigger_id, caller_did)` gains the `trigger_id` parameter and calls `register_log_event_api` after the other registrations. - `execute_procedure_script` and `execute_query_script` register the log API directly with `xrpc.{procedure,query}:` as the trigger. E2E test in `tests/e2e_scripts.rs` verifies a record-event script's `log("hello from script")` produces a `script.log` row whose subject is the trigger id and detail carries `{ trigger, message }`. Signed-off-by: Chris Pardy --- src/lua/execute.rs | 63 +++++++++++++++++++++++++++++++++++++++++++- src/lua/sandbox.rs | 14 ++++++---- src/lua/scripts.rs | 61 ++++++++++++++++++++++++++++++++++++++++-- tests/e2e_scripts.rs | 51 +++++++++++++++++++++++++++++++++++ 4 files changed, 181 insertions(+), 8 deletions(-) diff --git a/src/lua/execute.rs b/src/lua/execute.rs index 3ed5a23..7ee6f3c 100644 --- a/src/lua/execute.rs +++ b/src/lua/execute.rs @@ -289,6 +289,37 @@ pub async fn execute_procedure_script( return Err(AppError::Internal(error_message)); } + // Override the sandbox's tracing-only `log()` with a version that + // also writes a `script.log` row to `event_logs` so operators can + // see script output from the dashboard. The xrpc trigger id is + // computed from the lexicon's id + procedure type. + let trigger_id = format!("xrpc.procedure:{}", lexicon.id); + if let Err(e) = + super::scripts::register_log_event_api(&lua, &state_arc, &trigger_id, Some(claims.did())) + { + let error_message = format!("failed to register log API: {e}"); + log_event( + &state.db, + EventLog { + event_type: "script.error".to_string(), + severity: Severity::Error, + actor_did: Some(claims.did().to_string()), + subject: Some(method.to_string()), + detail: serde_json::json!({ + "error": error_message, + "script_source": script_source, + "input": input_json, + "caller_did": claims.did(), + "method": method, + "duration_ms": start.elapsed().as_millis() as u64, + }), + }, + backend, + ) + .await; + return Err(AppError::Internal(error_message)); + } + if let Err(e) = context::set_procedure_context( &lua, method, @@ -668,7 +699,7 @@ pub async fn execute_query_script( // auth context — the local-only methods (Record.load, :save_local, // :delete_local, Record.delete_local) work; PDS-touching variants // error with the no-PDS-auth message. - if let Err(e) = record::register_record_api_no_auth(&lua, state_arc) { + if let Err(e) = record::register_record_api_no_auth(&lua, state_arc.clone()) { let error_message = format!("failed to register Record API: {e}"); log_event( &state.db, @@ -690,6 +721,36 @@ pub async fn execute_query_script( return Err(AppError::Internal(error_message)); } + // Override the sandbox's tracing-only `log()` with a version that + // also writes a `script.log` row to `event_logs`. + let trigger_id = format!("xrpc.query:{}", lexicon.id); + if let Err(e) = super::scripts::register_log_event_api( + &lua, + &state_arc, + &trigger_id, + claims.map(|c| c.did()), + ) { + let error_message = format!("failed to register log API: {e}"); + log_event( + &state.db, + EventLog { + event_type: "script.error".to_string(), + severity: Severity::Error, + actor_did: None, + subject: Some(method.to_string()), + detail: serde_json::json!({ + "error": error_message, + "script_source": script_source, + "method": method, + "duration_ms": start.elapsed().as_millis() as u64, + }), + }, + backend, + ) + .await; + return Err(AppError::Internal(error_message)); + } + if let Err(e) = context::set_query_context( &lua, method, diff --git a/src/lua/sandbox.rs b/src/lua/sandbox.rs index fe7fe3d..833f83d 100644 --- a/src/lua/sandbox.rs +++ b/src/lua/sandbox.rs @@ -55,11 +55,15 @@ pub fn create_sandbox() -> LuaResult { let now_fn = lua.create_function(|_, ()| Ok(chrono::Utc::now().to_rfc3339()))?; globals.set("now", now_fn)?; - // Utility: log(message) logs via tracing::debug - let log_fn = lua.create_function(|_, msg: String| { - tracing::debug!(lua_log = %msg, "lua script log"); - Ok(()) - })?; + // `log(message)` no-op stub. The real implementation lives in + // `super::scripts::register_log_event_api` and is registered by + // every runner so the trigger context can be threaded into each + // `event_logs` row. The stub here exists only so paths that exec + // a script body OUTSIDE a runner — namely `validate_script` + // (admin write-time linting) and the in-process xrpc_api tests — + // don't break on top-level `log("...")` calls in user scripts. + // The runner-level registration always overrides this stub. + let log_fn = lua.create_function(|_, _msg: String| Ok(()))?; globals.set("log", log_fn)?; // Utility: TID table — callable as TID() to generate, plus conversion methods diff --git a/src/lua/scripts.rs b/src/lua/scripts.rs index 43970dc..870d373 100644 --- a/src/lua/scripts.rs +++ b/src/lua/scripts.rs @@ -407,7 +407,7 @@ pub async fn run_record_event_once( } let lua = sandbox::create_sandbox().map_err(|e| format!("create sandbox: {e}"))?; let state_arc = Arc::new(state.clone()); - register_default_apis(&lua, &state_arc, Some(did))?; + register_default_apis(&lua, &state_arc, &script.id, Some(did))?; // Legacy globals (action, uri, did, collection, rkey, record) for // back-compat with scripts written against the old `index_hook` @@ -565,7 +565,7 @@ async fn run_label_lua_once( } let lua = sandbox::create_sandbox().map_err(|e| format!("create sandbox: {e}"))?; let state_arc = Arc::new(state.clone()); - register_default_apis(&lua, &state_arc, None)?; + register_default_apis(&lua, &state_arc, &script.id, None)?; use mlua::LuaSerdeExt; let globals = lua.globals(); @@ -660,6 +660,7 @@ fn extract_bool(v: &Value, key: &str) -> Option { fn register_default_apis( lua: &mlua::Lua, state: &Arc, + trigger_id: &str, caller_did: Option<&str>, ) -> Result<(), String> { db_api::register_db_api(lua, state.clone()).map_err(|e| format!("db api: {e}"))?; @@ -670,6 +671,62 @@ fn register_default_apis( .map_err(|e| format!("atproto api: {e}"))?; record::register_record_api_no_auth(lua, state.clone()) .map_err(|e| format!("record api: {e}"))?; + register_log_event_api(lua, state, trigger_id, caller_did)?; + Ok(()) +} + +/// Register `log(msg)` as a Lua global that writes a `script.log` row to +/// `event_logs` (so operators can inspect script output from +/// `/dashboard/events` without tailing stderr) AND emits a +/// `tracing::debug!` for ops who do tail. +/// +/// `trigger_id` is recorded as the row's `subject` so events for a +/// specific script can be filtered by trigger. `caller_did` is recorded +/// as `actor_did` when the runner has one (XRPC handlers); record / +/// label runners pass `None`. +/// +/// This intentionally **overrides** the basic `log()` helper that +/// `sandbox::create_sandbox()` registers (which only writes to +/// `tracing::debug!`). All script runners call this helper so every +/// trigger family lands its `log()` calls in the event log. +pub(crate) fn register_log_event_api( + lua: &mlua::Lua, + state: &Arc, + trigger_id: &str, + caller_did: Option<&str>, +) -> Result<(), String> { + let state = state.clone(); + let trigger_id = trigger_id.to_string(); + let caller_did = caller_did.map(String::from); + let log_fn = lua + .create_async_function(move |_, msg: String| { + let state = state.clone(); + let trigger_id = trigger_id.clone(); + let caller_did = caller_did.clone(); + async move { + tracing::debug!(lua_log = %msg, trigger = %trigger_id, "lua script log"); + log_event( + &state.db, + EventLog { + event_type: "script.log".to_string(), + severity: Severity::Info, + actor_did: caller_did, + subject: Some(trigger_id.clone()), + detail: serde_json::json!({ + "trigger": trigger_id, + "message": msg, + }), + }, + state.db_backend, + ) + .await; + Ok(()) + } + }) + .map_err(|e| format!("log api: {e}"))?; + lua.globals() + .set("log", log_fn) + .map_err(|e| format!("set log global: {e}"))?; Ok(()) } diff --git a/tests/e2e_scripts.rs b/tests/e2e_scripts.rs index 78994ec..8b8a357 100644 --- a/tests/e2e_scripts.rs +++ b/tests/e2e_scripts.rs @@ -555,6 +555,57 @@ async fn record_create_returning_nil_skips_indexing() { ); } +// --------------------------------------------------------------------------- +// log() in scripts → event_logs +// --------------------------------------------------------------------------- + +#[tokio::test] +#[serial] +#[ignore] +async fn record_event_script_log_writes_event_log_row() { + let app = TestApp::new().await; + seed_lexicon(&app, fixtures::game_record_lexicon()).await; + + create_script( + &app, + "record.create:games.gamesgamesgamesgames.game", + "function handle() log('hello from script'); return event.record end", + ) + .await; + + handle_record_event( + &app.state, + &RecordEvent { + did: "did:plc:test".into(), + collection: "games.gamesgamesgamesgames.game".into(), + rkey: "rk1".into(), + action: "create".into(), + record: Some(json!({"title": "anything"})), + cid: Some("bafy".into()), + }, + ) + .await; + + // The script's log("hello from script") should land in event_logs + // as a `script.log` row whose subject is the trigger id. + let row: (String, String) = sqlx::query_as(&adapt_sql( + "SELECT subject, detail FROM event_logs + WHERE event_type = 'script.log' + ORDER BY id DESC LIMIT 1", + app.state.db_backend, + )) + .fetch_one(&app.state.db) + .await + .expect("expected a script.log row"); + assert_eq!(row.0, "record.create:games.gamesgamesgamesgames.game"); + let detail: Value = serde_json::from_str(&row.1).unwrap(); + assert_eq!(detail["message"], "hello from script"); + assert_eq!( + detail["trigger"], + "record.create:games.gamesgamesgamesgames.game" + ); +} + // --------------------------------------------------------------------------- // Label scripts via URI routing // --------------------------------------------------------------------------- -- 2.51.2