engine: standard-library logging for diagnostics

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.

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())

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]

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,20 +544,23 @@ 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.
         self.current_event = error_event
         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()
         try:
             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:

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] == []