Skip to content

Commit ec8316b

Browse files
Merge remote-tracking branch 'origin/main' into feature/live-view-and-approvals
2 parents 1890a63 + 99a5aca commit ec8316b

6 files changed

Lines changed: 137 additions & 14 deletions

File tree

grapharc/cli/main.py

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -48,7 +48,7 @@
4848
from grapharc.cli.output import EXIT_FAILED, EXIT_OK, emit, fail
4949
from grapharc.observe.metrics import summarize, to_mermaid
5050
from grapharc.observe.replay import ReplayError
51-
from grapharc.observe.trace import TraceRecorder
51+
from grapharc.observe.trace import TraceReadError, TraceRecorder
5252

5353
EXAMPLES = (
5454
"stage0",
@@ -491,7 +491,13 @@ def _cmd_trace(args: argparse.Namespace) -> int:
491491
recorder = _existing_trace(args.path, command="trace", as_json=args.json)
492492
if isinstance(recorder, int):
493493
return recorder
494-
events = recorder.read_events(args.run_id)
494+
try:
495+
events = recorder.read_events(args.run_id)
496+
except TraceReadError as exc:
497+
# A bad line — a truncated write, a hand edit — is the "unreadable
498+
# trace" the exit-code contract names, not a traceback. Same for
499+
# `metrics` and `viz` below: all three read this file.
500+
return fail(str(exc), as_json=args.json, command="trace")
495501
payload: dict[str, Any] = {
496502
"ok": True,
497503
"command": "trace",
@@ -521,7 +527,10 @@ def _cmd_metrics(args: argparse.Namespace) -> int:
521527
recorder = _existing_trace(args.path, command="metrics", as_json=args.json)
522528
if isinstance(recorder, int):
523529
return recorder
524-
metrics = summarize(recorder, args.run_id)
530+
try:
531+
metrics = summarize(recorder, args.run_id)
532+
except TraceReadError as exc:
533+
return fail(str(exc), as_json=args.json, command="metrics")
525534
if metrics is None:
526535
return fail(
527536
f"no events for run {args.run_id!r} in {args.path}",
@@ -544,6 +553,8 @@ def _cmd_viz(args: argparse.Namespace) -> int:
544553
return recorder
545554
try:
546555
mermaid = to_mermaid(recorder, args.run_id)
556+
except TraceReadError as exc:
557+
return fail(str(exc), as_json=args.json, command="viz")
547558
except ReplayError as exc:
548559
# Every other reading command answers this as a document; `viz` used to
549560
# let it out as a traceback with empty stdout, which breaks the CLI's own

grapharc/observe/__init__.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -40,7 +40,7 @@
4040
replay,
4141
replay_thread,
4242
)
43-
from grapharc.observe.trace import TraceEvent, TraceRecorder, load_events
43+
from grapharc.observe.trace import TraceEvent, TraceReadError, TraceRecorder, load_events
4444

4545
__all__ = [
4646
"ListSpanExporter",
@@ -61,6 +61,7 @@
6161
"SpanExporter",
6262
"ThreadCost",
6363
"TraceEvent",
64+
"TraceReadError",
6465
"TraceRecorder",
6566
"attribute",
6667
"attribute_thread",

grapharc/observe/trace.py

Lines changed: 25 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -20,11 +20,29 @@
2020
from pathlib import Path
2121
from typing import Any
2222

23-
from pydantic import BaseModel
23+
from pydantic import BaseModel, ValidationError
2424

2525
_MAX_VALUE_CHARS = 2000
2626

2727

28+
class TraceReadError(Exception):
29+
"""A line in a trace file is not a `TraceEvent`.
30+
31+
Raised instead of skipped on purpose: a partially-read audit trail
32+
presented as complete would be worse than a refusal. The message names the
33+
file and the 1-based line so the one bad line — a process killed mid-write,
34+
a hand edit — can be found without a pydantic field listing.
35+
"""
36+
37+
def __init__(self, path: Path, line_number: int, cause: Exception) -> None:
38+
super().__init__(
39+
f"unreadable trace file: {path}: line {line_number} is not a trace event"
40+
)
41+
self.path = path
42+
self.line_number = line_number
43+
self.cause = cause
44+
45+
2846
def _jsonable(value: Any) -> Any:
2947
"""Best-effort conversion to something json.dumps accepts, truncating long text."""
3048
if isinstance(value, BaseModel):
@@ -186,10 +204,13 @@ def read_events(self, run_id: str | None = None) -> list[TraceEvent]:
186204
return []
187205
events = []
188206
with self.path.open(encoding="utf-8") as f:
189-
for line in f:
207+
for line_number, line in enumerate(f, start=1):
190208
if not line.strip():
191209
continue
192-
ev = TraceEvent.model_validate_json(line)
210+
try:
211+
ev = TraceEvent.model_validate_json(line)
212+
except ValidationError as exc:
213+
raise TraceReadError(self.path, line_number, exc) from exc
193214
if run_id is None or ev.run_id == run_id:
194215
events.append(ev)
195216
return events
@@ -249,4 +270,4 @@ def load_events(
249270
return recorder.read_events(run_id)
250271

251272

252-
__all__ = ["TailRecorder", "TraceEvent", "TraceRecorder", "load_events"]
273+
__all__ = ["TailRecorder", "TraceEvent", "TraceReadError", "TraceRecorder", "load_events"]

grapharc/runtime/budget.py

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -380,8 +380,8 @@ def deadline_guard(meter: BudgetMeter, *, what: str) -> Iterator[None]:
380380
What this does *not* guarantee:
381381
382382
- Mechanism 2 cannot interrupt a thread parked inside a C call: a
383-
`time.sleep(60)` sleeps out its 60 seconds and raises on return. This is
384-
not a fan-out-only weakness. Mechanism 1 needs `invoke()` to be on the
383+
`time.sleep(60)` is not interrupted mid-call, but the guard still raises
384+
on exit. This is not a fan-out-only weakness. Mechanism 1 needs `invoke()` to be on the
385385
process's main thread, so *any* run driven from a worker thread — every
386386
request handler in a threaded server, every `ThreadPoolExecutor` caller —
387387
falls back to mechanism 2 for the whole run, nodes and fan-out alike.
@@ -395,9 +395,10 @@ def deadline_guard(meter: BudgetMeter, *, what: str) -> Iterator[None]:
395395
- Like any asynchronous exception, the interrupt lands wherever the node
396396
happened to be: it is as safe as Ctrl-C, no safer.
397397
398-
Short of that last case the ceiling is honoured at the node boundary: if the
399-
deadline passed and the node swallowed the exception, this guard raises on
400-
exit, so the node's writes never reach state.
398+
Short of the never-returns case the ceiling is honoured at the node
399+
boundary: if the deadline passed — whether the node swallowed the exception
400+
or no interrupt was ever delivered — this guard raises on exit, so the
401+
node's writes never reach state.
401402
"""
402403
remaining = meter.remaining_seconds()
403404
if remaining is None:
@@ -499,5 +500,11 @@ def disarm() -> None:
499500
disarm()
500501
except NodeDeadlineExceeded as exc:
501502
raise NodeDeadlineExceeded(detail()) from exc
502-
if state["fired"]:
503+
504+
# Reached only when the node returned normally. It may have swallowed the
505+
# interrupt, or the deadline may have passed without the timer firing —
506+
# the timer thread needs the GIL, which a node inside a long C call
507+
# withholds until it returns; either way its writes must not land.
508+
left = meter.remaining_seconds()
509+
if state["fired"] or (left is not None and left <= 0):
503510
raise NodeDeadlineExceeded(detail())

tests/test_budget_enforcement.py

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -542,6 +542,52 @@ def body():
542542
assert ran_for < 2.0, "the node asked for 5s and was not stopped"
543543

544544

545+
def test_an_overrun_is_refused_at_exit_even_if_the_timer_never_fired(monkeypatch):
546+
"""A node that holds the GIL through the deadline — a long C call, or plain
547+
timer-scheduling latency — denies the timer thread its turn: `fire()` never
548+
runs, the node returns normally, and an exit check that tests only
549+
`state["fired"]` lets the overrun's writes land. The contract is the node
550+
boundary, so the exit check itself must notice the spent deadline.
551+
552+
The timer is replaced with one that never fires, which makes this the
553+
deterministic statement of that contract: asserting on whether a real
554+
timer's async exception got delivered in time is a race (see
555+
`_run_swallower` above), whereas the exit check runs unconditionally.
556+
"""
557+
558+
class NeverFires:
559+
"""`threading.Timer`'s surface as the guard uses it, minus the firing."""
560+
561+
def __init__(self, interval, function):
562+
self.daemon = False
563+
564+
def start(self):
565+
pass
566+
567+
def cancel(self):
568+
pass
569+
570+
monkeypatch.setattr(threading, "Timer", NeverFires)
571+
outcome: dict[str, object] = {}
572+
573+
def body(): # a worker thread uses mechanism 2, like any threaded server
574+
meter = BudgetMeter(Budget(max_seconds=0.05))
575+
try:
576+
with deadline_guard(meter, what="node 'n'"):
577+
time.sleep(0.2) # outlast the deadline; nothing interrupts it
578+
outcome["raised"] = None
579+
except NodeDeadlineExceeded as exc:
580+
outcome["raised"] = exc
581+
582+
worker = threading.Thread(target=body)
583+
worker.start()
584+
worker.join(timeout=10)
585+
assert not worker.is_alive()
586+
assert isinstance(outcome["raised"], NodeDeadlineExceeded), (
587+
"the node overran, no interrupt fired, and the guard let its writes land"
588+
)
589+
590+
545591
def test_a_node_that_finishes_in_time_is_left_alone():
546592
def brisk(state):
547593
time.sleep(0.05)

tests/test_cli.py

Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -336,6 +336,43 @@ def test_viz_renders_the_executed_path(two_runs, capsys):
336336
assert "load" in payload["mermaid"]
337337

338338

339+
# Every reading command, with the arguments it needs beyond the path. `metrics`
340+
# and `viz` never reach the run id: the file refuses before any run is looked up.
341+
READERS = [["trace"], ["metrics", "r1"], ["viz", "r1"]]
342+
343+
344+
def _bad_trace(tmp_path) -> Path:
345+
"""A trace whose second line is not an event — a process killed mid-write."""
346+
trace = TraceRecorder(tmp_path / "bad.jsonl")
347+
trace.event(run_id="r1", graph="g", node="load", phase="start", step=1)
348+
with trace.path.open("a", encoding="utf-8") as f:
349+
f.write('{"not": "a trace event"}\n')
350+
return trace.path
351+
352+
353+
@pytest.mark.parametrize("argv", READERS, ids=lambda argv: argv[0])
354+
def test_a_malformed_trace_is_a_report_not_a_traceback(argv, tmp_path, capsys):
355+
"""The contract in `output.py` names "an unreadable trace" as exit 2."""
356+
bad = _bad_trace(tmp_path)
357+
code, out, err = call([argv[0], str(bad), *argv[1:]], capsys)
358+
assert code == 2
359+
assert out == ""
360+
assert f"error: unreadable trace file: {bad}: line 2 is not a trace event\n" == err
361+
362+
363+
@pytest.mark.parametrize("argv", READERS, ids=lambda argv: argv[0])
364+
def test_a_malformed_trace_fails_as_one_json_document(argv, tmp_path, capsys):
365+
bad = _bad_trace(tmp_path)
366+
code, payload, err = call_json([argv[0], str(bad), *argv[1:]], capsys)
367+
assert code == 2
368+
assert payload == {
369+
"ok": False,
370+
"command": argv[0],
371+
"error": f"unreadable trace file: {bad}: line 2 is not a trace event",
372+
}
373+
assert err == ""
374+
375+
339376
# -- models -------------------------------------------------------------------
340377

341378

0 commit comments

Comments
 (0)