diff --git a/README.md b/README.md index 0001d2a..da170cd 100644 --- a/README.md +++ b/README.md @@ -96,6 +96,16 @@ import sys, harel host = harel.Host(observer=harel.JsonlObserver(sys.stdout)) # one JSON line per step ``` +The Observer is *domain* observability (what the machine did). For *operational* +diagnostics the engine also emits **standard-library logging** under the `harel` logger +(dispatch/transition at `DEBUG`, faults/dead-letter at `WARNING`). It is silent by +default (a `NullHandler` is attached); enable it from the host app: + +```python +import logging +logging.basicConfig(level=logging.DEBUG) # or logging.getLogger("harel").setLevel(...) +``` + ## Layout - `src/harel/` — the package. - `tests/` — unit tests and the conformance harness. diff --git a/src/harel/__init__.py b/src/harel/__init__.py index 3d6ce20..7869902 100644 --- a/src/harel/__init__.py +++ b/src/harel/__init__.py @@ -7,6 +7,8 @@ from __future__ import annotations +import logging + from . import yaml12 from .cel import CelError from .definition import Definition, load_definition, load_definitions @@ -42,3 +44,7 @@ ] __version__ = "0.0.1" + +# Diagnostic logging under the ``harel`` logger; silent unless the host app +# configures logging (e.g. ``logging.basicConfig(level=logging.DEBUG)``). +logging.getLogger("harel").addHandler(logging.NullHandler()) diff --git a/src/harel/engine.py b/src/harel/engine.py index 7cc378f..c280aab 100644 --- a/src/harel/engine.py +++ b/src/harel/engine.py @@ -9,6 +9,7 @@ from __future__ import annotations +import logging from typing import Any from . import cel, values @@ -17,6 +18,8 @@ from .model import Machine from .observer import Observer +log = logging.getLogger(__name__) + class Host: def __init__(self, observer: Observer | None = None) -> None: @@ -132,6 +135,10 @@ def _run_one_step(self, inst: Instance) -> dict[str, Any]: } if self.observer is not None: self.observer({"instance": inst.id, **record}) + log.debug( + "dispatch instance=%s event=%s transition=%s entered=%s exited=%s", + inst.id, record["event"], record["transition"], record["entered"], record["exited"], + ) return record def inspect(self, instance: Instance | str) -> dict[str, Any]: @@ -182,6 +189,10 @@ def advance(self, duration: str) -> None: inst.queue.append( Event("__time__", after=(timer["state_path"], timer["spec"])) ) + log.debug( + "timer fired instance=%s state=%s after=%s", + inst.id, timer["state_path"], timer["spec"], + ) def run_to_quiescence(self) -> None: progress = True @@ -300,6 +311,7 @@ def spawn_action( child = Instance(machine, child_id, parent.id, self, external=external) self.instances[child_id] = child self.spawned.append(def_id) + log.debug("spawn parent=%s child=%s def=%s", parent.id, child_id, def_id) result = spec.get("result") if result: parent.assign_esv(root, result, child_id) @@ -317,6 +329,7 @@ def publish( k: cel.evaluate(v, scope) for k, v in (spec.get("payload") or {}).items() } self.published.append(name) + log.debug("publish event=%s from=%s", name, src.id) if "to" in spec: target = cel.evaluate(spec["to"], scope) ids = target if isinstance(target, list) else [target] diff --git a/src/harel/instance.py b/src/harel/instance.py index ad89675..d95eab5 100644 --- a/src/harel/instance.py +++ b/src/harel/instance.py @@ -10,6 +10,7 @@ from __future__ import annotations +import logging from collections import deque from dataclasses import dataclass from enum import StrEnum @@ -20,6 +21,8 @@ from .errors import HarelError from .model import Machine, State +log = logging.getLogger(__name__) + if TYPE_CHECKING: from .engine import Host @@ -541,6 +544,7 @@ def _restore(self, snap: dict[str, Any]) -> None: def _handle_fault(self, event: Event, exc: Exception) -> None: self.dead_letter.append({"event": event.type, "error": str(exc)}) + log.warning("dead-letter instance=%s event=%s: %s", self.id, event.type, exc) error_event = Event("error", {"event": event.type, "error": str(exc)}) # If some active state handles the reserved `error` event, dispatch it # (the instance recovers); otherwise the instance faults. @@ -548,6 +552,7 @@ def _handle_fault(self, event: Event, exc: Exception) -> None: handled = bool(self._collect_enabled(error_event)) self.current_event = None if not handled: + log.warning("instance %s faulted: no handler for the error event", self.id) self.status = Status.FAULTED return snapshot = self._snapshot() @@ -555,6 +560,7 @@ def _handle_fault(self, event: Event, exc: Exception) -> None: changed = self.dispatch(error_event) except (CelError, HarelError): self._restore(snapshot) + log.warning("instance %s faulted: error handler itself faulted", self.id) self.status = Status.FAULTED return if changed: diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..cd4e4d7 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,81 @@ +"""Standard-library diagnostic logging under the ``harel`` logger.""" + +from __future__ import annotations + +import logging + +import harel +from harel import Host + +TURNSTILE = """\ +id: turnstile +events: + coin: { payload: { amount: { type: int, required: true } } } + push: {} +top: + esvs: + fare: { type: int, init: 50 } + initial: { transition_to: locked } + states: + locked: + on_events: + coin: { transition_to: unlocked, guard: "event.payload.amount >= fare" } + unlocked: + on_events: + push: { transition_to: locked } +""" + +FAULTING = """\ +id: boom +events: + go: {} +top: + esvs: + x: { type: int, init: 1 } + initial: { transition_to: a } + states: + a: + on_events: + go: { transition_to: b, action: [ { assign: { x: "1 / 0" } } ] } + b: {} +""" + + +def _run(machine: str, event: str, payload=None): + host = Host() + host.register_all(harel.load_definitions(machine)) + root = harel.load_definitions(machine)[0].id + host.create_root(host.machines[root], "r") + host.run_to_quiescence() + host.deliver("r", event, payload) + host.run_to_quiescence() + return host + + +def test_silent_by_default(caplog): + """No handler is configured by the app → nothing propagates as output, but the + records still exist at their levels (caplog captures them).""" + # The library attaches only a NullHandler; verify it's present. + assert any(isinstance(h, logging.NullHandler) for h in logging.getLogger("harel").handlers) + + +def test_dispatch_and_transition_logged_at_debug(caplog): + with caplog.at_level(logging.DEBUG, logger="harel"): + _run(TURNSTILE, "coin", {"amount": 100}) + msgs = [r.getMessage() for r in caplog.records] + assert any("dispatch instance=r event=coin" in m for m in msgs) + assert any("transition=unlocked" in m for m in msgs) + + +def test_fault_logged_at_warning(caplog): + with caplog.at_level(logging.DEBUG, logger="harel"): + _run(FAULTING, "go") + warnings = [r for r in caplog.records if r.levelno >= logging.WARNING] + assert any("dead-letter" in r.getMessage() for r in warnings) + assert any("faulted" in r.getMessage() for r in warnings) + + +def test_no_debug_records_when_level_is_warning(caplog): + with caplog.at_level(logging.WARNING, logger="harel"): + _run(TURNSTILE, "coin", {"amount": 100}) + assert [r for r in caplog.records if r.levelno == logging.DEBUG] == []