traces
This commit is contained in:
@@ -7,7 +7,7 @@ import time
|
||||
from dataclasses import dataclass, field
|
||||
from datetime import datetime
|
||||
from pathlib import Path
|
||||
from typing import Any, TextIO
|
||||
from typing import Any, Callable, TextIO
|
||||
|
||||
from .bench_connect_lcd import (
|
||||
BenchLogger,
|
||||
@@ -21,6 +21,7 @@ from .bench_connect_lcd import (
|
||||
_send_frame,
|
||||
_wait_for_ready,
|
||||
format_frame,
|
||||
frame_checksum,
|
||||
frame_checksum_ok,
|
||||
parse_frame,
|
||||
serial_format_label,
|
||||
@@ -30,6 +31,7 @@ from .serial_table_dump import build_read_frame, decode_table_read_response
|
||||
|
||||
DEFAULT_ACK_TARGET = bytes.fromhex("07804020902D")
|
||||
DEFAULT_ACK_FRAME = bytes.fromhex("05004000001F")
|
||||
HEARTBEAT_FRAME = bytes.fromhex("0000000080DA")
|
||||
|
||||
|
||||
@dataclass
|
||||
@@ -69,6 +71,11 @@ def build_arg_parser() -> argparse.ArgumentParser:
|
||||
parser.add_argument("--sync", choices=("checksum", "fixed"), default="checksum", help="RX frame sync strategy")
|
||||
parser.add_argument("--log", type=Path, help="capture log path")
|
||||
parser.add_argument("--result-json", type=Path, help="write machine-readable scenario summary")
|
||||
parser.add_argument(
|
||||
"--quiet-console",
|
||||
action="store_true",
|
||||
help="keep full logs in --log but suppress RX/DETECT chatter on the console",
|
||||
)
|
||||
parser.add_argument("--dry-run", action="store_true", help="print the plan without opening serial ports")
|
||||
return parser
|
||||
|
||||
@@ -83,7 +90,8 @@ def main(argv: list[str] | None = None, *, stdout: TextIO = sys.stdout) -> int:
|
||||
return 0
|
||||
|
||||
serial = _import_serial()
|
||||
logger = BenchLogger(log_path, stdout=stdout)
|
||||
console = _FilteredStdout(stdout, _quiet_console_line) if args.quiet_console else stdout
|
||||
logger = BenchLogger(log_path, stdout=console)
|
||||
detector = FrameDetector(sync_mode=args.sync)
|
||||
try:
|
||||
logger.emit("Serial bench scenario")
|
||||
@@ -165,6 +173,8 @@ def _run_step(ctx: ScenarioContext, action: str, spec: dict[str, Any]) -> None:
|
||||
raise SystemExit(2)
|
||||
elif action in {"drain", "listen", "wait"}:
|
||||
_listen(ctx, float(spec.get("seconds", spec.get("value", 0.0))))
|
||||
elif action == "listen_ack":
|
||||
_step_listen_ack(ctx, spec)
|
||||
elif action == "send":
|
||||
frame = _parse_required_frame(spec.get("frame"))
|
||||
label = str(spec.get("label", "send"))
|
||||
@@ -173,6 +183,10 @@ def _run_step(ctx: ScenarioContext, action: str, spec: dict[str, Any]) -> None:
|
||||
_listen(ctx, float(spec.get("listen", 0.0)))
|
||||
elif action == "wait_for":
|
||||
_step_wait_for(ctx, spec)
|
||||
elif action == "prompt":
|
||||
_step_prompt(ctx, spec)
|
||||
elif action == "note":
|
||||
_step_note(ctx, spec)
|
||||
elif action == "table_sweep":
|
||||
_step_table_sweep(ctx, spec)
|
||||
elif action == "repeat":
|
||||
@@ -214,6 +228,24 @@ def _step_wait_for(ctx: ScenarioContext, spec: dict[str, Any]) -> None:
|
||||
raise SystemExit(3)
|
||||
|
||||
|
||||
def _step_prompt(ctx: ScenarioContext, spec: dict[str, Any]) -> None:
|
||||
message = str(spec.get("message", spec.get("value", "Press Enter to continue.")))
|
||||
ctx.logger.event(f"PROMPT {message}")
|
||||
input(message + " ")
|
||||
|
||||
|
||||
def _step_note(ctx: ScenarioContext, spec: dict[str, Any]) -> None:
|
||||
message = str(spec.get("message", spec.get("value", "")))
|
||||
if bool(spec.get("banner", False)):
|
||||
ctx.logger.emit("")
|
||||
ctx.logger.emit("NOTE " + "=" * 68)
|
||||
ctx.logger.event(f"NOTE {message}")
|
||||
ctx.logger.emit("NOTE " + "=" * 68)
|
||||
ctx.logger.emit("")
|
||||
else:
|
||||
ctx.logger.event(f"NOTE {message}")
|
||||
|
||||
|
||||
def _step_repeat(ctx: ScenarioContext, spec: dict[str, Any]) -> None:
|
||||
count = max(0, int(spec.get("count", 1)))
|
||||
steps = spec.get("steps", [])
|
||||
@@ -248,10 +280,52 @@ def _step_table_sweep(ctx: ScenarioContext, spec: dict[str, Any]) -> None:
|
||||
_listen_with_ack(ctx, gap, selector, ack)
|
||||
|
||||
|
||||
def _step_listen_ack(ctx: ScenarioContext, spec: dict[str, Any]) -> None:
|
||||
seconds = float(spec.get("seconds", spec.get("value", 1.0)))
|
||||
ack = _ack_config(
|
||||
{
|
||||
"enabled": spec.get("enabled", True),
|
||||
"frames": spec.get("frames", spec.get("frame")),
|
||||
"ack_frame": spec.get("ack_frame"),
|
||||
"ack_guard": spec.get("ack_guard", 0.020),
|
||||
"poll_interval": spec.get("poll_interval", 0.005),
|
||||
"post_ack_read": spec.get("post_ack_read", 0.250),
|
||||
"once_per_selector": spec.get("once_per_frame", False),
|
||||
"max_acks": spec.get("max_acks"),
|
||||
"max_target_hits": spec.get("max_target_hits"),
|
||||
"abort_on_limit": spec.get("abort_on_limit", False),
|
||||
"ack_mode": spec.get("ack_mode", spec.get("mode", "fixed")),
|
||||
"target_mode": spec.get("target_mode", spec.get("match", "explicit")),
|
||||
"limit_scope": spec.get("limit_scope", spec.get("scope", "local")),
|
||||
}
|
||||
)
|
||||
ack_text = (
|
||||
f"ack_frame={format_frame(ack['frame'])}"
|
||||
if ack["ack_mode"] == "fixed"
|
||||
else f"ack_mode={ack['ack_mode']}"
|
||||
)
|
||||
ctx.logger.event(
|
||||
f"LISTEN_ACK seconds={seconds:.3f} target_mode={ack['target_mode']} targets={len(ack['targets'])} "
|
||||
f"{ack_text} limit_scope={ack['limit_scope']} max_acks={ack['max_acks']}"
|
||||
)
|
||||
_listen_with_ack(ctx, seconds, None, ack)
|
||||
|
||||
|
||||
def _ack_config(raw: Any) -> dict[str, Any]:
|
||||
spec = raw if isinstance(raw, dict) else {}
|
||||
enabled = bool(spec.get("enabled", True))
|
||||
targets = _parse_frame_list(spec.get("frames", spec.get("frame", DEFAULT_ACK_TARGET)))
|
||||
ack_mode = str(spec.get("ack_mode", spec.get("mode", "fixed"))).strip().lower().replace("-", "_")
|
||||
if ack_mode not in {"fixed", "cmd5_selector"}:
|
||||
raise SystemExit(f"unknown ack_mode {ack_mode!r}")
|
||||
target_mode = str(spec.get("target_mode", spec.get("match", "explicit"))).strip().lower().replace("-", "_")
|
||||
if target_mode == "queued_report":
|
||||
target_mode = "queued_reports"
|
||||
if target_mode not in {"explicit", "queued_reports"}:
|
||||
raise SystemExit(f"unknown target_mode {target_mode!r}")
|
||||
limit_scope = str(spec.get("limit_scope", spec.get("scope", "global"))).strip().lower().replace("-", "_")
|
||||
if limit_scope not in {"global", "local"}:
|
||||
raise SystemExit(f"unknown limit_scope {limit_scope!r}")
|
||||
targets = set() if target_mode == "queued_reports" else _parse_frame_list(spec.get("frames", spec.get("frame", DEFAULT_ACK_TARGET)))
|
||||
if not enabled:
|
||||
targets = set()
|
||||
return {
|
||||
@@ -265,9 +339,29 @@ def _ack_config(raw: Any) -> dict[str, Any]:
|
||||
"max_acks": _optional_int(spec.get("max_acks")),
|
||||
"max_target_hits": _optional_int(spec.get("max_target_hits")),
|
||||
"abort_on_limit": bool(spec.get("abort_on_limit", True)),
|
||||
"ack_mode": ack_mode,
|
||||
"target_mode": target_mode,
|
||||
"limit_scope": limit_scope,
|
||||
}
|
||||
|
||||
|
||||
def _ack_frame_for_target(target: bytes, ack: dict[str, Any]) -> bytes:
|
||||
if ack["ack_mode"] == "fixed":
|
||||
return ack["frame"]
|
||||
if len(target) != 6:
|
||||
raise SystemExit(f"cannot build selector ACK for malformed target {target!r}")
|
||||
body = bytes([0x05, target[1] & 0x7F, target[2], 0x00, 0x00])
|
||||
return body + bytes([frame_checksum(body)])
|
||||
|
||||
|
||||
def _ack_matches(frame: bytes, ack: dict[str, Any]) -> bool:
|
||||
if ack["target_mode"] == "explicit":
|
||||
return frame in ack["targets"]
|
||||
if frame == HEARTBEAT_FRAME or not frame_checksum_ok(frame):
|
||||
return False
|
||||
return frame[0] in {0x00, 0x01, 0x02} and not (frame[1] & 0x80)
|
||||
|
||||
|
||||
def _listen_with_ack(
|
||||
ctx: ScenarioContext,
|
||||
seconds: float,
|
||||
@@ -277,6 +371,8 @@ def _listen_with_ack(
|
||||
deadline = time.monotonic() + max(0.0, seconds)
|
||||
observed: list[bytes] = []
|
||||
acked_targets: set[bytes] = set()
|
||||
ack_start = ctx.ack_sent
|
||||
target_start = sum(ctx.target_counts.values())
|
||||
while time.monotonic() < deadline:
|
||||
frames = _read_available(ctx, selector=selector)
|
||||
observed.extend(frames)
|
||||
@@ -288,10 +384,10 @@ def _listen_with_ack(
|
||||
if not ack["enabled"]:
|
||||
continue
|
||||
for frame in frames:
|
||||
if frame not in ack["targets"]:
|
||||
if not _ack_matches(frame, ack):
|
||||
continue
|
||||
_count_target(ctx, frame)
|
||||
if _ack_limit_reached(ctx, ack):
|
||||
if _ack_limit_reached(ctx, ack, ack_start=ack_start, target_start=target_start):
|
||||
ctx.logger.event("ACK_LIMIT reached before ACK send")
|
||||
if ack["abort_on_limit"]:
|
||||
ctx.abort_requested = True
|
||||
@@ -302,9 +398,9 @@ def _listen_with_ack(
|
||||
acked_targets.add(frame)
|
||||
if ack["guard"] > 0:
|
||||
observed.extend(_listen(ctx, ack["guard"], selector=selector))
|
||||
_send_and_record(ctx, ack["frame"], "ack")
|
||||
_send_and_record(ctx, _ack_frame_for_target(frame, ack), "ack")
|
||||
ctx.ack_sent += 1
|
||||
if _ack_limit_reached(ctx, ack):
|
||||
if _ack_limit_reached(ctx, ack, ack_start=ack_start, target_start=target_start):
|
||||
ctx.logger.event("ACK_LIMIT reached after ACK send")
|
||||
if ack["abort_on_limit"]:
|
||||
ctx.abort_requested = True
|
||||
@@ -440,12 +536,24 @@ def _optional_int(raw: Any) -> int | None:
|
||||
return _int_value(raw)
|
||||
|
||||
|
||||
def _ack_limit_reached(ctx: ScenarioContext, ack: dict[str, Any]) -> bool:
|
||||
def _ack_limit_reached(
|
||||
ctx: ScenarioContext,
|
||||
ack: dict[str, Any],
|
||||
*,
|
||||
ack_start: int = 0,
|
||||
target_start: int = 0,
|
||||
) -> bool:
|
||||
if ack.get("limit_scope") == "local":
|
||||
ack_count = ctx.ack_sent - ack_start
|
||||
target_count = sum(ctx.target_counts.values()) - target_start
|
||||
else:
|
||||
ack_count = ctx.ack_sent
|
||||
target_count = sum(ctx.target_counts.values())
|
||||
max_acks = ack.get("max_acks")
|
||||
if max_acks is not None and ctx.ack_sent >= max_acks:
|
||||
if max_acks is not None and ack_count >= max_acks:
|
||||
return True
|
||||
max_target_hits = ack.get("max_target_hits")
|
||||
if max_target_hits is not None and sum(ctx.target_counts.values()) >= max_target_hits:
|
||||
if max_target_hits is not None and target_count >= max_target_hits:
|
||||
return True
|
||||
return False
|
||||
|
||||
@@ -462,6 +570,51 @@ def _print_dry_run(args: argparse.Namespace, scenario: dict[str, Any], log_path:
|
||||
_print_step_dry_run(action, spec, stdout)
|
||||
|
||||
|
||||
class _FilteredStdout:
|
||||
def __init__(self, stdout: TextIO, predicate: Callable[[str], bool]) -> None:
|
||||
self.stdout = stdout
|
||||
self.predicate = predicate
|
||||
self.buffer = ""
|
||||
|
||||
def write(self, text: str) -> int:
|
||||
self.buffer += text
|
||||
while "\n" in self.buffer:
|
||||
line, self.buffer = self.buffer.split("\n", 1)
|
||||
if self.predicate(line):
|
||||
self.stdout.write(line + "\n")
|
||||
self.stdout.flush()
|
||||
return len(text)
|
||||
|
||||
def flush(self) -> None:
|
||||
if self.buffer:
|
||||
if self.predicate(self.buffer):
|
||||
self.stdout.write(self.buffer)
|
||||
self.buffer = ""
|
||||
self.stdout.flush()
|
||||
|
||||
|
||||
def _quiet_console_line(line: str) -> bool:
|
||||
if not line.strip():
|
||||
return True
|
||||
keep_fragments = (
|
||||
"Serial bench scenario",
|
||||
"name=",
|
||||
"device=",
|
||||
"log=",
|
||||
"STEP ",
|
||||
"PROMPT ",
|
||||
"NOTE ",
|
||||
"Summary",
|
||||
"rx_frames=",
|
||||
"resync_events=",
|
||||
"tx_frames=",
|
||||
"abort_requested=",
|
||||
"known_shutter",
|
||||
"queued_shutter",
|
||||
)
|
||||
return any(fragment in line for fragment in keep_fragments)
|
||||
|
||||
|
||||
def _print_step_dry_run(action: str, spec: dict[str, Any], stdout: TextIO, *, indent: str = " ") -> None:
|
||||
if action == "send":
|
||||
frame = _parse_required_frame(spec.get("frame"))
|
||||
@@ -470,6 +623,42 @@ def _print_step_dry_run(action: str, spec: dict[str, Any], stdout: TextIO, *, in
|
||||
print(f"{indent}listen={float(spec.get('listen', 0.0)):.3f}s", file=stdout)
|
||||
elif action in {"drain", "listen", "wait"}:
|
||||
print(f"{indent}seconds={float(spec.get('seconds', spec.get('value', 0.0))):.3f}", file=stdout)
|
||||
elif action == "listen_ack":
|
||||
ack = _ack_config(
|
||||
{
|
||||
"enabled": spec.get("enabled", True),
|
||||
"frames": spec.get("frames", spec.get("frame")),
|
||||
"ack_frame": spec.get("ack_frame"),
|
||||
"ack_guard": spec.get("ack_guard", 0.020),
|
||||
"poll_interval": spec.get("poll_interval", 0.005),
|
||||
"post_ack_read": spec.get("post_ack_read", 0.250),
|
||||
"once_per_selector": spec.get("once_per_frame", False),
|
||||
"max_acks": spec.get("max_acks"),
|
||||
"max_target_hits": spec.get("max_target_hits"),
|
||||
"abort_on_limit": spec.get("abort_on_limit", False),
|
||||
"ack_mode": spec.get("ack_mode", spec.get("mode", "fixed")),
|
||||
"target_mode": spec.get("target_mode", spec.get("match", "explicit")),
|
||||
"limit_scope": spec.get("limit_scope", spec.get("scope", "local")),
|
||||
}
|
||||
)
|
||||
print(f"{indent}seconds={float(spec.get('seconds', spec.get('value', 1.0))):.3f}", file=stdout)
|
||||
if not ack["enabled"]:
|
||||
print(f"{indent}ack=disabled", file=stdout)
|
||||
else:
|
||||
print(f"{indent}target_mode={ack['target_mode']}", file=stdout)
|
||||
for target in sorted(ack["targets"]):
|
||||
print(f"{indent}ack_target={format_frame(target)}", file=stdout)
|
||||
print(f"{indent}ack_mode={ack['ack_mode']}", file=stdout)
|
||||
if ack["ack_mode"] == "fixed":
|
||||
print(f"{indent}ack_frame={format_frame(ack['frame'])}", file=stdout)
|
||||
print(
|
||||
f"{indent}limit_scope={ack['limit_scope']} max_acks={ack['max_acks']} "
|
||||
f"max_target_hits={ack['max_target_hits']}",
|
||||
file=stdout,
|
||||
)
|
||||
elif action in {"prompt", "note"}:
|
||||
message = str(spec.get("message", spec.get("value", "Press Enter to continue.")))
|
||||
print(f"{indent}message={message}", file=stdout)
|
||||
elif action == "wait_ready":
|
||||
print(
|
||||
f"{indent}heartbeats={int(spec.get('heartbeats', 2))} "
|
||||
@@ -493,7 +682,11 @@ def _print_step_dry_run(action: str, spec: dict[str, Any], stdout: TextIO, *, in
|
||||
for target in sorted(ack["targets"]):
|
||||
print(f"{indent}ack_target={format_frame(target)}", file=stdout)
|
||||
print(f"{indent}ack_frame={format_frame(ack['frame'])}", file=stdout)
|
||||
print(f"{indent}max_acks={ack['max_acks']} max_target_hits={ack['max_target_hits']}", file=stdout)
|
||||
print(
|
||||
f"{indent}limit_scope={ack['limit_scope']} max_acks={ack['max_acks']} "
|
||||
f"max_target_hits={ack['max_target_hits']}",
|
||||
file=stdout,
|
||||
)
|
||||
elif action == "repeat":
|
||||
count = max(0, int(spec.get("count", 1)))
|
||||
steps = spec.get("steps", [])
|
||||
|
||||
Reference in New Issue
Block a user