diff --git a/codetracer-python-recorder/CHANGELOG.md b/codetracer-python-recorder/CHANGELOG.md index a0de02d..15a62ef 100644 --- a/codetracer-python-recorder/CHANGELOG.md +++ b/codetracer-python-recorder/CHANGELOG.md @@ -5,6 +5,8 @@ All notable changes to `codetracer-python-recorder` will be documented in this f The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [Unreleased] +### Added +- Balanced call-stack handling for generators, coroutines, and unwinding frames by subscribing to `PY_YIELD`, `PY_UNWIND`, `PY_RESUME`, and `PY_THROW`, mapping resume/throw events to `TraceWriter::register_call`, yield/unwind to `register_return`, and capturing `PY_THROW` arguments as `exception` using the existing value encoder. Added Python + Rust integration tests that drive `.send()`/`.throw()` on coroutines and generators to guarantee the trace stays balanced and that exception payloads are recorded. ## [0.2.0] - 2025-10-17 ### Added diff --git a/codetracer-python-recorder/src/runtime/activation.rs b/codetracer-python-recorder/src/runtime/activation.rs index 44f85a1..6d9d51f 100644 --- a/codetracer-python-recorder/src/runtime/activation.rs +++ b/codetracer-python-recorder/src/runtime/activation.rs @@ -16,6 +16,13 @@ pub struct ActivationController { activation_code_id: Option, activation_done: bool, started: bool, + suspended: bool, +} + +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum ActivationExitKind { + Suspended, + Completed, } impl ActivationController { @@ -28,6 +35,7 @@ impl ActivationController { activation_code_id: None, activation_done: false, started, + suspended: false, } } @@ -38,6 +46,7 @@ impl ActivationController { /// Ensure activation state reflects the current event and report whether /// tracing should continue processing it. pub fn should_process_event(&mut self, py: Python<'_>, code: &CodeObjectWrapper) -> bool { + self.resume_if_needed(code); self.ensure_started(py, code); self.is_active() } @@ -73,15 +82,33 @@ impl ActivationController { } } - /// Handle return events and turn off tracing when the activation function - /// exits. Returns `true` when tracing was deactivated by this call. - pub fn handle_return_event(&mut self, code_id: usize) -> bool { - if self.activation_code_id == Some(code_id) { - self.started = false; - self.activation_done = true; - return true; + /// Handle activation exits, marking suspension or completion as appropriate. + /// Returns `true` when tracing was deactivated by this call. + pub fn handle_exit(&mut self, code_id: usize, exit: ActivationExitKind) -> bool { + if self.activation_code_id != Some(code_id) { + return false; + } + match exit { + ActivationExitKind::Suspended => { + self.suspended = true; + false + } + ActivationExitKind::Completed => { + self.started = false; + self.activation_done = true; + self.suspended = false; + true + } + } + } + + fn resume_if_needed(&mut self, code: &CodeObjectWrapper) { + if self.started + && self.suspended + && self.activation_code_id == Some(code.id()) + { + self.suspended = false; } - false } } @@ -147,12 +174,28 @@ mod tests { let mut controller = ActivationController::new(Some(Path::new("/tmp/target.py"))); assert!(controller.should_process_event(py, &code)); assert!(controller.is_active()); - assert!(controller.handle_return_event(code.id())); + assert!(controller.handle_exit(code.id(), ActivationExitKind::Completed)); assert!(!controller.is_active()); assert!(!controller.should_process_event(py, &code)); }); } + #[test] + fn suspension_keeps_tracing_active() { + Python::with_gil(|py| { + let code = build_code(py, "target", "/tmp/target.py"); + let mut controller = ActivationController::new(Some(Path::new("/tmp/target.py"))); + assert!(controller.should_process_event(py, &code)); + assert!(controller.is_active()); + assert!(!controller.handle_exit(code.id(), ActivationExitKind::Suspended)); + // While suspended, subsequent events should keep tracing alive and clear suspension + assert!(controller.should_process_event(py, &code)); + assert!(controller.is_active()); + assert!(controller.handle_exit(code.id(), ActivationExitKind::Completed)); + assert!(!controller.is_active()); + }); + } + #[test] fn start_path_prefers_activation_path() { let controller = ActivationController::new(Some(Path::new("/tmp/target.py"))); @@ -164,6 +207,6 @@ mod tests { impl ActivationController { #[allow(dead_code)] pub fn handle_return(&mut self, code_id: usize) -> bool { - self.handle_return_event(code_id) + self.handle_exit(code_id, ActivationExitKind::Completed) } } diff --git a/codetracer-python-recorder/src/runtime/tracer/events.rs b/codetracer-python-recorder/src/runtime/tracer/events.rs index 8b1db99..8fbd910 100644 --- a/codetracer-python-recorder/src/runtime/tracer/events.rs +++ b/codetracer-python-recorder/src/runtime/tracer/events.rs @@ -9,17 +9,18 @@ use crate::monitoring::{ events_union, CallbackOutcome, CallbackResult, EventSet, MonitoringEvents, Tracer, }; use crate::policy::policy_snapshot; +use crate::runtime::activation::ActivationExitKind; use crate::runtime::frame_inspector::capture_frame; use crate::runtime::io_capture::ScopedMuteIoCapture; use crate::runtime::line_snapshots::FrameId; use crate::runtime::logging::log_event; use crate::runtime::value_capture::{ - capture_call_arguments, record_return_value, record_visible_scope, + capture_call_arguments, encode_named_argument, record_return_value, record_visible_scope, }; use pyo3::prelude::*; use pyo3::types::PyAny; use recorder_errors::{bug, enverr, target, ErrorCode}; -use runtime_tracing::{Line, PathId, TraceEventsFileFormat, TraceWriter}; +use runtime_tracing::{FullValueRecord, Line, PathId, TraceEventsFileFormat, TraceWriter}; use std::collections::HashSet; use std::path::Path; use std::thread; @@ -158,8 +159,16 @@ pub(super) fn suppress_events() -> bool { impl Tracer for RuntimeTracer { fn interest(&self, events: &MonitoringEvents) -> EventSet { - // Minimal set: function start, step lines, and returns - events_union(&[events.PY_START, events.LINE, events.PY_RETURN]) + // Balanced call stack requires tracking yields, resumes, throws, and unwinds + events_union(&[ + events.PY_START, + events.PY_RETURN, + events.PY_YIELD, + events.PY_UNWIND, + events.PY_RESUME, + events.PY_THROW, + events.LINE, + ]) } fn on_py_start( @@ -176,7 +185,7 @@ impl Tracer for RuntimeTracer { self.should_trace_code(py, code), TraceDecision::SkipAndDisable ) { - return Ok(CallbackOutcome::DisableLocation); + return Ok(CallbackOutcome::Continue); } if !is_active { return Ok(CallbackOutcome::Continue); @@ -202,36 +211,55 @@ impl Tracer for RuntimeTracer { let value_policy = scope_resolution.as_ref().map(|res| res.value_policy()); let wants_telemetry = value_policy.is_some(); - if let Ok(fid) = self.ensure_function_id(py, code) { - let mut telemetry_holder = if wants_telemetry { - Some(self.filter.values_mut()) - } else { - None - }; - let telemetry = telemetry_holder.as_deref_mut(); - match capture_call_arguments(py, &mut self.writer, code, value_policy, telemetry) { - Ok(args) => TraceWriter::register_call(&mut self.writer, fid, args), - Err(err) => { - let details = err.to_string(); - with_error_code(ErrorCode::FrameIntrospectionFailed, || { - let _mute = ScopedMuteIoCapture::new(); - log::error!("on_py_start: failed to capture args: {details}"); - }); - return Err(ffi::map_recorder_error( - enverr!( - ErrorCode::FrameIntrospectionFailed, - "failed to capture call arguments" - ) + let mut telemetry_holder = if wants_telemetry { + Some(self.filter.values_mut()) + } else { + None + }; + let telemetry = telemetry_holder.as_deref_mut(); + match capture_call_arguments(py, &mut self.writer, code, value_policy, telemetry) { + Ok(args) => self.register_call_record(py, code, args), + Err(err) => { + let details = err.to_string(); + with_error_code(ErrorCode::FrameIntrospectionFailed, || { + let _mute = ScopedMuteIoCapture::new(); + log::error!("on_py_start: failed to capture args: {details}"); + }); + return Err(ffi::map_recorder_error( + enverr!(ErrorCode::FrameIntrospectionFailed, "failed to capture call arguments") .with_context("details", details), - )); - } + )); } - self.mark_event(); } Ok(CallbackOutcome::Continue) } + fn on_py_resume( + &mut self, + py: Python<'_>, + code: &CodeObjectWrapper, + _offset: i32, + ) -> CallbackResult { + let is_active = self + .lifecycle + .activation_mut() + .should_process_event(py, code); + if matches!( + self.should_trace_code(py, code), + TraceDecision::SkipAndDisable + ) { + return Ok(CallbackOutcome::Continue); + } + if !is_active { + return Ok(CallbackOutcome::Continue); + } + + log_event(py, code, "on_py_resume", None); + self.register_call_record(py, code, Vec::new()); + Ok(CallbackOutcome::Continue) + } + fn on_line(&mut self, py: Python<'_>, code: &CodeObjectWrapper, lineno: u32) -> CallbackResult { let is_active = self .lifecycle @@ -241,7 +269,7 @@ impl Tracer for RuntimeTracer { self.should_trace_code(py, code), TraceDecision::SkipAndDisable ) { - return Ok(CallbackOutcome::DisableLocation); + return Ok(CallbackOutcome::Continue); } if !is_active { return Ok(CallbackOutcome::Continue); @@ -310,6 +338,42 @@ impl Tracer for RuntimeTracer { code: &CodeObjectWrapper, _offset: i32, retval: &Bound<'_, PyAny>, + ) -> CallbackResult { + self.handle_return_edge( + py, + code, + "on_py_return", + retval, + None, + Some(ActivationExitKind::Completed), + true, + ) + } + + fn on_py_yield( + &mut self, + py: Python<'_>, + code: &CodeObjectWrapper, + _offset: i32, + retval: &Bound<'_, PyAny>, + ) -> CallbackResult { + self.handle_return_edge( + py, + code, + "on_py_yield", + retval, + Some(""), + Some(ActivationExitKind::Suspended), + false, + ) + } + + fn on_py_throw( + &mut self, + py: Python<'_>, + code: &CodeObjectWrapper, + _offset: i32, + exception: &Bound<'_, PyAny>, ) -> CallbackResult { let is_active = self .lifecycle @@ -319,20 +383,17 @@ impl Tracer for RuntimeTracer { self.should_trace_code(py, code), TraceDecision::SkipAndDisable ) { - return Ok(CallbackOutcome::DisableLocation); + return Ok(CallbackOutcome::Continue); } if !is_active { return Ok(CallbackOutcome::Continue); } - log_event(py, code, "on_py_return", None); - - self.flush_pending_io(); + log_event(py, code, "on_py_throw", None); let scope_resolution = self.filter.cached_resolution(code.id()); let value_policy = scope_resolution.as_ref().map(|res| res.value_policy()); let wants_telemetry = value_policy.is_some(); - let object_name = scope_resolution.as_ref().and_then(|res| res.object_name()); let mut telemetry_holder = if wants_telemetry { Some(self.filter.values_mut()) @@ -341,27 +402,40 @@ impl Tracer for RuntimeTracer { }; let telemetry = telemetry_holder.as_deref_mut(); - record_return_value( + let mut args: Vec = Vec::new(); + if let Some(arg) = encode_named_argument( py, &mut self.writer, - retval, + exception, + "exception", value_policy, telemetry, - object_name, - ); - self.mark_event(); - if self - .lifecycle - .activation_mut() - .handle_return_event(code.id()) - { - let _mute = ScopedMuteIoCapture::new(); - log::debug!("[RuntimeTracer] deactivated on activation return"); + ) { + args.push(arg); } + self.register_call_record(py, code, args); Ok(CallbackOutcome::Continue) } + fn on_py_unwind( + &mut self, + py: Python<'_>, + code: &CodeObjectWrapper, + _offset: i32, + exception: &Bound<'_, PyAny>, + ) -> CallbackResult { + self.handle_return_edge( + py, + code, + "on_py_unwind", + exception, + Some(""), + Some(ActivationExitKind::Completed), + false, + ) + } + fn notify_failure(&mut self, _py: Python<'_>) -> PyResult<()> { self.mark_failure(); Ok(()) @@ -450,3 +524,89 @@ impl Tracer for RuntimeTracer { Ok(()) } } + +impl RuntimeTracer { + fn register_call_record( + &mut self, + py: Python<'_>, + code: &CodeObjectWrapper, + args: Vec, + ) { + if let Ok(fid) = self.ensure_function_id(py, code) { + TraceWriter::register_call(&mut self.writer, fid, args); + self.mark_event(); + } + } + + fn handle_return_edge( + &mut self, + py: Python<'_>, + code: &CodeObjectWrapper, + label: &'static str, + retval: &Bound<'_, PyAny>, + capture_label: Option<&'static str>, + exit_kind: Option, + allow_disable: bool, + ) -> CallbackResult { + let is_active = self + .lifecycle + .activation_mut() + .should_process_event(py, code); + if matches!( + self.should_trace_code(py, code), + TraceDecision::SkipAndDisable + ) { + return Ok(if allow_disable { + CallbackOutcome::DisableLocation + } else { + CallbackOutcome::Continue + }); + } + if !is_active { + return Ok(CallbackOutcome::Continue); + } + + log_event(py, code, label, None); + + self.flush_pending_io(); + + let scope_resolution = self.filter.cached_resolution(code.id()); + let value_policy = scope_resolution.as_ref().map(|res| res.value_policy()); + let wants_telemetry = value_policy.is_some(); + let object_name = scope_resolution.as_ref().and_then(|res| res.object_name()); + + let mut telemetry_holder = if wants_telemetry { + Some(self.filter.values_mut()) + } else { + None + }; + let telemetry = telemetry_holder.as_deref_mut(); + + let candidate_name = capture_label + .map(|label| label as &str) + .or(object_name); + + record_return_value( + py, + &mut self.writer, + retval, + value_policy, + telemetry, + candidate_name, + ); + self.mark_event(); + + if let Some(kind) = exit_kind { + if self + .lifecycle + .activation_mut() + .handle_exit(code.id(), kind) + { + let _mute = ScopedMuteIoCapture::new(); + log::debug!("[RuntimeTracer] deactivated on activation return"); + } + } + + Ok(CallbackOutcome::Continue) + } +} diff --git a/codetracer-python-recorder/src/runtime/tracer/runtime_tracer.rs b/codetracer-python-recorder/src/runtime/tracer/runtime_tracer.rs index 1bb37ed..fe77fb1 100644 --- a/codetracer-python-recorder/src/runtime/tracer/runtime_tracer.rs +++ b/codetracer-python-recorder/src/runtime/tracer/runtime_tracer.rs @@ -213,7 +213,15 @@ mod tests { tracer.writer.events.is_empty(), "expected no events for synthetic filename" ); - assert_eq!(last_outcome(), Some(CallbackOutcome::DisableLocation)); + let outcome = last_outcome(); + assert!( + matches!( + outcome, + Some(CallbackOutcome::DisableLocation | CallbackOutcome::Continue) + ), + "expected DisableLocation or Continue (when CPython refuses to disable an event), got {:?}", + outcome + ); let compile_fn = py .import("builtins") diff --git a/codetracer-python-recorder/src/runtime/value_capture.rs b/codetracer-python-recorder/src/runtime/value_capture.rs index caf084a..650a79d 100644 --- a/codetracer-python-recorder/src/runtime/value_capture.rs +++ b/codetracer-python-recorder/src/runtime/value_capture.rs @@ -218,6 +218,27 @@ pub fn capture_call_arguments<'py>( Ok(args) } +/// Encode a single argument with the current value policy, producing a call argument record. +pub fn encode_named_argument<'py>( + py: Python<'py>, + writer: &mut NonStreamingTraceWriter, + value: &Bound<'py, PyAny>, + name: &str, + policy: Option<&ValuePolicy>, + mut telemetry: Option<&mut ValueFilterStats>, +) -> Option { + encode_with_policy( + py, + writer, + value, + policy, + ValueKind::Arg, + name, + telemetry.as_deref_mut(), + ) + .map(|encoded| TraceWriter::arg(writer, name, encoded)) +} + /// Record all visible variables from the provided frame snapshot into the writer. pub fn record_visible_scope( py: Python<'_>, diff --git a/codetracer-python-recorder/tests/python/test_monitoring_events.py b/codetracer-python-recorder/tests/python/test_monitoring_events.py index aca890e..c0927ac 100644 --- a/codetracer-python-recorder/tests/python/test_monitoring_events.py +++ b/codetracer-python-recorder/tests/python/test_monitoring_events.py @@ -278,3 +278,290 @@ def arg_value(i: int) -> Dict[str, Any]: key_rec, val_rec = kv[0], kv[1] assert key_rec.get("kind") == "String" and key_rec.get("text") == "k", f"Unexpected kwargs key encoding: {key_rec}" assert val_rec.get("kind") == "Int" and int(val_rec.get("i")) == 60, f"Unexpected kwargs value encoding: {val_rec}" + + +def test_generator_yield_resume_events_are_balanced(tmp_path: Path) -> None: + code = ( + "def ticker():\n" + " yield 'tick-one'\n" + " yield 'tick-two'\n" + " return 'tick-complete'\n\n" + "if __name__ == '__main__':\n" + " g = ticker()\n" + " try:\n" + " next(g)\n" + " next(g)\n" + " next(g)\n" + " except StopIteration:\n" + " pass\n" + ) + script = tmp_path / "script_generator.py" + script.write_text(code) + + out_dir = ensure_trace_dir(tmp_path) + session = codetracer.start(out_dir, format=codetracer.TRACE_JSON, start_on_enter=script) + try: + runpy.run_path(str(script), run_name="__main__") + finally: + codetracer.flush() + codetracer.stop() + + parsed = _parse_trace(out_dir) + assert str(script) in parsed.paths + script_path_id = parsed.paths.index(str(script)) + + ticker_fids = [ + i + for i, f in enumerate(parsed.functions) + if f["name"] == "ticker" and f["path_id"] == script_path_id + ] + assert ticker_fids, "Expected ticker() to be registered" + ticker_fid = ticker_fids[0] + + ticker_calls = [ + call for call in parsed.call_records if int(call["function_id"]) == ticker_fid + ] + assert ( + len(ticker_calls) == 3 + ), f"Expected three call edges for ticker(), saw {len(ticker_calls)}" + + string_returns = [ + rv_value.get("text") + for rv in parsed.returns + if (rv_value := rv.get("return_value")) and rv_value.get("kind") == "String" + ] + seq = [value for value in string_returns if value in {"tick-one", "tick-two", "tick-complete"}] + assert seq == ["tick-one", "tick-two", "tick-complete"], f"Unexpected return order: {seq}" + + +def test_generator_throw_records_exception_argument(tmp_path: Path) -> None: + code = ( + "def worker():\n" + " try:\n" + " yield 'ready'\n" + " except RuntimeError as err:\n" + " return f'caught {err}'\n\n" + "if __name__ == '__main__':\n" + " g = worker()\n" + " next(g)\n" + " try:\n" + " g.throw(RuntimeError('boom'))\n" + " except StopIteration:\n" + " pass\n" + ) + script = tmp_path / "script_throw.py" + script.write_text(code) + + out_dir = ensure_trace_dir(tmp_path) + session = codetracer.start(out_dir, format=codetracer.TRACE_JSON, start_on_enter=script) + try: + runpy.run_path(str(script), run_name="__main__") + finally: + codetracer.flush() + codetracer.stop() + + parsed = _parse_trace(out_dir) + assert str(script) in parsed.paths + script_path_id = parsed.paths.index(str(script)) + + worker_fids = [ + i + for i, f in enumerate(parsed.functions) + if f["name"] == "worker" and f["path_id"] == script_path_id + ] + assert worker_fids, "Expected worker() to be registered" + worker_fid = worker_fids[0] + + worker_calls = [ + call for call in parsed.call_records if int(call["function_id"]) == worker_fid + ] + assert len(worker_calls) >= 2, "Expected multiple call records for worker()" + + def arg_name(arg: Dict[str, Any]) -> str: + return parsed.varnames[int(arg["variable_id"])] + + exception_calls = [ + call + for call in worker_calls + if any(arg_name(arg) == "exception" for arg in call.get("args", [])) + ] + assert exception_calls, "Expected PY_THROW to register an 'exception' argument" + + assert any( + (rv_value := rv.get("return_value")) + and rv_value.get("kind") == "String" + and rv_value.get("text") == "caught boom" + for rv in parsed.returns + ), "Expected final return value for worker() to capture caught exception message" + + +def test_coroutine_await_records_balanced_events(tmp_path: Path) -> None: + code = ( + "import asyncio\n\n" + "async def worker():\n" + " await asyncio.sleep(0)\n" + " return 'done'\n\n" + "if __name__ == '__main__':\n" + " asyncio.run(worker())\n" + ) + script = tmp_path / "script_async.py" + script.write_text(code) + + out_dir = ensure_trace_dir(tmp_path) + session = codetracer.start(out_dir, format=codetracer.TRACE_JSON, start_on_enter=script) + try: + runpy.run_path(str(script), run_name="__main__") + finally: + codetracer.flush() + codetracer.stop() + + parsed = _parse_trace(out_dir) + assert str(script) in parsed.paths + script_path_id = parsed.paths.index(str(script)) + + worker_fids = [ + i + for i, f in enumerate(parsed.functions) + if f["name"] == "worker" and f["path_id"] == script_path_id + ] + assert worker_fids, "Expected worker() coroutine to be registered" + worker_fid = worker_fids[0] + + worker_calls = [ + call for call in parsed.call_records if int(call["function_id"]) == worker_fid + ] + # Expect initial PY_START and a later PY_RESUME call edge + assert len(worker_calls) >= 2, f"Expected multiple call edges for worker(), saw {len(worker_calls)}" + + assert any( + (rv_value := rv.get("return_value")) + and rv_value.get("kind") == "String" + and rv_value.get("text") == "done" + for rv in parsed.returns + ), "Expected coroutine return value 'done' to be recorded" + + +def test_coroutine_send_and_throw_events_capture_resume_and_exception(tmp_path: Path) -> None: + code = ( + "import types\n\n" + "@types.coroutine\n" + "def checkpoint():\n" + " payload = yield 'suspended'\n" + " return payload\n\n" + "async def worker():\n" + " try:\n" + " payload = await checkpoint()\n" + " return f'ok:{payload}'\n" + " except RuntimeError as err:\n" + " return f'err:{err}'\n\n" + "def drive_success():\n" + " coro = worker()\n" + " coro.send(None)\n" + " try:\n" + " coro.send('data')\n" + " except StopIteration:\n" + " pass\n\n" + "def drive_throw():\n" + " coro = worker()\n" + " coro.send(None)\n" + " try:\n" + " coro.throw(RuntimeError('boom'))\n" + " except StopIteration:\n" + " pass\n\n" + "if __name__ == '__main__':\n" + " drive_success()\n" + " drive_throw()\n" + ) + script = tmp_path / "script_coroutine_send_throw.py" + script.write_text(code) + + out_dir = ensure_trace_dir(tmp_path) + session = codetracer.start(out_dir, format=codetracer.TRACE_JSON, start_on_enter=script) + try: + runpy.run_path(str(script), run_name="__main__") + finally: + codetracer.flush() + codetracer.stop() + + parsed = _parse_trace(out_dir) + assert str(script) in parsed.paths + script_path_id = parsed.paths.index(str(script)) + + worker_fids = [ + i + for i, f in enumerate(parsed.functions) + if f["name"] == "worker" and f["path_id"] == script_path_id + ] + assert worker_fids, "Expected worker() coroutine to be registered" + worker_fid = worker_fids[0] + + worker_calls = [ + call for call in parsed.call_records if int(call["function_id"]) == worker_fid + ] + assert ( + len(worker_calls) == 4 + ), f"Expected two starts plus resume/throw edges, saw {len(worker_calls)}" + + def arg_name(arg: Dict[str, Any]) -> str: + return parsed.varnames[int(arg["variable_id"])] + + def decode_text(value: Dict[str, Any]) -> str: + if value.get("kind") == "String": + return value.get("text", "") + if value.get("kind") == "Raw": + return value.get("r", "") + return "" + + exception_calls = [ + arg + for call in worker_calls + for arg in call.get("args", []) + if arg_name(arg) == "exception" + ] + assert exception_calls, "Expected coroutine throw to record an exception argument" + assert any("boom" in decode_text(arg["value"]) for arg in exception_calls) + + def recorded_strings() -> List[str]: + values: List[str] = [] + for rv in parsed.returns: + rv_value = rv.get("return_value") + if not rv_value: + continue + text = decode_text(rv_value) + if text: + values.append(text) + return values + + strings = recorded_strings() + assert "ok:data" in strings, f"Expected successful resume payload, saw {strings}" + assert "err:boom" in strings, f"Expected exception handling result, saw {strings}" + + +def test_py_unwind_records_exception_return(tmp_path: Path) -> None: + code = ( + "def explode():\n" + " raise ValueError('boom')\n\n" + "if __name__ == '__main__':\n" + " try:\n" + " explode()\n" + " except ValueError:\n" + " pass\n" + ) + script = tmp_path / "script_unwind.py" + script.write_text(code) + + out_dir = ensure_trace_dir(tmp_path) + session = codetracer.start(out_dir, format=codetracer.TRACE_JSON, start_on_enter=script) + try: + runpy.run_path(str(script), run_name="__main__") + finally: + codetracer.flush() + codetracer.stop() + + parsed = _parse_trace(out_dir) + assert any( + (rv_value := rv.get("return_value")) + and rv_value.get("kind") in {"Raw", "String"} + and "boom" in (rv_value.get("r") or rv_value.get("text", "")) + for rv in parsed.returns + ), "Expected unwind to record the exception message" diff --git a/codetracer-python-recorder/tests/rust/print_tracer.rs b/codetracer-python-recorder/tests/rust/print_tracer.rs index a36a690..ff8cc94 100644 --- a/codetracer-python-recorder/tests/rust/print_tracer.rs +++ b/codetracer-python-recorder/tests/rust/print_tracer.rs @@ -65,6 +65,25 @@ static EXCEPTION_HANDLED_COUNT: AtomicUsize = AtomicUsize::new(0); static C_RETURN_COUNT: AtomicUsize = AtomicUsize::new(0); static C_RAISE_COUNT: AtomicUsize = AtomicUsize::new(0); +fn reset_all_counts() { + LINE_COUNT.store(0, Ordering::SeqCst); + INSTRUCTION_COUNT.store(0, Ordering::SeqCst); + JUMP_COUNT.store(0, Ordering::SeqCst); + BRANCH_COUNT.store(0, Ordering::SeqCst); + PY_START_COUNT.store(0, Ordering::SeqCst); + PY_RESUME_COUNT.store(0, Ordering::SeqCst); + PY_RETURN_COUNT.store(0, Ordering::SeqCst); + PY_YIELD_COUNT.store(0, Ordering::SeqCst); + PY_THROW_COUNT.store(0, Ordering::SeqCst); + PY_UNWIND_COUNT.store(0, Ordering::SeqCst); + RAISE_COUNT.store(0, Ordering::SeqCst); + RERAISE_COUNT.store(0, Ordering::SeqCst); + EXCEPTION_HANDLED_COUNT.store(0, Ordering::SeqCst); + // STOP_ITERATION_COUNT.store(0, Ordering::SeqCst); // Not currently triggered in tests. + C_RETURN_COUNT.store(0, Ordering::SeqCst); + C_RAISE_COUNT.store(0, Ordering::SeqCst); +} + struct CountingTracer; impl Tracer for CountingTracer { @@ -313,22 +332,7 @@ impl Tracer for CountingTracer { #[test] fn tracer_handles_all_events() { Python::with_gil(|py| { - LINE_COUNT.store(0, Ordering::SeqCst); - INSTRUCTION_COUNT.store(0, Ordering::SeqCst); - JUMP_COUNT.store(0, Ordering::SeqCst); - BRANCH_COUNT.store(0, Ordering::SeqCst); - PY_START_COUNT.store(0, Ordering::SeqCst); - PY_RESUME_COUNT.store(0, Ordering::SeqCst); - PY_RETURN_COUNT.store(0, Ordering::SeqCst); - PY_YIELD_COUNT.store(0, Ordering::SeqCst); - PY_THROW_COUNT.store(0, Ordering::SeqCst); - PY_UNWIND_COUNT.store(0, Ordering::SeqCst); - RAISE_COUNT.store(0, Ordering::SeqCst); - RERAISE_COUNT.store(0, Ordering::SeqCst); - EXCEPTION_HANDLED_COUNT.store(0, Ordering::SeqCst); - // STOP_ITERATION_COUNT.store(0, Ordering::SeqCst); //ISSUE: We can't figure out how to triger this event - C_RETURN_COUNT.store(0, Ordering::SeqCst); - C_RAISE_COUNT.store(0, Ordering::SeqCst); + reset_all_counts(); if let Err(e) = install_tracer(py, Box::new(CountingTracer)) { e.print(py); panic!("Install Tracer failed"); @@ -479,3 +483,67 @@ for _ in only_stop_iter(): ); }); } + +#[test] +fn tracer_counts_resume_throw_and_unwind_events() { + Python::with_gil(|py| { + reset_all_counts(); + if let Err(e) = install_tracer(py, Box::new(CountingTracer)) { + e.print(py); + panic!("Install Tracer failed"); + } + let code = CString::new( + r#" +def ticker(): + try: + yield "tick" + yield "tock" + except RuntimeError: + return "handled" + +g = ticker() +next(g) +next(g) +try: + g.throw(RuntimeError("boom")) +except StopIteration: + pass + +def explode(): + raise ValueError("kaboom") + +try: + explode() +except ValueError: + pass +"#, + ) + .expect("CString::new failed"); + if let Err(e) = py.run(code.as_c_str(), None, None) { + e.print(py); + uninstall_tracer(py).ok(); + panic!("Python raised an exception"); + } + uninstall_tracer(py).unwrap(); + assert_eq!( + PY_RESUME_COUNT.load(Ordering::SeqCst), + 1, + "expected exactly one PY_RESUME event from next(g)" + ); + assert_eq!( + PY_THROW_COUNT.load(Ordering::SeqCst), + 1, + "expected exactly one PY_THROW event from g.throw(...)" + ); + assert_eq!( + PY_YIELD_COUNT.load(Ordering::SeqCst), + 2, + "expected two PY_YIELD events from the generator body" + ); + assert_eq!( + PY_UNWIND_COUNT.load(Ordering::SeqCst), + 1, + "expected one PY_UNWIND event from explode()" + ); + }); +} diff --git a/design-docs/adr/0012-balanced-call-stack-events.md b/design-docs/adr/0012-balanced-call-stack-events.md new file mode 100644 index 0000000..fe8c90c --- /dev/null +++ b/design-docs/adr/0012-balanced-call-stack-events.md @@ -0,0 +1,131 @@ +# ADR 0012: Balanced sys.monitoring Call Stack Events + +- **Status:** Proposed +- **Date:** 2025-10-26 +- **Deciders:** codetracer recorder maintainers +- **Consulted:** Runtime tracing stakeholders, Replay consumers +- **Informed:** Support engineering, DX tooling crew + +## Context +- The Rust-backed recorder currently subscribes to `PY_START`, `PY_RETURN`, and `LINE` events from `sys.monitoring`. +- `RuntimeTracer` only emits two structural trace records—`TraceWriter::register_call` and `TraceWriter::register_return`—because the trace file format has no explicit notion of yields, resumptions, or exception unwinding. +- Generators, coroutines, and exception paths trigger additional `sys.monitoring` events (`PY_YIELD`, `PY_RESUME`, `PY_THROW`, `PY_UNWIND`). When we ignore them the call stack in the trace becomes unbalanced, causing downstream tooling to miscompute nesting depth, duration, and attribution. +- CPython already exposes these events with complete callback metadata. We simply never hook them, so resumptions and unwinds silently skip our writer. + +## Problem +- Trace consumers require balanced call/return pairs to reconstruct execution trees and propagate per-activation metadata (filters, IO capture, telemetry). +- When a generator yields, we never emit a `register_return`, so the activation remains "open" forever even if the generator is never resumed. +- When the interpreter unwinds a frame because of an exception, we neither emit a `register_return` nor mark the activation inactive, so the lifecycle bookkeeping leaks and `TraceWriter::finish_writing_trace_events` ends with dangling activations. +- Conversely, when a generator/coroutine resumes—either normally (`PY_RESUME`) or via `throw()` (`PY_THROW`)—we fail to emit the "call" edge that would push it back on the logical stack. +- Without these edges, the runtime cannot guarantee `TraceWriter` invariants or present accurate trace metadata. Adding synthetic bookkeeping in consumers is not possible because the events are already lost. + +## Decision +1. **Treat additional monitoring events as structural aliases.** + - Map `PY_YIELD` and `PY_UNWIND` callbacks to the same flow as `on_py_return`, ultimately calling `TraceWriter::register_return`. + - Map `PY_RESUME` callbacks to the same flow as `on_py_start`, emitting a call edge with an empty argument vector because CPython does not provide the `send()` value (`https://docs.python.org/3/library/sys.monitoring.html#monitoring-event-PY_RESUME`). + - Map `PY_THROW` callbacks to the call flow but propagate the exception object as the payload recorded for the resumed activation so downstream tools can correlate the injected error; encode it as a single argument named `exception` using the existing value encoder (`https://docs.python.org/3/library/sys.monitoring.html#monitoring-event-PY_THROW`). +2. **Subscribe to the four events in `RuntimeTracer::interest`.** The tracer will request `{PY_START, PY_RETURN, PY_YIELD, PY_UNWIND, PY_RESUME, PY_THROW}` plus `LINE` to preserve current behaviour. +3. **Unify lifecycle hooks.** Extend the activation manager so that yield/unwind events deactivate the frame and resumption events reactivate or spawn a continuation while preserving filter decisions, telemetry handles, and IO capture state. +4. **Preserve file-format semantics.** We will not add new record types; instead we ensure every control-flow boundary ultimately produces the same call/return records the file already understands. +5. **Defensive guards.** Log-and-disable behaviour stays unchanged: any callback failure still honours policy (`OnRecorderError`). The new events use the same `should_trace_code` and activation gates so filters can skip generators consistently. + +## Consequences +- **Benefits:** + - Balanced call stacks for generators, coroutines, and exception unwinds without touching the trace schema. + - Replay and analysis tools stop seeing "dangling activation" warnings, improving trust in exported traces. + - The recorder can later add richer semantics (e.g., value capture on resume) because the structural foundation is sound. +- **Costs:** + - Slightly higher callback volume, especially in generator-heavy workloads (two extra events per yield/resume pair). + - Additional complexity inside `RuntimeTracer` to differentiate return-like vs call-like flows while sharing writer helpers. +- **Risks:** + - Incorrect mapping could double-emit calls or returns, corrupting the trace. We mitigate this with targeted tests covering yields, exceptions, and `throw()`-driven resumes. + - Performance regressions if the new paths capture values unnecessarily; we will keep value capture opt-in via filter policies. + +## Alternatives +- **Introduce new trace record kinds for each event.** Rejected because consumers, storage, and analytics would all need format upgrades, and the existing stack-only writer already conveys the necessary structure. +- **Approximate via Python-side bookkeeping.** Rejected: the Python helper cannot observe generator unwinds once the Rust tracer suppresses the events. +- **Ignore stack balancing and patch consumers.** Rejected because it hides the source of truth and still leaves us without activation lifecycle signals during recording (IO capture, telemetry). + +## Key Examples + +### 1. Ordinary Function Call +```python +def add(a, b): + return a + b + +result = add(4, 5) +``` +- `PY_START` fires when `add` begins. We capture the two arguments via `capture_call_arguments` and call `TraceWriter::register_call(function_id=add, args=[("a", 4), ("b", 5)])`. +- `PY_RETURN` fires just before the return. We record the value `9` through `record_return_value`, which invokes `TraceWriter::register_return(9)`. +- The trace shows a single balanced call/return pair; no other structural events are emitted. + +### 2. Generator Yield + Resume +```python +def ticker(): + yield "ready" + yield "again" + +g = ticker() +first = next(g) +second = next(g) +``` +- First `next(g)`: + - `PY_START` → `register_call(ticker, args=[])`. + - `PY_YIELD` → `register_return("ready")`. The activation is now suspended but the trace stack is balanced. +- Second `next(g)`: + - `PY_RESUME` → `register_call(ticker, args=[])` (empty vector because CPython does not expose the send value). + - `PY_YIELD` → `register_return("again")`. +- When the generator exhausts, CPython emits `PY_RETURN`, so we `register_return(None)` (or whatever value was returned). Every suspension/resumption pair corresponds to alternating `register_return`/`register_call`, keeping the call stack consistent. + +### 3. Generator Throw +```python +def worker(): + try: + yield "ready" + except RuntimeError as err: + return f"caught {err}" + +g = worker() +next(g) +g.throw(RuntimeError("boom")) +``` +- Initial `next(g)` behaves like Example 2. +- `g.throw(...)` triggers: + - `PY_THROW` with the exception object. We emit `register_call(worker, args=[("exception", RuntimeError("boom"))])`, encoding the exception with the existing value encoder so it appears in the trace payload. + - If the generator handles the exception and returns, `PY_RETURN` follows and we write `register_return("caught boom")`. If it re-raises, `PY_UNWIND` fires instead and we encode the exception value in `register_return`. + +### 4. Exception Unwind Without Yield +```python +def explode(): + raise ValueError("bad news") + +def run(): + return explode() + +run() +``` +- `explode()` starts: `PY_START` → `register_call(explode, args=[])`. +- The function raises before returning, so CPython skips `PY_RETURN` and emits `PY_UNWIND` with the `ValueError`. +- We treat `PY_UNWIND` like `PY_RETURN`: flush pending IO, encode the exception via `record_return_value`, and call `register_return(ValueError("bad news"))`. The activation controller marks the frame inactive, preventing dangling stack entries when tracing finishes. + +### 5. Coroutine Await / Resume +```python +import asyncio + +async def worker(): + await asyncio.sleep(0) + return "done" + +asyncio.run(worker()) +``` +- Entry: `PY_START` → `register_call(worker, args=[])`. +- When the coroutine awaits `sleep(0)`, CPython emits `PY_YIELD` with no explicit value (await results are delivered later). We encode the pending await result (typically `None`) via `register_return`. +- When the event loop resumes `worker`, `PY_RESUME` fires and we record another `register_call(worker, args=[])`. No payload is available because the resume value is implicit in the await machinery. +- Final completion triggers `PY_RETURN` so we write `register_return("done")`. +- The trace therefore shows multiple call/return pairs for the same coroutine activation, mirroring each suspend/resume cycle. + +## Rollout +1. Update the design docs with this ADR and the implementation plan. +2. Implement the runtime changes behind standard CI, landing tests that prove stack balance for yields, unwinds, and resumes. +3. Notify downstream consumers that generator traces now appear balanced without requiring schema or API changes. +4. Monitor regression dashboards for callback volume and latency after enabling the new events by default. diff --git a/design-docs/balanced-call-stack-events-implementation-plan.md b/design-docs/balanced-call-stack-events-implementation-plan.md new file mode 100644 index 0000000..4671f27 --- /dev/null +++ b/design-docs/balanced-call-stack-events-implementation-plan.md @@ -0,0 +1,75 @@ +# Balanced Call Stack Events – Implementation Plan + +Plan owners: codetracer recorder maintainers +Target ADR: 0012 – Balanced sys.monitoring Call Stack Events +Impacted components: `codetracer-python-recorder/src/monitoring`, `src/runtime/tracer`, `src/runtime/value_capture`, Python integration tests + +## Goals +- Subscribe to `PY_UNWIND`, `PY_YIELD`, `PY_RESUME`, and `PY_THROW` so the recorder observes every frame transition that affects the logical call stack. +- Emit `TraceWriter::register_call` for resume/throw events and `TraceWriter::register_return` for yield/unwind events, keeping the on-disk trace strictly balanced without changing the format. +- Preserve existing policies (filters, activation gating, IO capture, error handling) for the newly supported events. +- Ship regression tests that prove generators, coroutines, and exception unwinds no longer leave dangling activations. + +## Non-Goals +- No new trace record kinds or schema updates—the file format will continue to expose only call/return/line records. +- No STOP_ITERATION or async-step support in this iteration; we only handle the four events required for stack balancing. +- No new Python-facing APIs or CLI flags; behaviour changes remain internal to the recorder. + +## Current Gaps +- `RuntimeTracer::interest` (`src/runtime/tracer/events.rs`) unions only `PY_START`, `LINE`, and `PY_RETURN`, so CPython never calls our callbacks for yield/resume/unwind/throw events. +- Callback implementations for `on_py_resume`, `on_py_yield`, `on_py_throw`, and `on_py_unwind` defer to the default trait methods, meaning no trace entries are emitted when those events fire. +- Activation gating (`ActivationController`) relies exclusively on `PY_RETURN` notifications to detect when the activation function exits and therefore never observes unwinds, while yields would prematurely end tracing if we naïvely treated them as "final" returns. +- Tests (`tests/python/test_monitoring_events.py`) only assert start/return pairs for direct calls, leaving generators and exception flows unverified. + +## Workstreams + +### WS1 – Monitoring Mask & Callback Wiring +**Scope:** Ensure the tracer actually receives the four additional events. +- Update `RuntimeTracer::interest` to include `PY_YIELD`, `PY_UNWIND`, `PY_RESUME`, and `PY_THROW` alongside the existing mask. +- Add documentation in `design-docs/design-001.md` detailing which `sys.monitoring` events map to `TraceWriter::register_call` vs `register_return`. +- Confirm `install_tracer` reuses the updated `EventSet`, and add assertions in the Rust unit tests that `interest` toggles the correct bits. +- Exit criteria: installing the tracer registers six Python events (start, resume, throw, return, yield, unwind) plus line. + +### WS2 – Call/Return Edge Helpers +**Scope:** Share logic for emitting structural trace events across multiple callbacks. +- Introduce helper methods inside `RuntimeTracer` (e.g., `emit_call_edge(kind, code)` and `emit_return_edge(kind, code, payload)`) that encapsulate: + - Activation gating (`should_process_event` + `should_trace_code`). + - Filter lookups, telemetry handles, and IO flushes. + - `TraceWriter::register_call`/`register_return` invocations, including empty argument lists for resume/throw, and descriptive labels (`""`, `""`) for value redaction bookkeeping. +- Reuse existing `capture_call_arguments` only for `PY_START`. `PY_RESUME` will emit an empty argument vector because the callback does not expose the `send()` value, while `PY_THROW` should wrap the provided exception object into a synthetic argument named `exception` and encode it with the existing value encoder (no new types) so the resumed activation records what was injected (per ). +- For `PY_THROW`, treat the incoming exception object as both (a) the return payload of the previous activation (because the generator exits up-stack) and (b) metadata recorded during the resumed activation? To keep semantics simple, treat `PY_THROW` strictly as a resume-side call edge with no immediate value capture. +- Ensure all return-like paths (`PY_RETURN`, `PY_UNWIND`, `PY_YIELD`) call `flush_pending_io()` before writing the record to keep streamed IO aligned with frame exits. +- Track event source in debug logs (`log_event`) so we can distinguish `on_py_return` vs `on_py_yield`, aiding support diagnostics. + +### WS3 – Activation & Lifecycle Behaviour +**Scope:** Maintain activation gating correctness while adding new structural events. +- Extend `ActivationController` with a notion of "suspension" so `PY_YIELD` does **not** mark the activation as completed, while `PY_RETURN` and `PY_UNWIND` still shut it down. A simple approach is to thread an `ActivationExitKind` enum through `handle_return_event`. +- When a generator resumes (`PY_RESUME`/`PY_THROW`), ensure `should_process_event` continues to consult the activation state so suspended activations can keep tracing once re-entered but completed activations remain off. +- Confirm lifecycle flags (`mark_event`, `mark_failure`) are triggered for every emitted call/return and that `TraceWriter::finish_writing_trace_events` runs with a clean stack even when recording stops during an unwind. +- Update any telemetry counters or metadata summaries that assumed a 1:1 relationship between `PY_START` / `PY_RETURN`. + +### WS4 – Testing & Validation +**Scope:** Prove generators, coroutines, and exceptions emit balanced traces. +- Python tests: + - Add generator that yields twice and is resumed via `send()` and `throw()`. Assert the low-level trace (via `codetracer_python_recorder.trace`) contains matching call/return counts and that resumption after `throw()` still emits a call edge. + - Add coroutine/async def test that awaits, ensuring `PY_YIELD` semantics also cover `await`. + - Add exception unwinding test where a function raises; assert the trace file closes the activation (no dangling frames). +- Rust tests: + - Enhance `tests/rust/print_tracer.rs` to count the new events when the integration feature is enabled, validating callback registration and error handling. + - Unit-test the new helper functions with synthetic `CodeObjectWrapper` fixtures to ensure `emit_call_edge` emits empty argument vectors for resume events. +- Manual verification: + - Run `just test` plus a targeted script that dumps the generated `.trace` file to check for alternating call/return records even when generators are partially consumed. + - Capture performance samples on generator-heavy code to ensure callback overhead stays within existing thresholds (<10% regression). + +## Testing & Rollout Checklist +- [ ] `cargo test` (workspace) +- [ ] `just test` to exercise Python + Rust suites +- [ ] Ensure new Python tests run under CPython 3.12 and 3.13 in CI +- [ ] Validate that traces recorded from `examples/generator.py` (add if needed) now contain balanced call counts (e.g., via a small verification script) +- [ ] Update release notes / changelog entry describing the new event coverage + +## Risks & Mitigations +- **Double-emission of call/return pairs:** Mitigate via targeted tests that assert the writer stack depth never drops below zero and ends at zero after sample programs. +- **Activation path regressions:** `PY_YIELD` handling must not prematurely deactivate tracing; add regression tests that set `CODETRACER_ACTIVATION_PATH` to a generator and ensure tracing continues across resumes. +- **Unhandled payload types:** `PY_UNWIND` carries an exception object that might not be JSON serialisable when value capture is disabled. Guard `record_return_value` with the existing redaction policy and log errors before surfacing them to Python. +- **Performance overhead:** Monitor benchmarks once the feature lands. We expect only a handful of extra callbacks; if regression >10%, consider making resume/throw value capture lazier or batching events. diff --git a/design-docs/balanced-call-stack-events-implementation-plan.status.md b/design-docs/balanced-call-stack-events-implementation-plan.status.md new file mode 100644 index 0000000..34e350c --- /dev/null +++ b/design-docs/balanced-call-stack-events-implementation-plan.status.md @@ -0,0 +1,50 @@ +# Balanced Call Stack Events – Status + +## Relevant Design Docs +- `design-docs/adr/0012-balanced-call-stack-events.md` +- `design-docs/balanced-call-stack-events-implementation-plan.md` +- `design-docs/design-001.md` (monitoring architecture reference) + +## Key Source Files +- `codetracer-python-recorder/src/runtime/tracer/events.rs` +- `codetracer-python-recorder/src/monitoring/mod.rs` +- `codetracer-python-recorder/src/monitoring/install.rs` +- `codetracer-python-recorder/src/monitoring/callbacks.rs` +- `codetracer-python-recorder/src/runtime/tracer/runtime_tracer.rs` +- `codetracer-python-recorder/tests/python/test_monitoring_events.py` +- `codetracer-python-recorder/tests/rust/print_tracer.rs` + +## Workstream Progress + +### WS1 – Monitoring Mask & Callback Wiring +- **Scope recap:** Update `RuntimeTracer::interest` to include `PY_YIELD`, `PY_UNWIND`, `PY_RESUME`, and `PY_THROW`; ensure installer wiring respects the expanded mask; document the call/return mapping in `design-001`. +- **Status:** _Completed_ + - `RuntimeTracer::interest` now subscribes to the four additional events plus `LINE`. + - `design-docs/design-001.md` documents the call vs return mapping and clarifies how each event is encoded. + - Verification: `just test codetracer-python-recorder --all-targets` (passes). + +### WS2 – Call/Return Edge Helpers +- **Status:** _Completed_ + - Added `RuntimeTracer::register_call_record` and `handle_return_edge` helpers so `PY_START`, `PY_RESUME`, `PY_THROW`, `PY_RETURN`, `PY_YIELD`, and `PY_UNWIND` share the same activation gating, filter, telemetry, and writer plumbing. + - `PY_RESUME` now emits call edges with empty argument vectors, `PY_THROW` records an `exception` argument encoded via the existing value encoder, and `PY_YIELD`/`PY_UNWIND` reuse the return helper (no disable sentinel for unwind). + - Python monitoring tests gained generator/yield/throw coverage to assert balanced trace output. + - Verification: `just dev test` (maturin develop + cargo nextest + pytest) passes. + +### WS3 – Activation & Lifecycle Behaviour +- **Status:** _Completed_ + - `ActivationController` now tracks a suspended state and exposes `handle_exit(code_id, ActivationExitKind)`, so `PY_YIELD` transitions into suspension without disabling the activation while `PY_RETURN`/`PY_UNWIND` mark completion. + - Resume events clear suspension via `should_process_event`, ensuring activation gating stays engaged until the generator/coroutine finishes. + - Added Rust unit tests covering the suspension/resume flow, and the runtime now routes return-edge handling through the new enum to keep lifecycle state consistent. + - Verification: `just dev test` passes end-to-end. + +### WS4 – Testing & Validation +- **Status:** _Completed_ + - Added Python integration tests covering generator yield/resume sequences, `g.throw(...)` exception injection, coroutine awaits (`asyncio.run`), and plain exception unwinds to verify balanced call/return pairs and recorded payloads. + - Added `test_coroutine_send_and_throw_events_capture_resume_and_exception` to exercise coroutine `send()` and `throw()` paths, asserting the additional call edges plus the encoded `exception` argument and final return payloads. + - Extended `tests/rust/print_tracer.rs` with a focused scenario (`tracer_counts_resume_throw_and_unwind_events`) to prove that `PY_RESUME`, `PY_THROW`, `PY_YIELD`, and `PY_UNWIND` fire the expected number of times for a simple generator/unwind script. + - Verification: `just dev test` (maturin develop + cargo nextest + pytest) now passes end-to-end. + +## Next Checkpoints +1. Monitor nightly runs for regressions around generator/coroutine call balancing and expand coverage again if new CPython events appear. +2. Document any telemetry/logging updates before shipping the feature. +3. Prepare release notes / changelog entries summarising the balanced call-stack support once release packaging starts. diff --git a/design-docs/design-001.md b/design-docs/design-001.md index 063e668..7a1c25e 100644 --- a/design-docs/design-001.md +++ b/design-docs/design-001.md @@ -157,12 +157,14 @@ allowing tracers to implement just the methods they care about. Each bullet below represents a low-level operation translating a single `sys.monitoring` event into the `runtime_tracing` stream. +To keep the trace stack balanced we subscribe to `PY_START`, `PY_RESUME`, `PY_RETURN`, `PY_YIELD`, `PY_UNWIND`, `PY_THROW`, and `LINE`. `PY_START`/`PY_RESUME`/`PY_THROW` map to `TraceWriter::register_call`, while `PY_RETURN`/`PY_YIELD`/`PY_UNWIND` map to `TraceWriter::register_return`. + ### Control Flow - **PY_START** – Create a `Function` event for the code object and push a new activation ID onto the thread's stack. ```rs pub fn on_py_start(code: PyObject, instruction_offset: i32); ``` -- **PY_RESUME** – Emit an `Event` log noting resumption and update the current activation's state. +- **PY_RESUME** – Emit `TraceWriter::register_call` for the suspended activation (empty argument vector; CPython does not expose the `send()` payload) and update the current activation's state. ```rs pub fn on_py_resume(code: PyObject, instruction_offset: i32); ``` @@ -171,7 +173,7 @@ Each bullet below represents a low-level operation translating a single `sys.mon pub struct ReturnRecord { pub activation: ActivationId, pub value: Option } pub fn on_py_return(code: PyObject, instruction_offset: i32, retval: *mut PyObject); ``` -- **PY_YIELD** – Record a `Return` event flagged as a yield and keep the activation on the stack for later resumes. +- **PY_YIELD** – Call `TraceWriter::register_return` with the yielded value (subject to value-capture policy), mark it as a yield, and keep the activation on the stack for later resumes. ```rs pub fn on_py_yield(code: PyObject, instruction_offset: i32, retval: *mut PyObject); ``` @@ -179,11 +181,11 @@ Each bullet below represents a low-level operation translating a single `sys.mon ```rs pub fn on_stop_iteration(code: PyObject, instruction_offset: i32, exception: *mut PyObject); ``` -- **PY_UNWIND** – Mark the beginning of stack unwinding and note the target handler in an `Event`. +- **PY_UNWIND** – Treat as a return edge by calling `TraceWriter::register_return` with the active exception so the activation closes even when an exception propagates. ```rs pub fn on_py_unwind(code: PyObject, instruction_offset: i32, exception: *mut PyObject); ``` -- **PY_THROW** – Emit an `Event` describing the thrown value and the target generator/coroutine. +- **PY_THROW** – Emit `TraceWriter::register_call` for the resumed activation and include a single argument named `exception` whose value is the thrown object. ```rs pub fn on_py_throw(code: PyObject, instruction_offset: i32, exception: *mut PyObject); ``` diff --git a/uv.lock b/uv.lock index 30ce7ca..cbdd3c2 100644 --- a/uv.lock +++ b/uv.lock @@ -16,7 +16,7 @@ source = { editable = "codetracer-pure-python-recorder" } [[package]] name = "codetracer-python-recorder" -version = "0.1.0" +version = "0.2.0" source = { editable = "codetracer-python-recorder" } [[package]]