diff --git a/CHANGELOG.md b/CHANGELOG.md index 7cafa4c..1e0c274 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,98 @@ All notable changes to this workspace are documented here. The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) and this project adheres to [Semantic Versioning](https://semver.org/). +## 0.4.0 — 2026-04-28 + +### Changed — observability (breaking) + +- **Unified observation pipeline.** The codegen now emits a single + `__chart_observe!` invocation per observable atom, dispatched at + compile time to whichever sinks are enabled: the in-memory journal + (`feature = "journal"`), `defmt` (`trace-defmt`), `log` + (`trace-log`), and/or `tracing` (`trace-tracing`). All sinks share + the same vocabulary by construction — the journal IS the observation + stream; trace backends are textual renderings of it. With NO sink + feature on, every call site expands to `()` (zero overhead). Multiple + trace sinks may now be enabled simultaneously (previously they were + mutually exclusive). +- **Trace prefix changed.** `[ChartName] verb …` → + `[statechart:ChartName] verb …`. The new form is greppable and + unambiguous in mixed log streams. +- **Trace format is now logfmt-style.** Every line is + `[statechart:Name] key=value key=value …` (or native structured + fields under `tracing`). Twenty verbs cover every TraceEvent variant + — entries, exits (with begin/end pairs), actions (with kind), + durings, transitions (with **reason** showing what triggered them), + events (received/delivered/dropped/queued/failed), timers, terminate. +- **`trace;` keyword deprecated.** Still parsed for backwards + compatibility, but no longer gates emission. Trace output is now + controlled purely by which `trace-*` cargo feature you enable. + +### Changed — journal (breaking) + +- **`TraceEvent::TransitionFired` carries `reason: TransitionReason`.** + Replay consumers now see whether a transition was driven by an event + (`Event { event: u16 }`), a timer (`Timer { state, timer }`), or + internal logic (`Internal`). +- **New TraceEvent variants for phase begin/end pairing.** + - `EnterBegan { state }` fires before a state's entry actions / + timers / durings; `Entered` keeps its place as the end marker. + - `ExitBegan { state }` fires before a state's during cancellations + / timer cancellations / exit actions; `Exited` keeps its place as + the end marker. + - `TransitionComplete { from, to }` fires after a transition's full + exit-then-enter sequence finishes; pairs with `TransitionFired`. + - `EventReceived { event }` fires when an event is popped from the + queue, before handler search; pairs with `EventDelivered` / + `EventDropped` / `TerminateRequested`. + +### Added + +- **`hsmc/tests/trace_format.rs`** — 11 tests pinning every verb's + exact textual rendering, including a journal/trace atom-count + equivalence test. +- **`TransitionReason`** enum — re-exported from the crate root when + `feature = "journal"` is on. Carried on `TraceEvent::TransitionFired`. +- **Multiple trace backends compose.** Previously enabling more than + one of `trace-defmt` / `trace-log` / `trace-tracing` was a compile + error. Now they fan out independently. + +### Migration + +Chart syntax is unchanged: every v0.1 / v0.2 / v0.3 statechart compiles +under v0.4 without modification. Breakage is confined to the +observability surface area: + +1. **Trace line prefix.** Update grep patterns and log filters from + `[ChartName]` to `[statechart:ChartName]`. The verb after the + prefix is now a single hyphenated token followed by `key=value` + pairs. + +2. **`TraceEvent::TransitionFired`** has a new `reason` field. Update + pattern matches: + + ```rust + // before: + TraceEvent::TransitionFired { from, to } => … + // after: + TraceEvent::TransitionFired { from, to, reason } => … + // or, if you don't care: + TraceEvent::TransitionFired { from, to, .. } => … + ``` + +3. **New `TraceEvent` variants.** If you `match` exhaustively, add + arms for `EnterBegan`, `ExitBegan`, `TransitionComplete`, + `EventReceived`. Otherwise nothing changes. + +4. **`trace;` keyword is now a no-op.** Charts that declared it still + compile. Trace output is now controlled purely by which `trace-*` + cargo feature you enable. + +5. **`__chart_trace!` and `__chart_journal!` macros are removed.** + These were doc-hidden and not part of the public API; mentioned + here for codebases that grepped through the macro emission for + patches/forks. + ## 0.3.0 — 2026-04-27 ### Added diff --git a/Cargo.lock b/Cargo.lock index a0450f3..ac276ea 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -465,7 +465,7 @@ checksum = "2304e00983f87ffb38b55b444b5e3b60a884b5d30c0fca7d82fe33449bbe55ea" [[package]] name = "hsmc" -version = "0.3.0" +version = "0.4.0" dependencies = [ "crossterm", "defmt 0.3.100", @@ -484,7 +484,7 @@ dependencies = [ [[package]] name = "hsmc-macros" -version = "0.3.0" +version = "0.4.0" dependencies = [ "hsmc", "proc-macro2", @@ -495,7 +495,7 @@ dependencies = [ [[package]] name = "hsmc-verification" -version = "0.3.0" +version = "0.4.0" dependencies = [ "creusot-std", "hsmc", diff --git a/Cargo.toml b/Cargo.toml index 5f4859e..85e8bae 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -3,7 +3,7 @@ resolver = "2" members = ["hsmc", "hsmc-macros", "verification"] [workspace.package] -version = "0.3.0" +version = "0.4.0" edition = "2021" license = "MIT OR Apache-2.0" authors = ["Stephen Waits "] diff --git a/README.md b/README.md index dd81297..9cbcae1 100644 --- a/README.md +++ b/README.md @@ -40,14 +40,22 @@ statechart! { - **`m.run().await` is the whole task body.** Races active durings, the external event channel, and timer deadlines. The MCU sleeps between events (embassy's cooperative executor parks all futures). +- **Unified observability.** One observation per atom of execution + fans out at compile time to a journal (`Vec`) and/or + textual trace backends (`defmt`, `log`, `tracing`) — they share a + single vocabulary, so they cannot diverge. With no sink feature on, + every site expands to `()` (zero overhead). See + [Observability](#observability--one-journal-multiple-outputs). - **Deterministic + mechanically verified.** The `journal` feature records every action, transition, timer, and event in order — same inputs, byte-identical journal. The runtime queue and timer table carry Pearlite specs that Creusot + Why3 + alt-ergo + z3 discharge - mechanically (`just verify`). 113 byte-equal expected-vs-actual - journal tests anchor every spec rule. -- **Backward-compatible.** Every v0.1 / v0.2 statechart compiles under - v0.3 unchanged. + mechanically (`just verify`). 159 tests pin every spec rule + (journal sequences + trace-format regression + integration). +- **Backward-compatible chart syntax.** Every v0.1 / v0.2 / v0.3 + statechart compiles under v0.4 unchanged. The 0.4 breaks are in + observability surface area only — see + [Migration](#migration-from-v03). ## How a chart behaves — the building blocks @@ -86,6 +94,7 @@ walk up to the parent and check there. Repeat. If you reach the root with no handler, the event is silently discarded. Three corollaries: + - Leaf shadows ancestor for the same trigger. - Multiple handlers in one state on the same trigger fire in declaration order; the transition (if any) fires last. @@ -143,7 +152,7 @@ in. A timer (`on(after D) => …` or `on(every D) => …`) is **armed** when its declaring state is entered, **cancelled** when that state is -exited. Descending into a child is *not* an exit, so the parent's +exited. Descending into a child is _not_ an exit, so the parent's timers keep running while you're in a child. Re-entering a state restarts its timers from zero. @@ -174,16 +183,16 @@ overwhelming majority of charts. The bet is on **simple, consistent semantics**. These features are omitted on purpose; for each, what to do instead: -| Missing feature | Use instead | -|---|---| +| Missing feature | Use instead | +| ------------------------------- | ----------------------------------------------------------------------------------------------------- | | Guard conditions on transitions | Split source into two states, or have an action `emit()` a follow-up event for the chart to branch on | -| Orthogonal / parallel regions | Two charts as two tasks connected by channels, or multiple `during:` activities in one state | -| History states | Store last child explicitly in your context; transition to it on re-entry | -| Deferred events | Handle where they arrive (drop/log if not relevant), or have producer check state | -| Internal transitions | `action(Trig) => fn;` (no transition) — exactly that | -| State-local context | All state in the root context; durings borrow disjoint fields | -| Event priorities beyond FIFO | Higher-priority events on a separate channel into a separate, faster machine | -| Runtime statechart modification | Design every variation up front as states | +| Orthogonal / parallel regions | Two charts as two tasks connected by channels, or multiple `during:` activities in one state | +| History states | Store last child explicitly in your context; transition to it on re-entry | +| Deferred events | Handle where they arrive (drop/log if not relevant), or have producer check state | +| Internal transitions | `action(Trig) => fn;` (no transition) — exactly that | +| State-local context | All state in the root context; durings borrow disjoint fields | +| Event priorities beyond FIFO | Higher-priority events on a separate channel into a separate, faster machine | +| Runtime statechart modification | Design every variation up front as states | ## Quickstart @@ -191,7 +200,7 @@ Add to `Cargo.toml`: ```toml [dependencies] -hsmc = { version = "0.3", features = ["embassy"] } # or ["tokio"] +hsmc = { version = "0.4", features = ["embassy"] } # or ["tokio"] ``` Minimal timer-only machine: @@ -327,45 +336,100 @@ into a single during that uses `select` internally. For `statechart! Foo { ... }` the macro emits: -| Item | What it is | -|---------------------------------|----------------------------------------------------------------------| -| `FooState` | Enum of every user-declared state. | -| `FooActions` | Trait with one async fn per unique action name. User implements. | -| `FooActionContext<'a>` | Wrapper passed to actions. `Deref`s to the root context. `emit()`. | -| `FooCtx<'a>` | Type alias for `FooActionContext<'a>`. | -| `Foo` | The machine itself. | -| `FooSender` | Cloneable handle for cross-task / ISR event injection. | -| `Foo::<8>::STATE_CHART` | `&'static str` ASCII tree of the hierarchy (useful for `defmt`/docs).| +| Item | What it is | +| -------------------------- | --------------------------------------------------------------------- | +| `FooState` | Enum of every user-declared state. | +| `FooActions` | Trait with one async fn per unique action name. User implements. | +| `FooActionContext<'a>` | Wrapper passed to actions. `Deref`s to the root context. `emit()`. | +| `FooCtx<'a>` | Type alias for `FooActionContext<'a>`. | +| `Foo` | The machine itself. | +| `FooSender` | Cloneable handle for cross-task / ISR event injection. | +| `Foo::<8>::STATE_CHART` | `&'static str` ASCII tree of the hierarchy (useful for `defmt`/docs). | ### Machine methods -| Method | Notes | -|-------------------------------------|------------------------------------------------------------------| -| `new(ctx)` / `new(ctx, channel)` | Construct. Under embassy, pass an `&'static Channel`. | -| `with_queue_capacity::(ctx,...)` | Custom event-queue capacity. | -| `async fn run()` | Drive the machine to completion (async features). | -| `async fn dispatch(ev)` | Push event + drain to quiescence. Same task injection. | -| `fn step(elapsed) -> Option` | One unit of work (test/polling driver). | -| `fn send(ev)` | Raw push, non-draining. For tests. | -| `sender() -> Sender` | Clone handle for other tasks / ISRs. | -| `current_state()` | The active leaf state. | -| `is_terminated()` | True after `terminate` event. | -| `has_pending_events()` | Queue non-empty. | -| `context()` / `context_mut()` | Borrow the root context. | -| `into_context(self)` | Consume, return ctx. | -| `STATE_CHART` | Const ASCII diagram. | +| Method | Notes | +| -------------------------------------- | ------------------------------------------------------ | +| `new(ctx)` / `new(ctx, channel)` | Construct. Under embassy, pass an `&'static Channel`. | +| `with_queue_capacity::(ctx,...)` | Custom event-queue capacity. | +| `async fn run()` | Drive the machine to completion (async features). | +| `async fn dispatch(ev)` | Push event + drain to quiescence. Same task injection. | +| `fn step(elapsed) -> Option` | One unit of work (test/polling driver). | +| `fn send(ev)` | Raw push, non-draining. For tests. | +| `sender() -> Sender` | Clone handle for other tasks / ISRs. | +| `current_state()` | The active leaf state. | +| `is_terminated()` | True after `terminate` event. | +| `has_pending_events()` | Queue non-empty. | +| `context()` / `context_mut()` | Borrow the root context. | +| `into_context(self)` | Consume, return ctx. | +| `STATE_CHART` | Const ASCII diagram. | ## Feature flags -| Feature | Effect | -|-----------|-------------------------------------------------------------------------| -| (default) | `no_std`, no async runtime. Drive via `step(Duration)` + `send(ev)`. | -| `tokio` | Async actions + `run()`. Targets single-thread via `LocalSet`. | -| `embassy` | Async actions + `run()`. Targets embassy's cooperative executor. `no_std`.| +| Feature | Effect | +| --------- | -------------------------------------------------------------------------- | +| (default) | `no_std`, no async runtime. Drive via `step(Duration)` + `send(ev)`. | +| `tokio` | Async actions + `run()`. Targets single-thread via `LocalSet`. | +| `embassy` | Async actions + `run()`. Targets embassy's cooperative executor. `no_std`. | `embassy` and `tokio` are mutually exclusive — enabling both is a compile error. +## Migration from v0.3 + +The 0.4 breaks are in the observability surface area only; chart +syntax and runtime API are unchanged. + +### 1. Trace prefix changed + +Trace lines (when `trace-defmt` / `trace-log` / `trace-tracing` is +enabled) now use `[statechart:Name]` instead of `[Name]`. Update any +log filters or grep patterns. The verb after the prefix is now a +single hyphenated token followed by `key=value` pairs (logfmt). + +### 2. `TraceEvent::TransitionFired` carries `reason` + +Add `reason` to any pattern matches: + +```rust +// before: +TraceEvent::TransitionFired { from, to } => … +// after: +TraceEvent::TransitionFired { from, to, reason } => … +// or, if you don't need it: +TraceEvent::TransitionFired { from, to, .. } => … +``` + +The new field carries `TransitionReason::Event { event }`, +`Timer { state, timer }`, or `Internal` so consumers can see what +triggered the transition. + +### 3. New `TraceEvent` variants + +If you `match` exhaustively on `TraceEvent`, add arms for the new +variants. Otherwise nothing changes: + +- `EnterBegan { state }` — phase begin marker pairs with `Entered`. +- `ExitBegan { state }` — phase begin marker pairs with `Exited`. +- `TransitionComplete { from, to }` — pairs with `TransitionFired`. +- `EventReceived { event }` — fires when an event is popped from the + queue, before handler search. + +These are pure observation — no runtime semantic change. + +### 4. `trace;` keyword is a no-op + +Charts that declared `trace;` continue to compile. The keyword no +longer gates emission — observation is now controlled purely by +which `trace-*` cargo feature you enable. You can leave `trace;` in +or remove it; both work. + +### 5. Trace backends are no longer mutually exclusive + +Previously, enabling more than one of `trace-defmt` / `trace-log` / +`trace-tracing` was a compile error. Now they fan out independently: +turn on whichever you want. + ## Migration from v0.1 v0.1 statecharts continue to compile. New features are purely additive: @@ -442,12 +506,12 @@ async fn radio_task(lora: LoRaDriver, ch: &'static RadioChan) { ## Examples -| Example | Purpose | -|--------------------|---------------------------------------------------------------------| -| `microwave` | Full-feature pure-event machine: entry/exit, timers, emit, terminate.| -| `microwave_tui` | TUI variant of microwave. | -| `during_radio` | `during:` activities simulating a radio task with RX + TX loops. | -| `embassy_full` | Embassy feature demonstration. | +| Example | Purpose | +| --------------- | --------------------------------------------------------------------- | +| `microwave` | Full-feature pure-event machine: entry/exit, timers, emit, terminate. | +| `microwave_tui` | TUI variant of microwave. | +| `during_radio` | `during:` activities simulating a radio task with RX + TX loops. | +| `embassy_full` | Embassy feature demonstration. | Run `cargo run --example during_radio --features tokio` to see the `during:` pattern end-to-end. @@ -469,12 +533,81 @@ gets to a green proof in one command. See [`verification/INVARIANTS.md`](verification/INVARIANTS.md) for the spec-rule → proof mapping. -The `journal` Cargo feature gives you a deterministic execution -trace of every action, transition, timer arm/cancel/fire, queued -emit, event delivery, and termination. Same chart + same events = -byte-identical journal. 113 byte-equal expected-vs-actual journal -tests anchor every spec rule. `cargo mutants` runs cleanly with -0 missed mutants under `--features tokio,journal`. +Beyond Creusot, the suite includes: + +- **159 integration tests** — full chart behavior, byte-equal expected- + vs-actual journals for ~113 deterministic-flow tests, plus 11 trace- + format regression tests pinning every observation verb's exact + textual rendering. +- **0 missed mutants** under `cargo mutants --features + tokio,journal,trace-log`. +- **Miri**: 68 tests, no UB. + +## Observability — one journal, multiple outputs + +Every chart emits a single observation per atom of execution. That +observation fans out to whichever sinks you compile in: + +| Feature | Sink | +| --------------- | -------------------------------------------------------- | +| `journal` | In-memory `Vec` (replay, byte-deterministic) | +| `trace-defmt` | `defmt::*` log lines | +| `trace-log` | `log::*` log lines | +| `trace-tracing` | `tracing::*` events with structured fields | + +With **no** sink feature on, observation is fully elided at compile +time — zero overhead. Multiple sinks can be enabled simultaneously; +the journal IS the observation stream and trace backends are textual +renderings of it, so they cannot diverge. + +The textual format is logfmt-style — greppable and regex-parseable: + +``` +[statechart:Microwave] started chart_hash=0xa1b2c3d4 +[statechart:Microwave] entering state=Idle +[statechart:Microwave] action state=Idle action=clear_display kind=entry +[statechart:Microwave] timer-armed state=Idle timer=t0 duration_ns=5000000000 +[statechart:Microwave] during-started state=Idle during=poll_sensor +[statechart:Microwave] entered state=Idle +[statechart:Microwave] event-received name=StartButton +[statechart:Microwave] event-delivered name=StartButton handler=Idle +[statechart:Microwave] transition-begin from=Idle to=Heating reason=event:StartButton +[statechart:Microwave] exiting state=Idle +[statechart:Microwave] timer-cancelled state=Idle timer=t0 +[statechart:Microwave] during-cancelled state=Idle during=poll_sensor +[statechart:Microwave] action state=Idle action=stop_motor kind=exit +[statechart:Microwave] exited state=Idle +[statechart:Microwave] entering state=Heating +[statechart:Microwave] entered state=Heating +[statechart:Microwave] transition-complete from=Idle to=Heating +``` + +### The verb vocabulary + +Twenty verbs cover every `TraceEvent` variant. Begin/end markers +bracket entry, exit, and transition phases so the actions, timers, +and durings running inside each phase are visible. + +| Verb | Fires when | +|---|---| +| `started` | First step of a chart's life — carries `chart_hash` | +| `entering` / `entered` | Begin / end of a state's entry phase | +| `exiting` / `exited` | Begin / end of a state's exit phase | +| `action` | An action fn was called — `kind=entry\|exit\|handler` | +| `during-started` / `during-cancelled` | A `during:` activity started / was dropped | +| `transition-begin` / `transition-complete` | Begin / end of a transition's exit-then-enter sequence | +| `event-received` | An event was popped from the queue | +| `event-delivered` | A handler ran for the event | +| `event-dropped` | The event reached root with no handler | +| `emit-queued` / `emit-failed` | `emit()` from inside an action — queued or rejected | +| `timer-armed` / `timer-cancelled` / `timer-fired` | Timer lifecycle | +| `terminate-requested` | `terminate(...)` event matched, exit chain about to run | +| `terminated` | Chart finished (always last) | + +The `reason=` field on `transition-begin` records what triggered the +transition: an event (`event:VariantName`), a timer +(`timer:State/timer-id`), or `internal`. Real-life captures can be +diffed against expected behavior the same way the journal can. ## Status @@ -484,6 +617,12 @@ tests anchor every spec rule. `cargo mutants` runs cleanly with - v0.3: `journal` feature + deterministic trace + replay; root state targetable by chart name; Creusot verification of the runtime data structures; 113-test deterministic-flow suite. +- v0.4: unified observation pipeline (journal + trace share one + vocabulary, fan out to multiple sinks at compile time); logfmt- + style trace format with `[statechart:Name]` prefix; transition + reasons; entry/exit/transition begin/end markers; multiple trace + backends now compose; chart-level `trace;` keyword deprecated. + Breaking on the `TraceEvent` enum shape; chart syntax unchanged. - Out of scope (deliberate): guard conditions, orthogonal/parallel regions, history states, deferred events, internal transitions, state-local context, event priorities beyond FIFO, runtime diff --git a/docs/002. hsmc-semantics-formal.md b/docs/002. hsmc-semantics-formal.md index 3ae05e5..4b43c73 100644 --- a/docs/002. hsmc-semantics-formal.md +++ b/docs/002. hsmc-semantics-formal.md @@ -217,6 +217,16 @@ So a full transition reads top-to-bottom as: cancel durings on the way out → run exits on the way out → run entries on the way in → start durings on the way in. +Observers (the journal and any active trace backend) see this as +phase **begin** and **end** markers bracketing the work: an +`EnterBegan { state }` fires before any of that state's entry actions / +timer arms / during starts, and an `Entered { state }` fires after +all of them finish. The same for `ExitBegan` / `Exited`, and +`TransitionFired` / `TransitionComplete` bracket the whole exit-then- +enter sequence of a transition. This is purely a visibility change — +the operational rules above are unchanged — but it lets you tell from +a captured trace which atoms ran inside which phase. + --- ## `emit()` — sending events from inside an action diff --git a/hsmc-macros/src/codegen.rs b/hsmc-macros/src/codegen.rs index d7acb27..171ab40 100644 --- a/hsmc-macros/src/codegen.rs +++ b/hsmc-macros/src/codegen.rs @@ -88,22 +88,6 @@ fn compute_chart_hash(ir: &Ir) -> u64 { h } -/// Emit a single trace call routed through the hsmc-internal dispatcher -/// (`::hsmc::__chart_trace!`), or nothing if the chart didn't declare -/// `trace;`. The dispatcher picks the actual backend (defmt / log / -/// tracing / no-op) based on which `hsmc/trace-*` cargo feature the -/// user enabled in their `Cargo.toml` — no extra wiring required. -/// -/// Zero-overhead when `trace_enabled` is false: generates an empty -/// TokenStream so the compiler sees no extra work at the call site. -fn emit_trace_call(trace_enabled: bool, args: TokenStream) -> TokenStream { - if trace_enabled { - quote! { ::hsmc::__chart_trace!(#args); } - } else { - TokenStream::new() - } -} - /// For each user-declared leaf state that has one or more `during:` activities /// active (either declared on it, on any ancestor, or on root), return its /// state id and the flattened list of durings in leaf-first order. Durings @@ -533,15 +517,29 @@ pub fn generate(ir: &Ir) -> TokenStream { }) .collect(); - // Per-id name lookups, only emitted when the chart opted into tracing. - // Chart-name string is reused at every trace site as a literal. + // ── Per-id name lookup tables ───────────────────────────────────── + // + // Generated unconditionally at chart scope so any code in the + // emitted module (machine impl, action context, etc.) can resolve + // a u16 id to a `&'static str`. The tables are dead-code-eliminated + // when no observation feature is on: with neither `journal` nor any + // `trace-*` feature enabled, the `__chart_observe!` macro arms are + // empty, so the call sites never reference these helpers and the + // linker drops them. Marked `dead_code` to silence rustc when off. let chart_name_lit = ir.name.to_string(); + let state_name_arms: Vec<_> = ir .states .iter() .map(|s| { let sid = s.id; - let nm = s.name.to_string(); + let nm = if s.parent.is_none() { + // Synthesized root: render as the chart name (per spec + // the root state IS the chart). + ir.name.to_string() + } else { + s.name.to_string() + }; quote! { #sid => #nm, } }) .collect(); @@ -555,174 +553,357 @@ pub fn generate(ir: &Ir) -> TokenStream { quote! { #aid => #nm, } }) .collect(); - let trace_helpers = if ir.trace_enabled { - quote! { - #[inline(always)] - #[doc(hidden)] - fn __state_name(sid: u16) -> &'static str { - match sid { - #(#state_name_arms)* - _ => "", - } - } - #[inline(always)] - #[doc(hidden)] - fn __action_name(aid: u16) -> &'static str { - match aid { - #(#action_name_arms)* - _ => "", - } + let event_name_arms: Vec<_> = ir + .event_variants + .iter() + .enumerate() + .map(|(i, v)| { + let eid = i as u16; + let nm = v.name.to_string(); + quote! { #eid => #nm, } + }) + .collect(); + let timer_name_arms: Vec<_> = ir + .duration_triggers + .iter() + .enumerate() + .map(|(i, d)| { + let tid = i as u16; + // The intern key looks like ":::". For + // human readability render the expr text — fall back to + // numeric id if the key parses oddly. + let label = format!("t{}", tid); + // Try to extract the expression body so the trace shows + // something like `Duration::from_secs(5)`. Using `key` as + // a stable label is OK for now; the expr token stream isn't + // round-tripped through `to_string()` cleanly across rustc + // versions, so prefer a synthesized short name. + let _ = &d.key; // mark used for non-warn + quote! { #tid => #label, } + }) + .collect(); + // Per-(state, during-index) name lookup. The during's fn-name is + // the closest thing to a stable identifier the user wrote. + let during_name_arms: Vec<_> = { + let mut arms = Vec::new(); + for s in &ir.states { + let sid = s.id; + for (di, d) in s.durings.iter().enumerate() { + let did = di as u16; + let nm = d.fn_name.to_string(); + arms.push(quote! { (#sid, #did) => #nm, }); } } - } else { - TokenStream::new() + arms }; + // Pre-rendered transition reason strings for trace output. + // `event:` for event-driven transitions. + let event_reason_str_arms: Vec<_> = ir + .event_variants + .iter() + .enumerate() + .map(|(i, v)| { + let eid = i as u16; + let s = format!("event:{}", v.name); + quote! { #eid => #s, } + }) + .collect(); + // `timer:/` for timer-driven transitions. We + // enumerate (state, timer) pairs that actually occur. + let timer_reason_str_arms: Vec<_> = { + let mut arms = Vec::new(); + for s in &ir.states { + for &tid in &s.owned_timers { + let sid = s.id; + let sname = if s.parent.is_none() { + ir.name.to_string() + } else { + s.name.to_string() + }; + let tlabel = format!("t{}", tid); + let s_str = format!("timer:{}/{}", sname, tlabel); + arms.push(quote! { (#sid, #tid) => #s_str, }); + } + } + arms + }; + + let name_helpers = quote! { + #[allow(dead_code)] + #[doc(hidden)] + #[inline] + fn __state_name(sid: u16) -> &'static str { + match sid { + #(#state_name_arms)* + _ => "", + } + } + #[allow(dead_code)] + #[doc(hidden)] + #[inline] + fn __action_name(aid: u16) -> &'static str { + match aid { + #(#action_name_arms)* + _ => "", + } + } + #[allow(dead_code, unreachable_patterns)] + #[doc(hidden)] + #[inline] + fn __event_name(eid: u16) -> &'static str { + match eid { + #(#event_name_arms)* + _ => "", + } + } + #[allow(dead_code, unreachable_patterns)] + #[doc(hidden)] + #[inline] + fn __timer_name(tid: u16) -> &'static str { + match tid { + #(#timer_name_arms)* + _ => "", + } + } + #[allow(dead_code, unreachable_patterns, unused_variables)] + #[doc(hidden)] + #[inline] + fn __during_name(sid: u16, did: u16) -> &'static str { + match (sid, did) { + #(#during_name_arms)* + _ => "", + } + } + #[allow(dead_code, unreachable_patterns)] + #[doc(hidden)] + #[inline] + fn __event_reason_str(eid: u16) -> &'static str { + match eid { + #(#event_reason_str_arms)* + _ => "event:?", + } + } + #[allow(dead_code, unreachable_patterns, unused_variables)] + #[doc(hidden)] + #[inline] + fn __timer_reason_str(sid: u16, tid: u16) -> &'static str { + match (sid, tid) { + #(#timer_reason_str_arms)* + _ => "timer:?", + } + } + #[allow(dead_code)] + #[doc(hidden)] + #[inline] + fn __from_name(opt: Option) -> &'static str { + match opt { + Some(id) => __state_name(id), + None => "", + } + } + }; + // ── Observation hook snippets ───────────────────────────────────── // - // Trace and journal want the same call sites: enter, exit, action, - // transition. We emit a single `observe_*` snippet per site that - // contains BOTH the trace call (gated on `ir.trace_enabled` at - // parse time, may also be no-op'd by the trace-* feature gate) and - // the journal call (gated on the `journal` cargo feature inside the - // macro). Either gate independently produces zero overhead when off. + // Each snippet emits ONE `__chart_observe!` invocation. The macro + // dispatches per-variant to whichever sinks (journal + trace-*) are + // enabled at compile time. Trace and journal share the same call + // sites by construction — they cannot diverge. // - // Journal-only sites (timers, durings, emits, event dispatch, - // termination) get plain `journal_*` snippets — trace doesn't have - // a string format for them. - - // Trace-side primitives, recreated here so each observe_* snippet - // can splice them in. - let trace_enter_call = emit_trace_call( - ir.trace_enabled, - quote! { enter #chart_name_lit, Self::__state_name(sid) }, - ); - let trace_exit_call = emit_trace_call( - ir.trace_enabled, - quote! { exit #chart_name_lit, Self::__state_name(sid) }, - ); - let trace_action_call = emit_trace_call( - ir.trace_enabled, - quote! { action #chart_name_lit, Self::__action_name(aid) }, - ); - let trace_transition_call = emit_trace_call( - ir.trace_enabled, - quote! { - transition #chart_name_lit, - self.current.map(Self::__state_name).unwrap_or(""), - Self::__state_name(target) - }, - ); + // Names (state/action/event/timer/during) are passed as runtime + // lookups against the small static tables generated above. With no + // sink feature on, the macro arm body is empty and the lookup is + // never expanded — zero overhead at the call site. let observe_started = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::Started { chart_hash: Self::CHART_HASH } + ::hsmc::__chart_observe!( + Started, + &mut self.__journal, + #chart_name_lit, + Self::CHART_HASH + ); + }; + let observe_enter_began = quote! { + ::hsmc::__chart_observe!( + EnterBegan, + &mut self.__journal, + #chart_name_lit, + sid, + __state_name(sid) ); }; let observe_entered = quote! { - #trace_enter_call - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::Entered { state: sid } + ::hsmc::__chart_observe!( + Entered, + &mut self.__journal, + #chart_name_lit, + sid, + __state_name(sid) + ); + }; + let observe_exit_began = quote! { + ::hsmc::__chart_observe!( + ExitBegan, + &mut self.__journal, + #chart_name_lit, + sid, + __state_name(sid) ); }; let observe_exited = quote! { - #trace_exit_call - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::Exited { state: sid } + ::hsmc::__chart_observe!( + Exited, + &mut self.__journal, + #chart_name_lit, + sid, + __state_name(sid) ); }; let observe_action_entry = quote! { - #trace_action_call - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::ActionInvoked { - state: sid, - action: aid, - kind: ::hsmc::ActionKind::Entry, - } + ::hsmc::__chart_observe!( + ActionInvoked, + &mut self.__journal, + #chart_name_lit, + sid, __state_name(sid), + aid, __action_name(aid), + Entry ); }; let observe_action_exit = quote! { - #trace_action_call - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::ActionInvoked { - state: sid, - action: aid, - kind: ::hsmc::ActionKind::Exit, - } + ::hsmc::__chart_observe!( + ActionInvoked, + &mut self.__journal, + #chart_name_lit, + sid, __state_name(sid), + aid, __action_name(aid), + Exit ); }; let observe_action_handler = quote! { - #trace_action_call - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::ActionInvoked { - state: __handler_state, - action: aid, - kind: ::hsmc::ActionKind::Handler, - } + ::hsmc::__chart_observe!( + ActionInvoked, + &mut self.__journal, + #chart_name_lit, + __handler_state, __state_name(__handler_state), + aid, __action_name(aid), + Handler ); }; - let observe_transition = quote! { - #trace_transition_call - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::TransitionFired { - from: self.current, - to: target, - } + // TransitionFired — three call-site flavours. Codegen splices in + // the appropriate one based on what triggered the transition. + let observe_transition_fired_event = quote! { + ::hsmc::__chart_observe!( + TransitionFired, + &mut self.__journal, + #chart_name_lit, + self.current, __from_name(self.current), + target, __state_name(target), + ::hsmc::TransitionReason::Event { event: __ev_id }, + __event_reason_str(__ev_id) + ); + }; + let observe_transition_fired_timer = quote! { + ::hsmc::__chart_observe!( + TransitionFired, + &mut self.__journal, + #chart_name_lit, + self.current, __from_name(self.current), + target, __state_name(target), + ::hsmc::TransitionReason::Timer { + state: __t_state, + timer: __t_trigger, + }, + __timer_reason_str(__t_state, __t_trigger) + ); + }; + #[allow(dead_code)] + let _observe_transition_fired_internal = quote! { + ::hsmc::__chart_observe!( + TransitionFired, + &mut self.__journal, + #chart_name_lit, + self.current, __from_name(self.current), + target, __state_name(target), + ::hsmc::TransitionReason::Internal, + "internal" + ); + }; + let observe_transition_complete = quote! { + ::hsmc::__chart_observe!( + TransitionComplete, + &mut self.__journal, + #chart_name_lit, + __t_complete_from, __from_name(__t_complete_from), + target, __state_name(target) + ); + }; + let observe_event_received = quote! { + ::hsmc::__chart_observe!( + EventReceived, + &mut self.__journal, + #chart_name_lit, + __ev_id, + __event_name(__ev_id) ); }; let observe_event_delivered = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::EventDelivered { - handler_state: __handler_state, - event: __ev_id, - } + ::hsmc::__chart_observe!( + EventDelivered, + &mut self.__journal, + #chart_name_lit, + __ev_id, __event_name(__ev_id), + __handler_state, __state_name(__handler_state) ); }; let observe_event_dropped = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::EventDropped { event: __ev_id } + ::hsmc::__chart_observe!( + EventDropped, + &mut self.__journal, + #chart_name_lit, + __ev_id, __event_name(__ev_id) ); }; let observe_timer_armed = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::TimerArmed { - state: sid, - timer: tid, - ns: __duration_for(tid).as_nanos() as u64, - } + ::hsmc::__chart_observe!( + TimerArmed, + &mut self.__journal, + #chart_name_lit, + sid, __state_name(sid), + tid, __timer_name(tid), + __duration_for(tid).as_nanos() as u64 ); }; let observe_timer_cancelled = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::TimerCancelled { state: sid, timer: tid } + ::hsmc::__chart_observe!( + TimerCancelled, + &mut self.__journal, + #chart_name_lit, + sid, __state_name(sid), + tid, __timer_name(tid) ); }; let observe_timer_fired = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::TimerFired { state: __t_state, timer: __t_trigger } + ::hsmc::__chart_observe!( + TimerFired, + &mut self.__journal, + #chart_name_lit, + __t_state, __state_name(__t_state), + __t_trigger, __timer_name(__t_trigger) ); }; let observe_terminated = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::Terminated + ::hsmc::__chart_observe!( + Terminated, + &mut self.__journal, + #chart_name_lit ); }; let observe_terminate_requested = quote! { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::TerminateRequested { event: __ev_id } + ::hsmc::__chart_observe!( + TerminateRequested, + &mut self.__journal, + #chart_name_lit, + __ev_id, __event_name(__ev_id) ); }; @@ -741,9 +922,12 @@ pub fn generate(ir: &Ir) -> TokenStream { let __dn = Self::__durings_count(sid); let mut __di: u16 = 0; while __di < __dn { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::DuringStarted { state: sid, during: __di } + ::hsmc::__chart_observe!( + DuringStarted, + &mut self.__journal, + #chart_name_lit, + sid, __state_name(sid), + __di, __during_name(sid, __di) ); __di += 1; } @@ -752,9 +936,12 @@ pub fn generate(ir: &Ir) -> TokenStream { let __dn = Self::__durings_count(sid); let mut __di: u16 = 0; while __di < __dn { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::DuringCancelled { state: sid, during: __di } + ::hsmc::__chart_observe!( + DuringCancelled, + &mut self.__journal, + #chart_name_lit, + sid, __state_name(sid), + __di, __during_name(sid, __di) ); __di += 1; } @@ -1766,14 +1953,18 @@ pub fn generate(ir: &Ir) -> TokenStream { let __ev_id = __event_to_id(&event); let __result = self.__queue.push(event); if __result.is_ok() { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::EmitQueued { event: __ev_id } + ::hsmc::__chart_observe!( + EmitQueued, + &mut *self.__journal, + #chart_name_lit, + __ev_id, __event_name(__ev_id) ); } else { - ::hsmc::__chart_journal!( - self.__journal, - ::hsmc::TraceEvent::EmitFailed { event: __ev_id } + ::hsmc::__chart_observe!( + EmitFailed, + &mut *self.__journal, + #chart_name_lit, + __ev_id, __event_name(__ev_id) ); } __result @@ -1807,6 +1998,8 @@ pub fn generate(ir: &Ir) -> TokenStream { const __DEPTH: [u8; #n_states] = [#(#depth_table),*]; const __DEFAULT_CHILD: [Option; #n_states] = [#(#default_child_table),*]; + #name_helpers + #[allow(dead_code, unreachable_patterns)] fn __state_id_to_public(id: u16) -> #state_enum_name { match id { @@ -2016,13 +2209,13 @@ pub fn generate(ir: &Ir) -> TokenStream { } if let Some(ev) = self.queue.pop_front() { + let __ev_id = __event_to_id(&ev); + #observe_event_received if matches!(__check_terminate(&ev), TerminateCheck::Yes) { - let __ev_id = __event_to_id(&ev); #observe_terminate_requested self.do_terminate(); return None; } - let __ev_id = __event_to_id(&ev); if __ev_id != u16::MAX { let mut __cur = self.current; let mut __delivered = false; @@ -2030,7 +2223,10 @@ pub fn generate(ir: &Ir) -> TokenStream { if let Some((actions, target)) = __handler_lookup(s, 0, __ev_id) { let __handler_state = s; #observe_event_delivered - self.run_handlers(s, actions, target, Some(&ev)); + self.run_handlers( + s, actions, target, Some(&ev), + 1u8, __ev_id, 0u16, + ); __delivered = true; break; } @@ -2077,13 +2273,13 @@ pub fn generate(ir: &Ir) -> TokenStream { } if let Some(ev) = self.queue.pop_front() { + let __ev_id = __event_to_id(&ev); + #observe_event_received if matches!(__check_terminate(&ev), TerminateCheck::Yes) { - let __ev_id = __event_to_id(&ev); #observe_terminate_requested self.do_terminate().await; return None; } - let __ev_id = __event_to_id(&ev); if __ev_id != u16::MAX { let mut __cur = self.current; let mut __delivered = false; @@ -2091,7 +2287,10 @@ pub fn generate(ir: &Ir) -> TokenStream { if let Some((actions, target)) = __handler_lookup(s, 0, __ev_id) { let __handler_state = s; #observe_event_delivered - self.run_handlers(s, actions, target, Some(&ev)).await; + self.run_handlers( + s, actions, target, Some(&ev), + 1u8, __ev_id, 0u16, + ).await; __delivered = true; break; } @@ -2145,14 +2344,21 @@ pub fn generate(ir: &Ir) -> TokenStream { Ok(()) } + // Reason kind passed by callers to `run_handlers`: + // 1 → event-driven (reason_a = event id) + // 2 → timer-driven (reason_a = state id, reason_b = timer id) + // 0 → internal/other (unused today; reserved) #[cfg(not(any(feature = "tokio", feature = "embassy")))] - #[allow(unused_variables)] + #[allow(unused_variables, clippy::too_many_arguments)] fn run_handlers( &mut self, source_state: u16, actions: &'static [u16], target: Option, event: Option<&#ev_ty>, + __reason_kind: u8, + __reason_a: u16, + __reason_b: u16, ) { let __handler_state = source_state; for &aid in actions { @@ -2160,19 +2366,36 @@ pub fn generate(ir: &Ir) -> TokenStream { self.run_action(aid, event); if self.terminated { return; } } - if let Some(tgt) = target { - self.transition(source_state, tgt); + if let Some(target) = target { + match __reason_kind { + 1 => { + let __ev_id = __reason_a; + #observe_transition_fired_event + } + 2 => { + let __t_state = __reason_a; + let __t_trigger = __reason_b; + #observe_transition_fired_timer + } + _ => {} + } + let __t_complete_from = self.current; + self.transition(source_state, target); + #observe_transition_complete } } #[cfg(any(feature = "tokio", feature = "embassy"))] - #[allow(unused_variables)] + #[allow(unused_variables, clippy::too_many_arguments)] async fn run_handlers( &mut self, source_state: u16, actions: &'static [u16], target: Option, event: Option<&#ev_ty>, + __reason_kind: u8, + __reason_a: u16, + __reason_b: u16, ) { let __handler_state = source_state; for &aid in actions { @@ -2180,8 +2403,22 @@ pub fn generate(ir: &Ir) -> TokenStream { self.run_action(aid, event).await; if self.terminated { return; } } - if let Some(tgt) = target { - self.transition(source_state, tgt).await; + if let Some(target) = target { + match __reason_kind { + 1 => { + let __ev_id = __reason_a; + #observe_transition_fired_event + } + 2 => { + let __t_state = __reason_a; + let __t_trigger = __reason_b; + #observe_transition_fired_timer + } + _ => {} + } + let __t_complete_from = self.current; + self.transition(source_state, target).await; + #observe_transition_complete } } @@ -2272,7 +2509,6 @@ pub fn generate(ir: &Ir) -> TokenStream { #[cfg(not(any(feature = "tokio", feature = "embassy")))] fn transition(&mut self, _source_matched_state: u16, target: u16) { - #observe_transition if Self::is_up_transition(self.current, target) { if let Some(mut cur) = self.current { while cur != target { @@ -2319,7 +2555,6 @@ pub fn generate(ir: &Ir) -> TokenStream { #[cfg(any(feature = "tokio", feature = "embassy"))] async fn transition(&mut self, _source_matched_state: u16, target: u16) { - #observe_transition if Self::is_up_transition(self.current, target) { if let Some(mut cur) = self.current { while cur != target { @@ -2394,7 +2629,7 @@ pub fn generate(ir: &Ir) -> TokenStream { #[cfg(not(any(feature = "tokio", feature = "embassy")))] #[allow(unused_variables)] fn enter_state_no_descent(&mut self, sid: u16) { - #observe_entered + #observe_enter_began let entries = Self::entries_of(sid); for &aid in entries { #observe_action_entry @@ -2408,12 +2643,13 @@ pub fn generate(ir: &Ir) -> TokenStream { } self.current = Some(sid); #observe_durings_started + #observe_entered } #[cfg(any(feature = "tokio", feature = "embassy"))] #[allow(unused_variables)] async fn enter_state_no_descent(&mut self, sid: u16) { - #observe_entered + #observe_enter_began let entries = Self::entries_of(sid); for &aid in entries { #observe_action_entry @@ -2427,6 +2663,7 @@ pub fn generate(ir: &Ir) -> TokenStream { } self.current = Some(sid); #observe_durings_started + #observe_entered } #[cfg(not(any(feature = "tokio", feature = "embassy")))] @@ -2451,7 +2688,9 @@ pub fn generate(ir: &Ir) -> TokenStream { #[allow(unused_variables)] fn exit_state(&mut self, sid: u16) { // Per spec §"Entry and exit ordering": - // 1. cancel durings 2. cancel timers 3. exit actions 4. Exited + // 1. ExitBegan 2. cancel durings 3. cancel timers + // 4. exit actions 5. Exited + #observe_exit_began #observe_durings_cancelled for &tid in __owned_timers(sid) { #observe_timer_cancelled @@ -2469,6 +2708,7 @@ pub fn generate(ir: &Ir) -> TokenStream { #[cfg(any(feature = "tokio", feature = "embassy"))] #[allow(unused_variables)] async fn exit_state(&mut self, sid: u16) { + #observe_exit_began #observe_durings_cancelled for &tid in __owned_timers(sid) { #observe_timer_cancelled @@ -2504,8 +2744,6 @@ pub fn generate(ir: &Ir) -> TokenStream { } } - #trace_helpers - #[cfg(not(any(feature = "tokio", feature = "embassy")))] fn do_terminate(&mut self) { if let Some(mut cur) = self.current { @@ -2543,15 +2781,15 @@ pub fn generate(ir: &Ir) -> TokenStream { #[cfg(not(any(feature = "tokio", feature = "embassy")))] fn dispatch_trigger(&mut self, state: u16, kind: u8, trig: u16) { if let Some((actions, target)) = __handler_lookup(state, kind, trig) { - // Timer-driven dispatch: no event payload in scope. - self.run_handlers(state, actions, target, None); + // Timer-driven dispatch: no event payload, reason = timer. + self.run_handlers(state, actions, target, None, 2u8, state, trig); } } #[cfg(any(feature = "tokio", feature = "embassy"))] async fn dispatch_trigger(&mut self, state: u16, kind: u8, trig: u16) { if let Some((actions, target)) = __handler_lookup(state, kind, trig) { - self.run_handlers(state, actions, target, None).await; + self.run_handlers(state, actions, target, None, 2u8, state, trig).await; } } } diff --git a/hsmc-macros/src/ir.rs b/hsmc-macros/src/ir.rs index 0fe5f08..e5ffb7c 100644 --- a/hsmc-macros/src/ir.rs +++ b/hsmc-macros/src/ir.rs @@ -26,10 +26,12 @@ pub struct Ir { /// Duration triggers referenced anywhere, in first-seen order. /// Each one gets a trigger id used by the timer table. pub duration_triggers: Vec, - /// True when the chart declared `trace;` at root. Codegen routes - /// trace calls to `::hsmc::__chart_trace!`, which dispatches to a - /// backend (defmt / log / tracing / no-op) based on the user's - /// `hsmc/trace-*` feature selection in their `Cargo.toml`. + /// Set when the chart declared `trace;` at root. Retained for + /// backwards-compatible parsing — the keyword no longer gates + /// observation emission. As of 0.4 every chart unconditionally + /// emits `__chart_observe!` calls, and the actual trace fan-out is + /// chosen by the user's `hsmc/trace-*` cargo feature selection. + #[allow(dead_code)] pub trace_enabled: bool, } diff --git a/hsmc-macros/tests/ui/t9_8_unknown_target.rs b/hsmc-macros/tests/ui/t9_8_unknown_target.rs index 8655345..ebac5b8 100644 --- a/hsmc-macros/tests/ui/t9_8_unknown_target.rs +++ b/hsmc-macros/tests/ui/t9_8_unknown_target.rs @@ -1,3 +1,5 @@ +#![allow(unexpected_cfgs)] + use hsmc::statechart; #[derive(Debug, Clone)] diff --git a/hsmc-macros/tests/ui/t9_8_unknown_target.stderr b/hsmc-macros/tests/ui/t9_8_unknown_target.stderr index 47d4650..24abe61 100644 --- a/hsmc-macros/tests/ui/t9_8_unknown_target.stderr +++ b/hsmc-macros/tests/ui/t9_8_unknown_target.stderr @@ -1,68 +1,13 @@ -warning: unexpected `cfg` condition value: `tokio` - --> tests/ui/t9_8_unknown_target.rs:8:1 - | - 8 | / statechart! { - 9 | | M { -10 | | context: Ctx; -11 | | events: Ev; -... | -17 | | } - | |_^ - | - = note: no expected values for `feature` - = note: using a cfg inside a macro will use the cfgs from the destination crate and not the ones from the defining crate - = help: try referring to `statechart` crate for guidance on how handle this unexpected cfg - = help: the macro `statechart` may come from an old version of the `hsmc_macros` crate, try updating your dependency with `cargo update -p hsmc_macros` - = note: see for more information about checking conditional configuration - = note: `#[warn(unexpected_cfgs)]` on by default - = note: this warning originates in the macro `statechart` (in Nightly builds, run with -Z macro-backtrace for more info) - -warning: unexpected `cfg` condition value: `embassy` - --> tests/ui/t9_8_unknown_target.rs:8:1 - | - 8 | / statechart! { - 9 | | M { -10 | | context: Ctx; -11 | | events: Ev; -... | -17 | | } - | |_^ - | - = note: no expected values for `feature` - = note: using a cfg inside a macro will use the cfgs from the destination crate and not the ones from the defining crate - = help: try referring to `statechart` crate for guidance on how handle this unexpected cfg - = help: the macro `statechart` may come from an old version of the `hsmc_macros` crate, try updating your dependency with `cargo update -p hsmc_macros` - = note: see for more information about checking conditional configuration - = note: this warning originates in the macro `statechart` (in Nightly builds, run with -Z macro-backtrace for more info) - -warning: unexpected `cfg` condition value: `journal` - --> tests/ui/t9_8_unknown_target.rs:8:1 - | - 8 | / statechart! { - 9 | | M { -10 | | context: Ctx; -11 | | events: Ev; -... | -17 | | } - | |_^ - | - = note: no expected values for `feature` - = note: using a cfg inside a macro will use the cfgs from the destination crate and not the ones from the defining crate - = help: try referring to `statechart` crate for guidance on how handle this unexpected cfg - = help: the macro `statechart` may come from an old version of the `hsmc_macros` crate, try updating your dependency with `cargo update -p hsmc_macros` - = note: see for more information about checking conditional configuration - = note: this warning originates in the macro `statechart` (in Nightly builds, run with -Z macro-backtrace for more info) - error[E0046]: not all trait items implemented, missing: `NonExistent` - --> tests/ui/t9_8_unknown_target.rs:19:1 + --> tests/ui/t9_8_unknown_target.rs:21:1 | - 8 | / statechart! { - 9 | | M { -10 | | context: Ctx; -11 | | events: Ev; +10 | / statechart! { +11 | | M { +12 | | context: Ctx; +13 | | events: Ev; ... | -17 | | } +19 | | } | |_- `NonExistent` from trait -18 | -19 | impl MActions for MActionContext<'_> {} +20 | +21 | impl MActions for MActionContext<'_> {} | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ missing `NonExistent` in implementation diff --git a/hsmc/Cargo.toml b/hsmc/Cargo.toml index 8ebc1a3..baed509 100644 --- a/hsmc/Cargo.toml +++ b/hsmc/Cargo.toml @@ -17,25 +17,30 @@ exclude = ["examples/microwave_tui.rs"] default = [] tokio = ["dep:tokio"] embassy = ["dep:embassy-sync", "dep:embassy-time", "dep:embassy-futures"] -# Auto-tracing backends — pick at most one. When the user opts a chart -# into `trace;`, the macro emits calls to an internal dispatcher that -# routes to whichever backend is enabled here. With NO backend feature -# enabled, `trace;` is a no-op (zero overhead). Enabling more than one -# backend produces a duplicate-macro compile error — that's intentional. +# Auto-tracing sinks — every chart emits `__chart_observe!` calls +# unconditionally; whichever of these sinks you enable is what gets +# textual log lines. Pick zero, one, or any combination — the +# observation pipeline fans out to all enabled sinks and the in-memory +# journal (below). With NO sink feature enabled, observation is fully +# elided at compile time (zero overhead). +# +# Format: `[statechart:] key=value …` (logfmt-style, +# greppable, regex-parseable). The `tracing` backend uses native +# structured fields instead of stringly key=value pairs. trace-defmt = ["dep:defmt"] trace-log = ["dep:log"] trace-tracing = ["dep:tracing"] -# Journaling backend. When enabled, the macro emits calls into an -# in-memory journal recording every observable atom: entries, exits, -# action invocations, during start/cancel, timer arm/cancel/fire, emits, -# event delivery, transitions, and termination. Used to make charts -# replay-deterministic and to catch semantic regressions in CI. +# In-memory journal sink. When enabled, every `__chart_observe!` site +# also records a `TraceEvent` into the per-machine `JournalSink`. The +# journal is the authoritative byte-deterministic atom-by-atom record +# of chart execution; trace backends are textual renderings of the +# same vocabulary. # Requires `alloc` (the journal grows dynamically). Off by default — # zero overhead and no `alloc` requirement when not enabled. journal = [] [dependencies] -hsmc-macros = { path = "../hsmc-macros", version = "0.3.0" } +hsmc-macros = { path = "../hsmc-macros", version = "0.4.0" } heapless = "0.8" tokio = { version = "1", features = ["sync", "time", "rt", "macros"], optional = true } embassy-sync = { version = "0.8", optional = true } diff --git a/hsmc/src/journal.rs b/hsmc/src/journal.rs index 1da5418..8be038e 100644 --- a/hsmc/src/journal.rs +++ b/hsmc/src/journal.rs @@ -45,6 +45,22 @@ pub enum ActionKind { Handler, } +/// Why a transition fired. Carried on `TransitionFired` so observers can +/// see *what triggered* the state change, not just that one happened. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum TransitionReason { + /// External or queued event with the given index dispatched into a + /// handler that fired this transition. + Event { event: u16 }, + /// Timer on the given (state, timer) slot expired and its handler + /// fired this transition. + Timer { state: u16, timer: u16 }, + /// Driven from inside the runtime without an originating event or + /// timer (e.g. default-descent into a child after entering a + /// composite state). Reserved; not currently emitted. + Internal, +} + /// One observable atom of chart execution. The macro emits these at every /// hook point so the full sequence can be journaled and compared. /// @@ -54,14 +70,23 @@ pub enum ActionKind { pub enum TraceEvent { /// First event in any journal. Identifies the chart definition. Started { chart_hash: u64 }, - /// A state's entry begins. Followed by `ActionInvoked{Entry}` for each - /// of that state's entry actions, then `DuringStarted` for each during - /// declared on the state, then potentially the next state's `Entered` - /// (default-descent). + /// A state's entry began. The marker is emitted before any of the + /// state's entry actions, timers, or durings have run. Followed by + /// `ActionInvoked{Entry}`, `TimerArmed`, `DuringStarted`, then the + /// matching `Entered` end marker. + EnterBegan { state: u16 }, + /// A state's entry completed. Emitted after every entry action, + /// timer arm, and during start has run for that state. Pairs with + /// the prior `EnterBegan { state }`. Entered { state: u16 }, - /// A state's exit completed. Preceded by `DuringCancelled` for each - /// during on the state, followed by `ActionInvoked{Exit}` for each - /// exit action. + /// A state's exit began. The marker is emitted before any of the + /// state's during cancellations, timer cancellations, or exit + /// actions have run. Followed by `DuringCancelled`, `TimerCancelled`, + /// `ActionInvoked{Exit}`, then the matching `Exited` end marker. + ExitBegan { state: u16 }, + /// A state's exit completed. Emitted after every during cancel, + /// timer cancel, and exit action has run for that state. Pairs with + /// the prior `ExitBegan { state }`. Exited { state: u16 }, /// An action function was called. ActionInvoked { @@ -75,14 +100,30 @@ pub enum TraceEvent { /// A `during:` activity was cancelled because its owning state is /// being exited. DuringCancelled { state: u16, during: u16 }, - /// A transition is about to fire. `from` is the innermost active state - /// at the moment the transition was triggered; `to` is the target. - /// Followed by the actual `Exited` / `Entered` / etc. events that - /// implement the transition. - TransitionFired { from: Option, to: u16 }, + /// A transition is about to fire. `from` is the innermost active + /// state at the moment the transition was triggered; `to` is the + /// target; `reason` records what caused the transition (event, + /// timer, or internal). Followed by the actual `ExitBegan`/`Exited`/ + /// `EnterBegan`/`Entered` events that implement the transition, + /// then the matching `TransitionComplete` end marker. + TransitionFired { + from: Option, + to: u16, + reason: TransitionReason, + }, + /// A transition completed. Emitted after the transition's exit and + /// entry sequences are fully done. Pairs with the prior + /// `TransitionFired { from, to, .. }`. + TransitionComplete { from: Option, to: u16 }, + /// An event was popped from the internal queue and is about to be + /// dispatched. Emitted before the handler search; followed by either + /// `EventDelivered` (handler found and ran) or `EventDropped` + /// (no handler on the active path), or `TerminateRequested` if the + /// event matches the chart's terminate declaration. + EventReceived { event: u16 }, /// An event reached a state's handler. `handler_state` is the state - /// whose handler ran (which may be an ancestor of the innermost active - /// state if the event bubbled). + /// whose handler ran (which may be an ancestor of the innermost + /// active state if the event bubbled). EventDelivered { handler_state: u16, event: u16 }, /// An event was dispatched but no state on the active path had a /// handler. Silently dropped per spec. diff --git a/hsmc/src/lib.rs b/hsmc/src/lib.rs index 76eb7fc..d4dc1d6 100644 --- a/hsmc/src/lib.rs +++ b/hsmc/src/lib.rs @@ -102,140 +102,614 @@ pub use hsmc_macros::statechart; mod error; pub use error::HsmcError; -// ── Journal (deterministic execution trace) ───────────────────────── +// ── Unified observation pipeline ──────────────────────────────────── // -// When `feature = "journal"` is enabled, the macro emits one -// [`TraceEvent`] per observable atom: entries, exits, action calls, -// during start/cancel, timer arm/cancel/fire, queued emits, event -// dispatch, transitions, termination. The events are appended to the -// machine's internal `JournalSink` so callers can compare against an -// expected sequence (see `tests/replay.rs`). +// The `statechart!` macro emits ONE `__chart_observe!` call per +// observable atom of execution — entry/exit phase begin/end markers, +// action invocations, during start/cancel, timer arm/cancel/fire, +// emit queue push/fail, event receive/deliver/drop, transition +// begin/complete, terminate-requested, and terminated. // -// When the feature is OFF, the codegen still emits `__chart_journal!` -// invocations at every hook site, but the macro expands to nothing -// (zero overhead) and `JournalSink` is a ZST so the field on the -// machine takes 0 bytes. +// `__chart_observe!` is the single dispatcher: each arm fans the +// observation out to whichever sinks are enabled at compile time: +// +// - `feature = "journal"` → push a `TraceEvent` into the +// per-machine `JournalSink`. +// - `feature = "trace-defmt"` → emit a `defmt::*` log line. +// - `feature = "trace-log"` → emit a `log::*` log line. +// - `feature = "trace-tracing"` → emit a `tracing::*` event with +// structured fields. +// +// With NO sink feature enabled, every arm body is empty and the +// macro's args are never expanded — zero runtime cost, zero binary +// growth. There is intentionally no catch-all arm: an unrecognized +// invocation produces a compile error, so codegen mismatches are +// caught loudly rather than silently dropped. +// +// Trace and journal share the same vocabulary by construction. The +// trace's textual rendering is machine-parseable (logfmt-style: +// `[statechart:Name] verb key=value …`), so a captured log can be +// diff'd against expected behavior the same way the journal can. #[cfg(feature = "journal")] mod journal; #[cfg(feature = "journal")] -pub use journal::{ActionKind, Journal, TraceEvent}; +pub use journal::{ActionKind, Journal, TraceEvent, TransitionReason}; -/// Journal call dispatcher invoked by `statechart!`-generated code. -/// Not part of the public API. +/// Internal observation dispatcher invoked by `statechart!`-generated +/// code. Not part of the public API. /// -/// Call form: `__chart_journal!(, )`. -/// The first argument is a place expression for the sink (typically -/// `self.__journal`); the second is the full `TraceEvent` value to -/// push. +/// Call form (one arm per `TraceEvent` variant): +/// `__chart_observe!(, , , )` /// -/// When the `journal` feature is off, the macro discards both arguments -/// and expands to nothing — the codegen can refer to `TraceEvent::*` -/// without the type having to exist. -#[cfg(feature = "journal")] +/// `sink-expr` is the place expression for the journal sink (typically +/// `&mut self.__journal`); `chart-literal` is the chart name as a +/// string literal. Variant args are passed positionally — see each arm +/// for the order. Names (state, action, event, timer, during) are +/// passed as `&'static str` literals at each call site so the trace +/// formatters never do a runtime lookup. +/// +/// All sink-feature gates apply *inside* each arm. With every sink +/// feature off, the arm body is empty; the macro's positional args are +/// never expanded; the call site contributes zero code. #[doc(hidden)] #[macro_export] -macro_rules! __chart_journal { - ($sink:expr, $event:expr) => { - $sink.push($event); - }; -} +macro_rules! __chart_observe { + // ── Started ──────────────────────────────────────────────────── + (Started, $sink:expr, $chart:literal, $hash:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::Started { chart_hash: $hash }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!( + "[statechart:{}] started chart_hash={=u64:#x}", + $chart, + $hash + ); + #[cfg(feature = "trace-log")] + ::log::info!("[statechart:{}] started chart_hash={:#x}", $chart, $hash); + #[cfg(feature = "trace-tracing")] + ::tracing::info!(chart = $chart, chart_hash = $hash, "started"); + }}; -/// No-op fallback for when `feature = "journal"` is disabled. -#[cfg(not(feature = "journal"))] -#[doc(hidden)] -#[macro_export] -macro_rules! __chart_journal { - ($($_:tt)*) => {}; -} + // ── EnterBegan / Entered ─────────────────────────────────────── + (EnterBegan, $sink:expr, $chart:literal, $sid:expr, $sname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::EnterBegan { state: $sid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!("[statechart:{}] entering state={}", $chart, $sname); + #[cfg(feature = "trace-log")] + ::log::info!("[statechart:{}] entering state={}", $chart, $sname); + #[cfg(feature = "trace-tracing")] + ::tracing::info!(chart = $chart, state = $sname, "entering"); + }}; + (Entered, $sink:expr, $chart:literal, $sid:expr, $sname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::Entered { state: $sid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!("[statechart:{}] entered state={}", $chart, $sname); + #[cfg(feature = "trace-log")] + ::log::info!("[statechart:{}] entered state={}", $chart, $sname); + #[cfg(feature = "trace-tracing")] + ::tracing::info!(chart = $chart, state = $sname, "entered"); + }}; -// ── Auto-tracing dispatcher ────────────────────────────────────────── -// -// When a chart opts in via `trace;`, the proc-macro emits calls to -// `::hsmc::__chart_trace!( , );` at -// every state entry, exit, action invocation, and transition. This -// crate-level macro picks the backend based on which `trace-*` cargo -// feature is enabled — exactly one of `trace-defmt` / `trace-log` / -// `trace-tracing`. With none enabled it expands to nothing. -// -// Multiple `trace-*` features enabled simultaneously produce a -// duplicate-definition compile error from rustc. Intentional. + // ── ExitBegan / Exited ───────────────────────────────────────── + (ExitBegan, $sink:expr, $chart:literal, $sid:expr, $sname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::ExitBegan { state: $sid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!("[statechart:{}] exiting state={}", $chart, $sname); + #[cfg(feature = "trace-log")] + ::log::info!("[statechart:{}] exiting state={}", $chart, $sname); + #[cfg(feature = "trace-tracing")] + ::tracing::info!(chart = $chart, state = $sname, "exiting"); + }}; + (Exited, $sink:expr, $chart:literal, $sid:expr, $sname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::Exited { state: $sid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!("[statechart:{}] exited state={}", $chart, $sname); + #[cfg(feature = "trace-log")] + ::log::info!("[statechart:{}] exited state={}", $chart, $sname); + #[cfg(feature = "trace-tracing")] + ::tracing::info!(chart = $chart, state = $sname, "exited"); + }}; -/// Internal trace dispatcher invoked by `statechart!`-generated code. -/// Not part of the public API. -#[cfg(feature = "trace-defmt")] -#[doc(hidden)] -#[macro_export] -macro_rules! __chart_trace { - (enter $chart:literal, $state:expr) => { - ::defmt::info!("[{}] enter {}", $chart, $state); - }; - (exit $chart:literal, $state:expr) => { - ::defmt::info!("[{}] exit {}", $chart, $state); - }; - (action $chart:literal, $action:expr) => { - ::defmt::trace!("[{}] action {}", $chart, $action); - }; - (transition $chart:literal, $from:expr, $to:expr) => { - ::defmt::info!("[{}] {} -> {}", $chart, $from, $to); - }; - ($($_:tt)*) => {}; -} + // ── ActionInvoked (Entry / Exit / Handler) ───────────────────── + (ActionInvoked, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $aid:expr, $aname:expr, + Entry) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::ActionInvoked { + state: $sid, + action: $aid, + kind: $crate::ActionKind::Entry, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::trace!( + "[statechart:{}] action state={} action={} kind=entry", + $chart, + $sname, + $aname + ); + #[cfg(feature = "trace-log")] + ::log::trace!( + "[statechart:{}] action state={} action={} kind=entry", + $chart, + $sname, + $aname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::trace!( + chart = $chart, + state = $sname, + action = $aname, + kind = "entry", + "action" + ); + }}; + (ActionInvoked, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $aid:expr, $aname:expr, + Exit) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::ActionInvoked { + state: $sid, + action: $aid, + kind: $crate::ActionKind::Exit, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::trace!( + "[statechart:{}] action state={} action={} kind=exit", + $chart, + $sname, + $aname + ); + #[cfg(feature = "trace-log")] + ::log::trace!( + "[statechart:{}] action state={} action={} kind=exit", + $chart, + $sname, + $aname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::trace!( + chart = $chart, + state = $sname, + action = $aname, + kind = "exit", + "action" + ); + }}; + (ActionInvoked, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $aid:expr, $aname:expr, + Handler) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::ActionInvoked { + state: $sid, + action: $aid, + kind: $crate::ActionKind::Handler, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::trace!( + "[statechart:{}] action state={} action={} kind=handler", + $chart, + $sname, + $aname + ); + #[cfg(feature = "trace-log")] + ::log::trace!( + "[statechart:{}] action state={} action={} kind=handler", + $chart, + $sname, + $aname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::trace!( + chart = $chart, + state = $sname, + action = $aname, + kind = "handler", + "action" + ); + }}; -/// Internal trace dispatcher invoked by `statechart!`-generated code. -/// Not part of the public API. -#[cfg(feature = "trace-log")] -#[doc(hidden)] -#[macro_export] -macro_rules! __chart_trace { - (enter $chart:literal, $state:expr) => { - ::log::info!("[{}] enter {}", $chart, $state); - }; - (exit $chart:literal, $state:expr) => { - ::log::info!("[{}] exit {}", $chart, $state); - }; - (action $chart:literal, $action:expr) => { - ::log::trace!("[{}] action {}", $chart, $action); - }; - (transition $chart:literal, $from:expr, $to:expr) => { - ::log::info!("[{}] {} -> {}", $chart, $from, $to); - }; - ($($_:tt)*) => {}; -} + // ── DuringStarted / DuringCancelled ──────────────────────────── + (DuringStarted, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $did:expr, $dname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::DuringStarted { + state: $sid, + during: $did, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::debug!( + "[statechart:{}] during-started state={} during={}", + $chart, + $sname, + $dname + ); + #[cfg(feature = "trace-log")] + ::log::debug!( + "[statechart:{}] during-started state={} during={}", + $chart, + $sname, + $dname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::debug!( + chart = $chart, + state = $sname, + during = $dname, + "during-started" + ); + }}; + (DuringCancelled, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $did:expr, $dname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::DuringCancelled { + state: $sid, + during: $did, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::debug!( + "[statechart:{}] during-cancelled state={} during={}", + $chart, + $sname, + $dname + ); + #[cfg(feature = "trace-log")] + ::log::debug!( + "[statechart:{}] during-cancelled state={} during={}", + $chart, + $sname, + $dname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::debug!( + chart = $chart, + state = $sname, + during = $dname, + "during-cancelled" + ); + }}; -/// Internal trace dispatcher invoked by `statechart!`-generated code. -/// Not part of the public API. -#[cfg(feature = "trace-tracing")] -#[doc(hidden)] -#[macro_export] -macro_rules! __chart_trace { - (enter $chart:literal, $state:expr) => { - ::tracing::info!(chart = $chart, state = $state, "enter"); - }; - (exit $chart:literal, $state:expr) => { - ::tracing::info!(chart = $chart, state = $state, "exit"); - }; - (action $chart:literal, $action:expr) => { - ::tracing::trace!(chart = $chart, action = $action, "action"); - }; - (transition $chart:literal, $from:expr, $to:expr) => { - ::tracing::info!(chart = $chart, from = $from, to = $to, "transition"); - }; - ($($_:tt)*) => {}; -} + // ── TransitionFired (begin marker) ───────────────────────────── + // + // The reason is rendered three ways (event:Name, timer:State/Timer, + // internal). The journal stores the structured reason and the trace + // gets a pre-rendered `&'static str` (`$rname`) so log lines stay + // simple to parse. + (TransitionFired, $sink:expr, $chart:literal, + $from:expr, $fname:expr, + $to:expr, $tname:expr, + $reason:expr, $rname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::TransitionFired { + from: $from, + to: $to, + reason: $reason, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!( + "[statechart:{}] transition-begin from={} to={} reason={}", + $chart, + $fname, + $tname, + $rname + ); + #[cfg(feature = "trace-log")] + ::log::info!( + "[statechart:{}] transition-begin from={} to={} reason={}", + $chart, + $fname, + $tname, + $rname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::info!( + chart = $chart, + from = $fname, + to = $tname, + reason = $rname, + "transition-begin" + ); + }}; -/// No-op fallback when no `trace-*` backend feature is enabled. The -/// chart's `trace;` keyword still parses; calls just expand to nothing. -#[cfg(not(any( - feature = "trace-defmt", - feature = "trace-log", - feature = "trace-tracing", -)))] -#[doc(hidden)] -#[macro_export] -macro_rules! __chart_trace { - ($($_:tt)*) => {}; + // ── TransitionComplete (end marker) ──────────────────────────── + (TransitionComplete, $sink:expr, $chart:literal, + $from:expr, $fname:expr, + $to:expr, $tname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::TransitionComplete { + from: $from, + to: $to, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!( + "[statechart:{}] transition-complete from={} to={}", + $chart, + $fname, + $tname + ); + #[cfg(feature = "trace-log")] + ::log::info!( + "[statechart:{}] transition-complete from={} to={}", + $chart, + $fname, + $tname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::info!( + chart = $chart, + from = $fname, + to = $tname, + "transition-complete" + ); + }}; + + // ── Event lifecycle ──────────────────────────────────────────── + (EventReceived, $sink:expr, $chart:literal, $eid:expr, $ename:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::EventReceived { event: $eid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::debug!("[statechart:{}] event-received name={}", $chart, $ename); + #[cfg(feature = "trace-log")] + ::log::debug!("[statechart:{}] event-received name={}", $chart, $ename); + #[cfg(feature = "trace-tracing")] + ::tracing::debug!(chart = $chart, name = $ename, "event-received"); + }}; + (EventDelivered, $sink:expr, $chart:literal, + $eid:expr, $ename:expr, + $sid:expr, $sname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::EventDelivered { + handler_state: $sid, + event: $eid, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!( + "[statechart:{}] event-delivered name={} handler={}", + $chart, + $ename, + $sname + ); + #[cfg(feature = "trace-log")] + ::log::info!( + "[statechart:{}] event-delivered name={} handler={}", + $chart, + $ename, + $sname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::info!( + chart = $chart, + name = $ename, + handler = $sname, + "event-delivered" + ); + }}; + (EventDropped, $sink:expr, $chart:literal, $eid:expr, $ename:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::EventDropped { event: $eid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::debug!("[statechart:{}] event-dropped name={}", $chart, $ename); + #[cfg(feature = "trace-log")] + ::log::debug!("[statechart:{}] event-dropped name={}", $chart, $ename); + #[cfg(feature = "trace-tracing")] + ::tracing::debug!(chart = $chart, name = $ename, "event-dropped"); + }}; + + // ── emit() outcomes ──────────────────────────────────────────── + (EmitQueued, $sink:expr, $chart:literal, $eid:expr, $ename:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::EmitQueued { event: $eid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::debug!("[statechart:{}] emit-queued event={}", $chart, $ename); + #[cfg(feature = "trace-log")] + ::log::debug!("[statechart:{}] emit-queued event={}", $chart, $ename); + #[cfg(feature = "trace-tracing")] + ::tracing::debug!(chart = $chart, event = $ename, "emit-queued"); + }}; + (EmitFailed, $sink:expr, $chart:literal, $eid:expr, $ename:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::EmitFailed { event: $eid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::warn!( + "[statechart:{}] emit-failed event={} reason=queue-full", + $chart, + $ename + ); + #[cfg(feature = "trace-log")] + ::log::warn!( + "[statechart:{}] emit-failed event={} reason=queue-full", + $chart, + $ename + ); + #[cfg(feature = "trace-tracing")] + ::tracing::warn!( + chart = $chart, + event = $ename, + reason = "queue-full", + "emit-failed" + ); + }}; + + // ── Timer lifecycle ──────────────────────────────────────────── + (TimerArmed, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $tid:expr, $tname:expr, + $ns:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::TimerArmed { + state: $sid, + timer: $tid, + ns: $ns, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::debug!( + "[statechart:{}] timer-armed state={} timer={} duration_ns={=u64}", + $chart, + $sname, + $tname, + $ns + ); + #[cfg(feature = "trace-log")] + ::log::debug!( + "[statechart:{}] timer-armed state={} timer={} duration_ns={}", + $chart, + $sname, + $tname, + $ns + ); + #[cfg(feature = "trace-tracing")] + ::tracing::debug!( + chart = $chart, + state = $sname, + timer = $tname, + duration_ns = $ns, + "timer-armed" + ); + }}; + (TimerCancelled, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $tid:expr, $tname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::TimerCancelled { + state: $sid, + timer: $tid, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::debug!( + "[statechart:{}] timer-cancelled state={} timer={}", + $chart, + $sname, + $tname + ); + #[cfg(feature = "trace-log")] + ::log::debug!( + "[statechart:{}] timer-cancelled state={} timer={}", + $chart, + $sname, + $tname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::debug!( + chart = $chart, + state = $sname, + timer = $tname, + "timer-cancelled" + ); + }}; + (TimerFired, $sink:expr, $chart:literal, + $sid:expr, $sname:expr, + $tid:expr, $tname:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::TimerFired { + state: $sid, + timer: $tid, + }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!( + "[statechart:{}] timer-fired state={} timer={}", + $chart, + $sname, + $tname + ); + #[cfg(feature = "trace-log")] + ::log::info!( + "[statechart:{}] timer-fired state={} timer={}", + $chart, + $sname, + $tname + ); + #[cfg(feature = "trace-tracing")] + ::tracing::info!( + chart = $chart, + state = $sname, + timer = $tname, + "timer-fired" + ); + }}; + + // ── Termination ──────────────────────────────────────────────── + (TerminateRequested, $sink:expr, $chart:literal, $eid:expr, $ename:expr) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::TerminateRequested { event: $eid }); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!( + "[statechart:{}] terminate-requested event={}", + $chart, + $ename + ); + #[cfg(feature = "trace-log")] + ::log::info!( + "[statechart:{}] terminate-requested event={}", + $chart, + $ename + ); + #[cfg(feature = "trace-tracing")] + ::tracing::info!(chart = $chart, event = $ename, "terminate-requested"); + }}; + (Terminated, $sink:expr, $chart:literal) => {{ + #[cfg(feature = "journal")] + { + $sink.push($crate::TraceEvent::Terminated); + } + #[cfg(feature = "trace-defmt")] + ::defmt::info!("[statechart:{}] terminated", $chart); + #[cfg(feature = "trace-log")] + ::log::info!("[statechart:{}] terminated", $chart); + #[cfg(feature = "trace-tracing")] + ::tracing::info!(chart = $chart, "terminated"); + }}; } #[doc(hidden)] diff --git a/hsmc/tests/det_descent.rs b/hsmc/tests/det_descent.rs index e2c1156..b92cb82 100644 --- a/hsmc/tests/det_descent.rs +++ b/hsmc/tests/det_descent.rs @@ -12,7 +12,7 @@ #![cfg(all(feature = "tokio", feature = "journal"))] #![allow(unexpected_cfgs)] -use hsmc::{statechart, ActionKind, TraceEvent}; +use hsmc::{statechart, ActionKind, TraceEvent, TransitionReason}; #[derive(Default)] pub struct Ctx; @@ -117,9 +117,12 @@ async fn det_descent_target_with_three_default_levels() { TraceEvent::Started { chart_hash: Desc::<8>::CHART_HASH, }, + TraceEvent::EnterBegan { state: SR }, TraceEvent::Entered { state: SR }, - TraceEvent::Entered { state: SI }, + TraceEvent::EnterBegan { state: SI }, entry(SI, A_IDLE_IN), + TraceEvent::Entered { state: SI }, + TraceEvent::EventReceived { event: E_GO }, TraceEvent::EventDelivered { handler_state: SI, event: E_GO, @@ -127,17 +130,27 @@ async fn det_descent_target_with_three_default_levels() { TraceEvent::TransitionFired { from: Some(SI), to: ST, + reason: TransitionReason::Event { event: E_GO }, }, + TraceEvent::ExitBegan { state: SI }, exit_(SI, A_IDLE_OUT), TraceEvent::Exited { state: SI }, - TraceEvent::Entered { state: ST }, + TraceEvent::EnterBegan { state: ST }, entry(ST, A_TOWER_IN), - TraceEvent::Entered { state: SL1 }, + TraceEvent::Entered { state: ST }, + TraceEvent::EnterBegan { state: SL1 }, entry(SL1, A_L1_IN), - TraceEvent::Entered { state: SL2 }, + TraceEvent::Entered { state: SL1 }, + TraceEvent::EnterBegan { state: SL2 }, entry(SL2, A_L2_IN), - TraceEvent::Entered { state: SL3 }, + TraceEvent::Entered { state: SL2 }, + TraceEvent::EnterBegan { state: SL3 }, entry(SL3, A_L3_IN), + TraceEvent::Entered { state: SL3 }, + TraceEvent::TransitionComplete { + from: Some(SI), + to: ST, + }, ]; assert_eq!(actual, expected); diff --git a/hsmc/tests/det_initial.rs b/hsmc/tests/det_initial.rs index 828914c..b597e95 100644 --- a/hsmc/tests/det_initial.rs +++ b/hsmc/tests/det_initial.rs @@ -127,27 +127,38 @@ async fn det_initial_descent_records_full_path() { TraceEvent::Started { chart_hash: Init4::<8>::CHART_HASH, }, - TraceEvent::Entered { state: SR }, + TraceEvent::EnterBegan { state: SR }, entry(SR, A_R_IN), - TraceEvent::Entered { state: SA }, + TraceEvent::Entered { state: SR }, + TraceEvent::EnterBegan { state: SA }, entry(SA, A_A_IN), - TraceEvent::Entered { state: SB }, + TraceEvent::Entered { state: SA }, + TraceEvent::EnterBegan { state: SB }, entry(SB, A_B_IN), - TraceEvent::Entered { state: SC }, + TraceEvent::Entered { state: SB }, + TraceEvent::EnterBegan { state: SC }, entry(SC, A_C_IN), - TraceEvent::Entered { state: SD }, + TraceEvent::Entered { state: SC }, + TraceEvent::EnterBegan { state: SD }, entry(SD, A_D_IN), + TraceEvent::Entered { state: SD }, // Halt. + TraceEvent::EventReceived { event: E_HALT }, TraceEvent::TerminateRequested { event: E_HALT }, // Bottom-up exit chain. + TraceEvent::ExitBegan { state: SD }, exit_(SD, A_D_OUT), TraceEvent::Exited { state: SD }, + TraceEvent::ExitBegan { state: SC }, exit_(SC, A_C_OUT), TraceEvent::Exited { state: SC }, + TraceEvent::ExitBegan { state: SB }, exit_(SB, A_B_OUT), TraceEvent::Exited { state: SB }, + TraceEvent::ExitBegan { state: SA }, exit_(SA, A_A_OUT), TraceEvent::Exited { state: SA }, + TraceEvent::ExitBegan { state: SR }, exit_(SR, A_R_OUT), TraceEvent::Exited { state: SR }, TraceEvent::Terminated, diff --git a/hsmc/tests/det_lateral.rs b/hsmc/tests/det_lateral.rs index 2e6f42f..805480e 100644 --- a/hsmc/tests/det_lateral.rs +++ b/hsmc/tests/det_lateral.rs @@ -11,7 +11,7 @@ #![cfg(all(feature = "tokio", feature = "journal"))] #![allow(unexpected_cfgs)] -use hsmc::{statechart, ActionKind, TraceEvent}; +use hsmc::{statechart, ActionKind, TraceEvent, TransitionReason}; #[derive(Default)] pub struct Ctx; @@ -146,11 +146,14 @@ fn initial_descent() -> Vec { TraceEvent::Started { chart_hash: Lat::<8>::CHART_HASH, }, + TraceEvent::EnterBegan { state: SR }, TraceEvent::Entered { state: SR }, - TraceEvent::Entered { state: SP }, + TraceEvent::EnterBegan { state: SP }, entry(SP, A_P_IN), - TraceEvent::Entered { state: SA }, + TraceEvent::Entered { state: SP }, + TraceEvent::EnterBegan { state: SA }, entry(SA, A_A_IN), + TraceEvent::Entered { state: SA }, ] } @@ -185,6 +188,7 @@ async fn det_lateral_a_to_b_lca_is_parent() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_GOB }, TraceEvent::EventDelivered { handler_state: SA, event: E_GOB, @@ -192,11 +196,18 @@ async fn det_lateral_a_to_b_lca_is_parent() { TraceEvent::TransitionFired { from: Some(SA), to: SB, + reason: TransitionReason::Event { event: E_GOB }, }, + TraceEvent::ExitBegan { state: SA }, exit_(SA, A_A_OUT), TraceEvent::Exited { state: SA }, - TraceEvent::Entered { state: SB }, + TraceEvent::EnterBegan { state: SB }, entry(SB, A_B_IN), + TraceEvent::Entered { state: SB }, + TraceEvent::TransitionComplete { + from: Some(SA), + to: SB, + }, ]); assert_journal(&actual, &expected); }) @@ -215,6 +226,7 @@ async fn det_lateral_a_to_c_exits_parent() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_GOC }, TraceEvent::EventDelivered { handler_state: SA, event: E_GOC, @@ -222,13 +234,21 @@ async fn det_lateral_a_to_c_exits_parent() { TraceEvent::TransitionFired { from: Some(SA), to: SC, + reason: TransitionReason::Event { event: E_GOC }, }, + TraceEvent::ExitBegan { state: SA }, exit_(SA, A_A_OUT), TraceEvent::Exited { state: SA }, + TraceEvent::ExitBegan { state: SP }, exit_(SP, A_P_OUT), TraceEvent::Exited { state: SP }, - TraceEvent::Entered { state: SC }, + TraceEvent::EnterBegan { state: SC }, entry(SC, A_C_IN), + TraceEvent::Entered { state: SC }, + TraceEvent::TransitionComplete { + from: Some(SA), + to: SC, + }, ]); assert_journal(&actual, &expected); }) @@ -246,6 +266,7 @@ async fn det_lateral_target_with_children_default_descends() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_GOD }, TraceEvent::EventDelivered { handler_state: SA, event: E_GOD, @@ -253,15 +274,24 @@ async fn det_lateral_target_with_children_default_descends() { TraceEvent::TransitionFired { from: Some(SA), to: SD, + reason: TransitionReason::Event { event: E_GOD }, }, + TraceEvent::ExitBegan { state: SA }, exit_(SA, A_A_OUT), TraceEvent::Exited { state: SA }, + TraceEvent::ExitBegan { state: SP }, exit_(SP, A_P_OUT), TraceEvent::Exited { state: SP }, - TraceEvent::Entered { state: SD }, + TraceEvent::EnterBegan { state: SD }, entry(SD, A_D_IN), - TraceEvent::Entered { state: SE }, + TraceEvent::Entered { state: SD }, + TraceEvent::EnterBegan { state: SE }, entry(SE, A_E_IN), + TraceEvent::Entered { state: SE }, + TraceEvent::TransitionComplete { + from: Some(SA), + to: SD, + }, ]); assert_journal(&actual, &expected); }) @@ -280,6 +310,7 @@ async fn det_lateral_to_deeply_nested_target() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_GOE }, TraceEvent::EventDelivered { handler_state: SA, event: E_GOE, @@ -287,15 +318,24 @@ async fn det_lateral_to_deeply_nested_target() { TraceEvent::TransitionFired { from: Some(SA), to: SE, + reason: TransitionReason::Event { event: E_GOE }, }, + TraceEvent::ExitBegan { state: SA }, exit_(SA, A_A_OUT), TraceEvent::Exited { state: SA }, + TraceEvent::ExitBegan { state: SP }, exit_(SP, A_P_OUT), TraceEvent::Exited { state: SP }, - TraceEvent::Entered { state: SD }, + TraceEvent::EnterBegan { state: SD }, entry(SD, A_D_IN), - TraceEvent::Entered { state: SE }, + TraceEvent::Entered { state: SD }, + TraceEvent::EnterBegan { state: SE }, entry(SE, A_E_IN), + TraceEvent::Entered { state: SE }, + TraceEvent::TransitionComplete { + from: Some(SA), + to: SE, + }, ]); assert_journal(&actual, &expected); }) @@ -316,6 +356,7 @@ async fn det_lateral_chained_transitions() { let mut expected = initial_descent(); // A → B expected.extend(vec![ + TraceEvent::EventReceived { event: E_GOB }, TraceEvent::EventDelivered { handler_state: SA, event: E_GOB, @@ -323,14 +364,22 @@ async fn det_lateral_chained_transitions() { TraceEvent::TransitionFired { from: Some(SA), to: SB, + reason: TransitionReason::Event { event: E_GOB }, }, + TraceEvent::ExitBegan { state: SA }, exit_(SA, A_A_OUT), TraceEvent::Exited { state: SA }, - TraceEvent::Entered { state: SB }, + TraceEvent::EnterBegan { state: SB }, entry(SB, A_B_IN), + TraceEvent::Entered { state: SB }, + TraceEvent::TransitionComplete { + from: Some(SA), + to: SB, + }, ]); // B → C (LCA = Root, so Parent exits too). expected.extend(vec![ + TraceEvent::EventReceived { event: E_GOC }, TraceEvent::EventDelivered { handler_state: SB, event: E_GOC, @@ -338,13 +387,21 @@ async fn det_lateral_chained_transitions() { TraceEvent::TransitionFired { from: Some(SB), to: SC, + reason: TransitionReason::Event { event: E_GOC }, }, + TraceEvent::ExitBegan { state: SB }, exit_(SB, A_B_OUT), TraceEvent::Exited { state: SB }, + TraceEvent::ExitBegan { state: SP }, exit_(SP, A_P_OUT), TraceEvent::Exited { state: SP }, - TraceEvent::Entered { state: SC }, + TraceEvent::EnterBegan { state: SC }, entry(SC, A_C_IN), + TraceEvent::Entered { state: SC }, + TraceEvent::TransitionComplete { + from: Some(SB), + to: SC, + }, ]); assert_journal(&actual, &expected); }) @@ -360,9 +417,13 @@ async fn det_lateral_lca_stays_active() { let _ = m.dispatch(Ev::GoB).await; let j = m.take_journal(); // After initial Entered(Parent), Parent must not appear again. + let initial_p_idx = j + .iter() + .position(|e| matches!(e, TraceEvent::Entered { state: SP })) + .unwrap(); let parent_events: Vec<&TraceEvent> = j .iter() - .skip(3) + .skip(initial_p_idx + 1) .filter(|e| { matches!( e, diff --git a/hsmc/tests/det_root_target.rs b/hsmc/tests/det_root_target.rs index b2eb105..75d0df5 100644 --- a/hsmc/tests/det_root_target.rs +++ b/hsmc/tests/det_root_target.rs @@ -17,7 +17,7 @@ #![cfg(all(feature = "tokio", feature = "journal"))] #![allow(unexpected_cfgs)] -use hsmc::{statechart, ActionKind, TraceEvent}; +use hsmc::{statechart, ActionKind, TraceEvent, TransitionReason}; #[derive(Default)] pub struct Ctx; @@ -101,12 +101,16 @@ async fn det_root_targetable_by_chart_name() { TraceEvent::Started { chart_hash: Sub::<8>::CHART_HASH, }, - TraceEvent::Entered { state: SR }, + TraceEvent::EnterBegan { state: SR }, entry(SR, A_R_IN), - TraceEvent::Entered { state: SA }, + TraceEvent::Entered { state: SR }, + TraceEvent::EnterBegan { state: SA }, entry(SA, A_A_IN), - TraceEvent::Entered { state: SB }, + TraceEvent::Entered { state: SA }, + TraceEvent::EnterBegan { state: SB }, entry(SB, A_B_IN), + TraceEvent::Entered { state: SB }, + TraceEvent::EventReceived { event: E_UPTOROOT }, TraceEvent::EventDelivered { handler_state: SB, event: E_UPTOROOT, @@ -114,11 +118,18 @@ async fn det_root_targetable_by_chart_name() { TraceEvent::TransitionFired { from: Some(SB), to: SR, + reason: TransitionReason::Event { event: E_UPTOROOT }, }, + TraceEvent::ExitBegan { state: SB }, exit_(SB, A_B_OUT), TraceEvent::Exited { state: SB }, + TraceEvent::ExitBegan { state: SA }, exit_(SA, A_A_OUT), TraceEvent::Exited { state: SA }, + TraceEvent::TransitionComplete { + from: Some(SB), + to: SR, + }, ]; assert_eq!( diff --git a/hsmc/tests/det_self.rs b/hsmc/tests/det_self.rs index d55a5ba..f55d689 100644 --- a/hsmc/tests/det_self.rs +++ b/hsmc/tests/det_self.rs @@ -13,7 +13,7 @@ #![cfg(all(feature = "tokio", feature = "journal"))] #![allow(unexpected_cfgs)] -use hsmc::{statechart, ActionKind, TraceEvent}; +use hsmc::{statechart, ActionKind, TraceEvent, TransitionReason}; #[derive(Default)] pub struct Ctx; @@ -86,11 +86,14 @@ fn initial_descent() -> Vec { TraceEvent::Started { chart_hash: Self_::<8>::CHART_HASH, }, + TraceEvent::EnterBegan { state: SR }, TraceEvent::Entered { state: SR }, - TraceEvent::Entered { state: SM }, + TraceEvent::EnterBegan { state: SM }, entry(SM, A_M_IN), - TraceEvent::Entered { state: SL }, + TraceEvent::Entered { state: SM }, + TraceEvent::EnterBegan { state: SL }, entry(SL, A_L_IN), + TraceEvent::Entered { state: SL }, ] } fn assert_journal(actual: &[TraceEvent], expected: &[TraceEvent]) { @@ -123,6 +126,7 @@ async fn det_self_leaf_exits_and_reenters_only_leaf() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_SELFLEAF }, TraceEvent::EventDelivered { handler_state: SL, event: E_SELFLEAF, @@ -130,11 +134,18 @@ async fn det_self_leaf_exits_and_reenters_only_leaf() { TraceEvent::TransitionFired { from: Some(SL), to: SL, + reason: TransitionReason::Event { event: E_SELFLEAF }, }, + TraceEvent::ExitBegan { state: SL }, exit_(SL, A_L_OUT), TraceEvent::Exited { state: SL }, - TraceEvent::Entered { state: SL }, + TraceEvent::EnterBegan { state: SL }, entry(SL, A_L_IN), + TraceEvent::Entered { state: SL }, + TraceEvent::TransitionComplete { + from: Some(SL), + to: SL, + }, ]); assert_journal(&actual, &expected); }) @@ -209,6 +220,7 @@ async fn det_self_composite_default_descends() { // Mid's entry actions don't fire. No default-descent. let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_SELFMID }, TraceEvent::EventDelivered { handler_state: SM, event: E_SELFMID, @@ -216,9 +228,15 @@ async fn det_self_composite_default_descends() { TraceEvent::TransitionFired { from: Some(SL), to: SM, + reason: TransitionReason::Event { event: E_SELFMID }, }, + TraceEvent::ExitBegan { state: SL }, exit_(SL, A_L_OUT), TraceEvent::Exited { state: SL }, + TraceEvent::TransitionComplete { + from: Some(SL), + to: SM, + }, ]); assert_journal(&actual, &expected); }) @@ -257,7 +275,8 @@ async fn det_self_leaf_repeated_is_deterministic() { e, TraceEvent::TransitionFired { from: Some(SL), - to: SL + to: SL, + .. } ) }) diff --git a/hsmc/tests/det_self_composite.rs b/hsmc/tests/det_self_composite.rs index 0b6c25c..acd5400 100644 --- a/hsmc/tests/det_self_composite.rs +++ b/hsmc/tests/det_self_composite.rs @@ -85,7 +85,8 @@ async fn det_self_composite_default_descends_after_re_entry() { e, TraceEvent::TransitionFired { from: Some(SP), - to: SP + to: SP, + .. } ) }) @@ -133,7 +134,8 @@ async fn det_self_composite_action_kinds_in_order() { e, TraceEvent::TransitionFired { from: Some(SP), - to: SP + to: SP, + .. } ) }) diff --git a/hsmc/tests/det_up.rs b/hsmc/tests/det_up.rs index 99d90e2..0dfaa64 100644 --- a/hsmc/tests/det_up.rs +++ b/hsmc/tests/det_up.rs @@ -15,7 +15,7 @@ #![cfg(all(feature = "tokio", feature = "journal"))] #![allow(unexpected_cfgs)] -use hsmc::{statechart, ActionKind, TraceEvent}; +use hsmc::{statechart, ActionKind, TraceEvent, TransitionReason}; #[derive(Default)] pub struct Ctx; @@ -117,16 +117,21 @@ fn initial_descent() -> Vec { TraceEvent::Started { chart_hash: Up::<8>::CHART_HASH, }, - TraceEvent::Entered { state: SR }, + TraceEvent::EnterBegan { state: SR }, entry(SR, A_R_IN), - TraceEvent::Entered { state: SA }, + TraceEvent::Entered { state: SR }, + TraceEvent::EnterBegan { state: SA }, entry(SA, A_A_IN), - TraceEvent::Entered { state: SB }, + TraceEvent::Entered { state: SA }, + TraceEvent::EnterBegan { state: SB }, entry(SB, A_B_IN), - TraceEvent::Entered { state: SC }, + TraceEvent::Entered { state: SB }, + TraceEvent::EnterBegan { state: SC }, entry(SC, A_C_IN), - TraceEvent::Entered { state: SD }, + TraceEvent::Entered { state: SC }, + TraceEvent::EnterBegan { state: SD }, entry(SD, A_D_IN), + TraceEvent::Entered { state: SD }, ] } fn assert_journal(actual: &[TraceEvent], expected: &[TraceEvent]) { @@ -159,6 +164,7 @@ async fn det_up_to_immediate_grandparent() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_UPTOC }, TraceEvent::EventDelivered { handler_state: SD, event: E_UPTOC, @@ -166,9 +172,15 @@ async fn det_up_to_immediate_grandparent() { TraceEvent::TransitionFired { from: Some(SD), to: SC, + reason: TransitionReason::Event { event: E_UPTOC }, }, + TraceEvent::ExitBegan { state: SD }, exit_(SD, A_D_OUT), TraceEvent::Exited { state: SD }, + TraceEvent::TransitionComplete { + from: Some(SD), + to: SC, + }, ]); assert_journal(&actual, &expected); }) @@ -186,6 +198,7 @@ async fn det_up_two_levels() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_UPTOB }, TraceEvent::EventDelivered { handler_state: SD, event: E_UPTOB, @@ -193,11 +206,18 @@ async fn det_up_two_levels() { TraceEvent::TransitionFired { from: Some(SD), to: SB, + reason: TransitionReason::Event { event: E_UPTOB }, }, + TraceEvent::ExitBegan { state: SD }, exit_(SD, A_D_OUT), TraceEvent::Exited { state: SD }, + TraceEvent::ExitBegan { state: SC }, exit_(SC, A_C_OUT), TraceEvent::Exited { state: SC }, + TraceEvent::TransitionComplete { + from: Some(SD), + to: SB, + }, ]); assert_journal(&actual, &expected); }) @@ -215,6 +235,7 @@ async fn det_up_three_levels_to_a() { let mut expected = initial_descent(); expected.extend(vec![ + TraceEvent::EventReceived { event: E_UPTOA }, TraceEvent::EventDelivered { handler_state: SD, event: E_UPTOA, @@ -222,13 +243,21 @@ async fn det_up_three_levels_to_a() { TraceEvent::TransitionFired { from: Some(SD), to: SA, + reason: TransitionReason::Event { event: E_UPTOA }, }, + TraceEvent::ExitBegan { state: SD }, exit_(SD, A_D_OUT), TraceEvent::Exited { state: SD }, + TraceEvent::ExitBegan { state: SC }, exit_(SC, A_C_OUT), TraceEvent::Exited { state: SC }, + TraceEvent::ExitBegan { state: SB }, exit_(SB, A_B_OUT), TraceEvent::Exited { state: SB }, + TraceEvent::TransitionComplete { + from: Some(SD), + to: SA, + }, ]); assert_journal(&actual, &expected); }) diff --git a/hsmc/tests/journal_replay.rs b/hsmc/tests/journal_replay.rs index 6ead02e..6b214d7 100644 --- a/hsmc/tests/journal_replay.rs +++ b/hsmc/tests/journal_replay.rs @@ -12,7 +12,7 @@ #![cfg(all(feature = "tokio", feature = "journal"))] #![allow(unexpected_cfgs)] -use hsmc::{statechart, ActionKind, TraceEvent}; +use hsmc::{statechart, ActionKind, TraceEvent, TransitionReason}; #[derive(Default)] pub struct Ctx; @@ -97,19 +97,22 @@ async fn replay_full_lifecycle_matches_expected() { TraceEvent::Started { chart_hash: Replay::<8>::CHART_HASH, }, - TraceEvent::Entered { state: ST_ROOT }, + TraceEvent::EnterBegan { state: ST_ROOT }, TraceEvent::ActionInvoked { state: ST_ROOT, action: A_ROOT_IN, kind: ActionKind::Entry, }, - TraceEvent::Entered { state: ST_IDLE }, + TraceEvent::Entered { state: ST_ROOT }, + TraceEvent::EnterBegan { state: ST_IDLE }, TraceEvent::ActionInvoked { state: ST_IDLE, action: A_IDLE_IN, kind: ActionKind::Entry, }, + TraceEvent::Entered { state: ST_IDLE }, // ── Go event delivered to Idle, transition to Active → Sub ── + TraceEvent::EventReceived { event: E_GO }, TraceEvent::EventDelivered { handler_state: ST_IDLE, event: E_GO, @@ -117,39 +120,51 @@ async fn replay_full_lifecycle_matches_expected() { TraceEvent::TransitionFired { from: Some(ST_IDLE), to: ST_ACTIVE, + reason: TransitionReason::Event { event: E_GO }, }, + TraceEvent::ExitBegan { state: ST_IDLE }, TraceEvent::ActionInvoked { state: ST_IDLE, action: A_IDLE_OUT, kind: ActionKind::Exit, }, TraceEvent::Exited { state: ST_IDLE }, - TraceEvent::Entered { state: ST_ACTIVE }, + TraceEvent::EnterBegan { state: ST_ACTIVE }, TraceEvent::ActionInvoked { state: ST_ACTIVE, action: A_ACTIVE_IN, kind: ActionKind::Entry, }, - TraceEvent::Entered { state: ST_SUB }, + TraceEvent::Entered { state: ST_ACTIVE }, + TraceEvent::EnterBegan { state: ST_SUB }, TraceEvent::ActionInvoked { state: ST_SUB, action: A_SUB_IN, kind: ActionKind::Entry, }, + TraceEvent::Entered { state: ST_SUB }, + TraceEvent::TransitionComplete { + from: Some(ST_IDLE), + to: ST_ACTIVE, + }, // ── Halt event triggers termination: exit Sub → Active → root, then Terminated ── + TraceEvent::EventReceived { event: E_HALT }, TraceEvent::TerminateRequested { event: E_HALT }, + TraceEvent::ExitBegan { state: ST_SUB }, TraceEvent::ActionInvoked { state: ST_SUB, action: A_SUB_OUT, kind: ActionKind::Exit, }, TraceEvent::Exited { state: ST_SUB }, + TraceEvent::ExitBegan { state: ST_ACTIVE }, TraceEvent::ActionInvoked { state: ST_ACTIVE, action: A_ACTIVE_OUT, kind: ActionKind::Exit, }, TraceEvent::Exited { state: ST_ACTIVE }, + TraceEvent::ExitBegan { state: ST_ROOT }, TraceEvent::ActionInvoked { state: ST_ROOT, action: A_ROOT_OUT, diff --git a/hsmc/tests/trace_format.rs b/hsmc/tests/trace_format.rs new file mode 100644 index 0000000..8945645 --- /dev/null +++ b/hsmc/tests/trace_format.rs @@ -0,0 +1,429 @@ +//! Verifies the textual format of the unified observation pipeline's +//! `trace-log` sink line-for-line. +//! +//! Each `__chart_observe!` arm has a stable logfmt-style format: +//! +//! `[statechart:] key=value key=value …` +//! +//! These tests pin every verb's exact rendering so a real-life log capture +//! can be diffed against expected behavior. The chart is exercised through +//! both the journal sink (so we can assert atom-by-atom equivalence) and +//! the trace-log sink (so we can assert the rendered strings). + +#![cfg(all(feature = "tokio", feature = "journal", feature = "trace-log"))] +#![allow(unexpected_cfgs)] + +use hsmc::{statechart, Duration, TraceEvent, TransitionReason}; +use std::sync::{Mutex, MutexGuard, OnceLock}; + +// ── Capture sink ───────────────────────────────────────────────────── +// +// log::set_logger can only be installed once per process. The capture +// holds a single Vec shared across all tests, plus a global +// `TEST_LOCK` that each test holds across its drive-then-assert +// section so concurrent tests don't interleave their captured lines. + +struct Capture { + lines: Mutex>, +} + +impl log::Log for Capture { + fn enabled(&self, _: &log::Metadata<'_>) -> bool { + true + } + fn log(&self, record: &log::Record<'_>) { + if let Ok(mut g) = self.lines.lock() { + g.push(format!("{}", record.args())); + } + } + fn flush(&self) {} +} + +static CAPTURE: OnceLock<&'static Capture> = OnceLock::new(); +static TEST_LOCK: Mutex<()> = Mutex::new(()); + +fn install_capture() -> &'static Capture { + *CAPTURE.get_or_init(|| { + let leaked: &'static Capture = Box::leak(Box::new(Capture { + lines: Mutex::new(Vec::new()), + })); + let _ = log::set_logger(leaked); + log::set_max_level(log::LevelFilter::Trace); + leaked + }) +} + +/// RAII helper. Acquire before driving the chart, drop after assertions +/// — keeps `tests::*` from interleaving captured log lines. +fn lock_for_test() -> MutexGuard<'static, ()> { + install_capture(); + let g = TEST_LOCK.lock().unwrap_or_else(|p| p.into_inner()); + // Clear any lines left by a previous test that paniced before + // draining (poison case). + let cap = CAPTURE.get().unwrap(); + cap.lines.lock().unwrap().clear(); + g +} + +fn current_lines() -> Vec { + let cap = install_capture(); + cap.lines.lock().unwrap().clone() +} + +// ── Test chart ─────────────────────────────────────────────────────── +// +// Covers every observation verb the macro can emit. Two states with +// entry/exit actions, a handler that emits and transitions, a timer, +// a during, and a terminate event. + +#[derive(Default)] +pub struct Ctx { + pub buf: u32, +} + +#[derive(Debug, Clone)] +pub enum Ev { + Go, + Step, + Halt, +} + +statechart! { + TraceFmt { + context: Ctx; + events: Ev; + + default(Idle); + terminate(Halt); + + state Idle { + entry: idle_in; + exit: idle_out; + during: tick(buf); + on(after Duration::from_secs(60)) => Idle; + on(Go) => Active; + } + state Active { + entry: active_in; + exit: active_out; + on(Step) => bump; + on(Halt) => Idle; + } + } +} + +async fn tick(_buf: &mut u32) -> Ev { + Ev::Step +} + +impl TraceFmtActions for TraceFmtActionContext<'_> { + async fn idle_in(&mut self) {} + async fn idle_out(&mut self) {} + async fn active_in(&mut self) {} + async fn active_out(&mut self) {} + async fn bump(&mut self) { + let _ = self.emit(Ev::Halt); + } +} + +// ── Helpers ────────────────────────────────────────────────────────── + +/// Returns true iff `line` matches the expected `[statechart:TraceFmt] verb …` +/// shape. Every line emitted by the dispatcher must. +fn well_formed(line: &str) -> bool { + line.starts_with("[statechart:TraceFmt] ") +} + +/// Filter `lines` to only those whose verb (the first token after the +/// prefix) equals `verb`. Useful for asserting on a single verb's lines. +fn lines_with_verb<'a>(lines: &'a [String], verb: &str) -> Vec<&'a str> { + let prefix = "[statechart:TraceFmt] "; + lines + .iter() + .filter_map(|l| l.strip_prefix(prefix)) + .filter(|rest| rest.split_whitespace().next() == Some(verb)) + .map(|s| s.as_ref()) + .collect() +} + +// ── Tests ──────────────────────────────────────────────────────────── + +#[tokio::test(flavor = "current_thread")] +async fn every_line_uses_statechart_prefix() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + let _ = m.dispatch(Ev::Halt).await; + }) + .await; + + let lines = current_lines(); + assert!(!lines.is_empty(), "no log lines captured"); + for l in &lines { + assert!( + well_formed(l), + "line missing [statechart:TraceFmt] prefix: {l:?}" + ); + } +} + +#[tokio::test(flavor = "current_thread")] +async fn enter_and_exit_emit_begin_end_pairs() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + }) + .await; + + let lines = current_lines(); + let entering = lines_with_verb(&lines, "entering"); + let entered = lines_with_verb(&lines, "entered"); + assert_eq!( + entering.len(), + entered.len(), + "every `entering` must have a matching `entered`" + ); + assert!(entering.contains(&"entering state=TraceFmt")); + assert!(entered.contains(&"entered state=TraceFmt")); + assert!(entering.contains(&"entering state=Idle")); + assert!(entered.contains(&"entered state=Idle")); +} + +#[tokio::test(flavor = "current_thread")] +async fn transition_records_event_reason() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + }) + .await; + + let lines = current_lines(); + let begins = lines_with_verb(&lines, "transition-begin"); + assert!(!begins.is_empty(), "no transition-begin lines captured"); + let line = begins[0]; + assert!( + line.contains("from=Idle"), + "transition-begin missing from=Idle: {line:?}" + ); + assert!( + line.contains("to=Active"), + "transition-begin missing to=Active: {line:?}" + ); + assert!( + line.contains("reason=event:Go"), + "transition-begin missing reason=event:Go: {line:?}" + ); + + let completes = lines_with_verb(&lines, "transition-complete"); + assert!( + !completes.is_empty(), + "transition-complete must follow transition-begin" + ); + assert!(completes[0].contains("from=Idle") && completes[0].contains("to=Active")); +} + +#[tokio::test(flavor = "current_thread")] +async fn event_lifecycle_received_then_outcome() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + }) + .await; + + let lines = current_lines(); + let received = lines_with_verb(&lines, "event-received"); + let delivered = lines_with_verb(&lines, "event-delivered"); + assert!(received.iter().any(|l| l.contains("name=Go"))); + assert!(delivered + .iter() + .any(|l| l.contains("name=Go") && l.contains("handler=Idle"))); +} + +#[tokio::test(flavor = "current_thread")] +async fn during_emits_started_and_cancelled() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + // Go enters Active, which causes Idle's during to be cancelled. + let _ = m.dispatch(Ev::Go).await; + }) + .await; + + let lines = current_lines(); + let started = lines_with_verb(&lines, "during-started"); + let cancelled = lines_with_verb(&lines, "during-cancelled"); + assert!(started.iter().any(|l| l.contains("during=tick"))); + assert!(cancelled.iter().any(|l| l.contains("during=tick"))); +} + +#[tokio::test(flavor = "current_thread")] +async fn timer_arm_then_cancel_lines() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + }) + .await; + + let lines = current_lines(); + let armed = lines_with_verb(&lines, "timer-armed"); + let cancelled = lines_with_verb(&lines, "timer-cancelled"); + assert!( + armed.iter().any(|l| l.contains("state=Idle")), + "timer should arm when Idle is entered" + ); + assert!( + cancelled.iter().any(|l| l.contains("state=Idle")), + "timer should be cancelled when Idle is exited (Go transition)" + ); +} + +#[tokio::test(flavor = "current_thread")] +async fn emit_queued_appears_for_handler_emit() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + // Step's handler calls emit(Halt). + let _ = m.dispatch(Ev::Step).await; + }) + .await; + + let lines = current_lines(); + let queued = lines_with_verb(&lines, "emit-queued"); + assert!( + queued.iter().any(|l| l.contains("event=Halt")), + "expected emit-queued event=Halt line: {lines:?}" + ); +} + +#[tokio::test(flavor = "current_thread")] +async fn terminate_records_request_then_terminated() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + // Halt from Active is a transition to Idle (no terminate); + // dispatch Halt twice via Idle to actually terminate. + // First Go landed us in Active; Halt → Idle (handler). + let _ = m.dispatch(Ev::Halt).await; // back to Idle + let _ = m.dispatch(Ev::Halt).await; // now terminate + }) + .await; + + let lines = current_lines(); + let req = lines_with_verb(&lines, "terminate-requested"); + let term = lines_with_verb(&lines, "terminated"); + assert!( + req.iter().any(|l| l.contains("event=Halt")), + "expected terminate-requested event=Halt: {lines:?}" + ); + assert!( + !term.is_empty(), + "expected a final `terminated` line: {lines:?}" + ); +} + +#[tokio::test(flavor = "current_thread")] +async fn started_records_chart_hash() { + let _g = lock_for_test(); + + tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + }) + .await; + + let lines = current_lines(); + let started = lines_with_verb(&lines, "started"); + assert!(!started.is_empty(), "expected one `started` line"); + assert!( + started[0].contains("chart_hash=0x"), + "started must include chart_hash in hex: {:?}", + started[0] + ); +} + +#[tokio::test(flavor = "current_thread")] +async fn trace_and_journal_have_matching_atom_count() { + // The "one journal, multiple outputs" contract: every TraceEvent + // recorded in the journal corresponds to exactly one log line in + // the trace, modulo verb-name differences. + let _g = lock_for_test(); + + let actual = tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + m.take_journal() + }) + .await; + + let lines = current_lines(); + assert_eq!( + actual.len(), + lines.len(), + "journal/trace atom count diverged ({} vs {} lines)", + actual.len(), + lines.len() + ); +} + +#[tokio::test(flavor = "current_thread")] +async fn transition_reason_in_journal_matches_trace() { + // The journal records the structured `TransitionReason::Event { event }` + // and the trace renders it as `event:`. They must agree. + let _g = lock_for_test(); + + let actual = tokio::task::LocalSet::new() + .run_until(async { + let mut m = TraceFmt::new(Ctx::default()); + let _ = m.dispatch(Ev::Go).await; + m.take_journal() + }) + .await; + + let lines = current_lines(); + + let journal_reason = actual.iter().find_map(|e| match e { + TraceEvent::TransitionFired { reason, .. } => Some(*reason), + _ => None, + }); + let trace_reason_line = lines_with_verb(&lines, "transition-begin") + .first() + .copied() + .map(|s| s.to_string()); + + assert_eq!( + journal_reason, + Some(TransitionReason::Event { event: 0 }), + "expected first transition driven by Ev::Go (event id 0)" + ); + assert!( + trace_reason_line + .as_deref() + .is_some_and(|l| l.contains("reason=event:Go")), + "trace reason should match journal reason: {trace_reason_line:?}" + ); +}