diff --git a/keel/commands/activity.py b/keel/commands/activity.py new file mode 100644 index 00000000..55c4766c --- /dev/null +++ b/keel/commands/activity.py @@ -0,0 +1,1053 @@ +"""The activity feed -- a chronological, newest-first reconstruction of what the agent has +actually been *doing*, grouped one row per engine cycle, built from the structured JSONL engine +log. The pure substrate for `keel tui`'s `v` overlay, kept out of `tui.py` for exactly the reason +`insights.py` and `admission.py` are: grouping and summarising are ordinary, thoroughly testable +functions, and curses rendering is not. + +**Why the log, and not the database.** The dashboard already reports *state* -- equity, positions, +freshness, rails -- and state is precisely what looks dead when nothing trades: a deployment that +has run flawlessly for three weeks and correctly declined every setup shows the same zeroes as one +that crashed on day one. What distinguishes them is the *narrative*, and the narrative already +exists: every cycle emits `agent.cycle_start`, `agent.feed_polled`, `agent.signals_evaluated`, +`engine.setup_detected`/`setup_rejected`, `guards.check_failed`, `agent.enter_evaluated` ... all +correlated by the `cycle_id` `keel/agent.py` binds via `keel_core.telemetry.bind_cycle`. A new DB +table would have been the tidier design and the wrong one: it would start EMPTY on the very +deployment this feature exists to explain, reproducing the "nothing is happening" impression for +however many weeks it took to fill. The log is already months deep. No schema change, no +migration, no engine change -- this module only *reads*. + +**Why this is admissible under the TUI's iron rule.** `keel tui`'s overlays are "DB reads only; +never builds a broker, never touches the network". Reading a local file is neither: nothing here +constructs a broker, opens a socket, or resolves a name. The rule's purpose is that opening an +overlay can never place an order, spend money, or hang on a remote host, and a bounded read of a +file on the same disk violates none of that. It is the same latitude `p` propose already takes to +read `config.proposals_dir`. + +**The read is BOUNDED, on purpose.** The log grows without limit between rotations +(`LoggingConfig.max_file_mb` defaults to 25 MB per file), and this overlay is rebuilt on EVERY +poll while it is open -- typically every 5 seconds. Parsing the whole file would make the +dashboard's responsiveness a function of how long the deployment has been running, which is the +one thing an operator dashboard must never do. So three hard caps, all named constants below: +`_MAX_BYTES` (1 MiB) of the file's TAIL is read, at most `_MAX_LINES` (5000) lines are parsed +from it, and at most `_MAX_CYCLES` (200) cycles are retained. 1 MiB is chosen to comfortably +exceed a real deployment's whole current log (815 KB and ~330 lines, because each ERROR record +carries a full traceback) while staying a fixed, few-millisecond read against a 25 MB one. When a +cap bites, the feed SAYS so rather than silently pretending the window is the whole history. + +**Everything degrades to a sentence, never a traceback.** This reads a file this process does not +own, which another process is appending to and may rotate out from under it at any moment. A +missing file, an empty one, a permissions error, a partial JSON line from a crash mid-write, a +line predating `cycle_id` entirely, an event carrying fields no version of this code has seen -- +each has a defined, tested outcome, and none of them is an exception escaping to the live loop or +(worse) a blank overlay that looks exactly like the dead dashboard this feature exists to +disprove. `build_activity_feed` is total: it returns an `ActivityFeed` for every input, including +inputs that are not a log at all. + +**Uncorrelated events still count.** `cycle_id` is bound per engine cycle, so events emitted +outside one -- a `keel balance` invocation's `cb_client.accounts_fetch_failed`, or anything logged +by a build that predates the correlation id -- carry none. Dropping them would hide the single +most informative thing in one real deployment's log (64 consecutive account-fetch failures). They +are instead gathered into synthetic groups: a contiguous run of uncorrelated events whose +neighbours are within `_UNCORRELATED_GAP_SEC` of each other becomes one row, which is what such +events actually are -- one failed attempt at something. +""" + +from __future__ import annotations + +import json +import time +from collections.abc import Iterable, Mapping, Sequence +from dataclasses import dataclass +from pathlib import Path +from typing import Any + +# -- bounds (see the module docstring) ----------------------------------------------------------- + +#: Bytes of the log's TAIL that are ever read in one build. The whole point of the tail read is +#: that cost is independent of how long the deployment has been running. +_MAX_BYTES = 1024 * 1024 + +#: Lines parsed from that window, newest kept. A second, independent cap: one MiB of a log whose +#: records are short (no tracebacks) could be tens of thousands of lines, and `json.loads` per +#: line is the expensive part, not the read. +_MAX_LINES = 5_000 + +#: Cycles retained after grouping, newest kept. Bounds the overlay itself, not just the parse -- +#: an operator scrolls tens of rows, never thousands. +_MAX_CYCLES = 200 + +#: Events retained per cycle for the expanded view. Counts in the collapsed row are computed over +#: ALL of a cycle's events first, so a cycle that hits this cap still reports honest totals; only +#: the expansion is trimmed (to the newest), and it says so. +_MAX_EVENTS_PER_CYCLE = 400 + +#: Seconds between two consecutive `cycle_id`-less events beyond which they are treated as two +#: separate attempts rather than one. The real deployment emits these in tight pairs +#: (`cb_client.accounts_fetch_failed` + `executor.quote_fetch_failed`, same second) roughly every +#: 16 minutes, so anything between "same second" and "minutes" separates them correctly; 60s is +#: comfortably inside that gap on both sides. +_UNCORRELATED_GAP_SEC = 60.0 + +#: Cap on one rendered event-detail string. `exc` fields carry whole tracebacks and `violation` +#: strings carry full-precision Decimals; neither may be allowed to define the width of a row. +_DETAIL_MAX_CHARS = 220 + +#: How many notable markers a collapsed row shows before it summarises the rest as "+N more". +_MAX_HIGHLIGHTS = 3 + +#: The window of epoch seconds a `ts` is allowed to fall in -- 1970-01-01 to 2100-01-01. `ts` is +#: written by another process, and `time.localtime`/`time.strftime` raise (`OverflowError`, +#: `ValueError`) rather than degrade on a value outside the platform's `time_t`, on a NaN, or on a +#: year past 9999. A single such record -- a bad clock, a hand-edited line, a corrupted byte -- +#: would otherwise reach the RENDERER, which is called from the live loop's repaint path and would +#: take the whole dashboard down with it. A timestamp outside this window is treated exactly like +#: a missing one (the neighbouring record's time is borrowed), which is both safe and, for a +#: garbled line in an append-ordered file, very nearly right. +_MIN_TS = 0.0 +_MAX_TS = 4_102_444_800.0 + +#: Levels that count toward a cycle's `errors`. +_ERROR_LEVELS = frozenset({"ERROR", "CRITICAL", "FATAL"}) + +#: Payload keys `keel_core.telemetry.JsonFormatter` writes itself -- excluded from the generic +#: `key=value` fallback detail so an unrecognised event renders its OWN fields, not the envelope +#: every event shares. +_ENVELOPE_KEYS = frozenset({"ts", "level", "logger", "event", "cycle_id", "venue"}) + +#: The default log path, matching `keel_core.config.LoggingConfig.file`'s own default. Used only +#: when a config object cannot supply one -- the path normally comes from `logging.file` in +#: config.yaml, so a deployment that writes its log somewhere else is already configurable and +#: needs no new setting. +_DEFAULT_LOG_PATH = "logs/keel.log" + + +# -- the parsed model ---------------------------------------------------------------------------- + + +@dataclass(frozen=True) +class ActivityEvent: + """One structured log record, normalised. `fields` holds everything that is not envelope -- + deliberately kept whole rather than projected onto a fixed schema, because the event + vocabulary grows (every `log_event` call site invents its own kwargs) and an overlay that + silently dropped a field it had not been taught about would be worse than one that renders it + as `key=value`.""" + + ts: float + level: str + event: str + cycle_id: str | None + fields: Mapping[str, Any] + + +@dataclass(frozen=True) +class ActivityCycle: + """One engine cycle (or one synthetic group of uncorrelated events), summarised into the + counts a collapsed row shows plus the events an expanded one lists. + + `cycle_id is None` marks a synthetic group -- see the module docstring. `key` is what the + overlay's expansion set stores, and is stable across repaints so an expanded cycle stays + expanded while the feed is rebuilt underneath it every poll.""" + + cycle_id: str | None + started_ts: float + ended_ts: float + mode: str | None + products: tuple[str, ...] + rules: tuple[str, ...] + signals: int + blocked: int + entered: int + exited: int + errors: int + highlights: tuple[str, ...] + events: tuple[ActivityEvent, ...] + events_dropped: int = 0 + + @property + def key(self) -> str: + """Stable identity for the overlay's expansion set. Uncorrelated groups have no id of + their own, so they borrow their start time -- unique enough in practice (two distinct + groups are separated by at least `_UNCORRELATED_GAP_SEC`) and, crucially, stable across + repaints, which is the property the expansion set actually needs.""" + if self.cycle_id is not None: + return self.cycle_id + return f"uncorrelated@{self.started_ts:.3f}" + + @property + def is_uncorrelated(self) -> bool: + return self.cycle_id is None + + @property + def is_quiet(self) -> bool: + """A cycle in which the agent looked at the market and nothing happened -- no signal, no + block, no fill, no error. The overwhelming majority of rows, by design, and the reason + the feed answers "is it alive": a long run of quiet cycles is a *positive* observation, + not an absence of one, so quiet rows are rendered muted but never omitted.""" + return not (self.signals or self.blocked or self.entered or self.exited or self.errors) + + +@dataclass(frozen=True) +class ActivityFeed: + """The whole overlay's input. Total by construction -- there is an `ActivityFeed` for a + missing log, an empty one, and one that is not JSON at all. + + `status` is one of: + + * `"ok"` -- the log was read and at least one line parsed. + * `"missing"` -- no file at `source`. The commonest case by far, and NOT an error: `keel tui` + run from a directory that is not the deployment root resolves `logging.file`'s relative + default against the wrong cwd, and the overlay says exactly that. + * `"empty"` -- the file exists but the window held no non-blank line. + * `"unparseable"` -- lines were read but not one of them was a JSON object. Distinguished + from `"empty"` because the two have completely different fixes. + * `"oversized"` -- the bounded tail read landed entirely inside a single record, so nothing + whole survived the boundary trim. Also distinguished from `"empty"`: the file is anything + but. + * `"unreadable"` -- an `OSError` (permissions, a directory where a file was expected, a file + deleted between the open and the read). `detail` carries the reason. + + `lines_skipped` counts lines that were read but could not be used -- the partial JSON a crash + mid-write leaves behind, a line that is valid JSON but not an object, a record with no usable + timestamp. It is surfaced in the overlay rather than swallowed: silently discarding input is + how a feed comes to under-report reality while looking healthy.""" + + status: str + source: str + cycles: tuple[ActivityCycle, ...] = () + detail: str | None = None + lines_read: int = 0 + lines_skipped: int = 0 + window_truncated: bool = False + cycles_dropped: int = 0 + + +@dataclass(frozen=True) +class LogWindow: + """The bounded tail read of the log file, before any parsing. Split out from + `build_activity_feed` so the read (the only I/O in this module) and the grouping (the part + worth testing exhaustively) never have to be exercised together.""" + + lines: tuple[str, ...] = () + status: str = "ok" + detail: str | None = None + truncated: bool = False + size_bytes: int = 0 + + +# -- path resolution ----------------------------------------------------------------------------- + + +def resolve_log_path(config: Any) -> Path: + """The engine log this deployment writes, taken from `logging.file` in config.yaml (parsed + into `keel_core.config.LoggingConfig`) rather than hardcoded -- so the overlay reads whatever + file `keel_core.logging_setup.configure_logging` actually attached its `RotatingFileHandler` + to, and a deployment that moved its log needs no second setting to keep this working. + + That default (`logs/keel.log`) is RELATIVE, which is a feature here and not an oversight: the + engine resolves it against its working directory, so a `keel tui` run from the deployment root + (`~/keel`, where the LaunchAgents run the agent and where the log therefore lives) resolves it + to the same file. Run from anywhere else, it resolves somewhere else -- which is why a missing + file is reported with the resolved ABSOLUTE path, so the mismatch is visible at a glance + instead of looking like an empty history. + + Never raises: a config object without a readable `logging.file` falls back to the same default + `LoggingConfig` itself declares.""" + raw: Any = None + try: + raw = config.logging.file + except Exception: + raw = None + if not isinstance(raw, str) or not raw.strip(): + raw = _DEFAULT_LOG_PATH + try: + return Path(raw).expanduser().resolve() + except OSError: + # `resolve()` can raise on a path with a broken symlink component on some platforms. + return Path(raw) + + +# -- the bounded read (the only I/O here) ---------------------------------------------------------- + + +def read_log_window( + path: Path, *, max_bytes: int = _MAX_BYTES, max_lines: int = _MAX_LINES +) -> LogWindow: + """Read at most `max_bytes` from the END of `path`, keep at most the last `max_lines` lines. + + Three details carry the robustness: + + * **The partial first line is dropped.** Seeking to `size - max_bytes` lands mid-record + whenever the cap bites, so everything up to and including the first newline is discarded -- + the alternative is feeding half a JSON object to the parser and counting a phantom + malformed line on every single repaint. + * **Decoding never raises.** `errors="replace"` -- a log with a byte sequence that is not + UTF-8 (a truncated multi-byte character at a rotation boundary, say) degrades to a visible + replacement character in one field, not an overlay that refuses to render. + * **Rotation is a non-event.** The file is opened by path on every build, so once + `RotatingFileHandler` renames the old file aside, the next build simply reads the new, small + one. The rotated-away history is deliberately NOT chased into `keel.log.1`: an operator + dashboard reading files the running process has already closed would be guessing at + ordering, and the feed reports a short history honestly instead. + + Returns a `LogWindow` for every outcome. The only exceptions it does not catch are the ones + that must not be caught (`KeyboardInterrupt`, `MemoryError` -- neither is an `OSError`).""" + try: + with open(path, "rb") as fh: + fh.seek(0, 2) + size = fh.tell() + truncated = size > max_bytes + fh.seek(size - max_bytes if truncated else 0) + blob = fh.read() + except FileNotFoundError: + return LogWindow(status="missing", detail=f"no engine log at {path}") + except OSError as exc: + return LogWindow(status="unreadable", detail=f"{type(exc).__name__}: {exc}") + + if truncated: + newline = blob.find(b"\n") + blob = b"" if newline < 0 else blob[newline + 1 :] + + lines = blob.decode("utf-8", errors="replace").splitlines() + if len(lines) > max_lines: + lines = lines[-max_lines:] + truncated = True + + if not any(line.strip() for line in lines): + if truncated: + # The window landed inside ONE record -- an ERROR line carrying a traceback can be + # kilobytes on its own -- so the boundary trim left nothing whole behind. Reporting + # this as "empty" would print "engine log is empty (815357 bytes)", which is + # self-contradictory and sends an operator hunting for the wrong problem. + return LogWindow( + status="oversized", + detail=( + f"no complete record in the newest {max_bytes // 1024} KiB of {path} " + f"({size} bytes total) -- one record spans the whole read window" + ), + truncated=True, + size_bytes=size, + ) + return LogWindow( + status="empty", + detail=f"engine log is empty ({size} bytes at {path})", + truncated=truncated, + size_bytes=size, + ) + return LogWindow(lines=tuple(lines), truncated=truncated, size_bytes=size) + + +# -- parsing (pure) -------------------------------------------------------------------------------- + + +def _as_float(value: Any) -> float | None: + if isinstance(value, bool): + return None + if isinstance(value, int | float): + return float(value) + if isinstance(value, str): + try: + return float(value) + except ValueError: + return None + return None + + +def _as_timestamp(value: Any) -> float | None: + """A `ts` this module is willing to hand to `time.localtime` -- see `_MIN_TS`/`_MAX_TS`. + + `nan` falls out for free: every comparison against it is `False`, so it fails the range test + without needing a separate `math.isnan` check. `inf` fails it the same way.""" + ts = _as_float(value) + if ts is None or not (_MIN_TS <= ts <= _MAX_TS): + return None + return ts + + +def _as_int(value: Any) -> int: + if isinstance(value, bool): + return int(value) + if isinstance(value, int): + return value + if isinstance(value, float): + return int(value) + if isinstance(value, str): + try: + return int(float(value)) + except (ValueError, OverflowError): + # `float("inf")` PARSES -- it is `int()` that then raises `OverflowError`, which is + # not a `ValueError`. Letting that escape would abort the whole grouping pass over a + # single garbled `signal_count`, discarding every other, perfectly good cycle in the + # window: one bad line would empty the entire feed. + return 0 + return 0 + + +def _as_bool(value: Any) -> bool: + """`placed` is written as a real JSON bool today, but a string `"false"` (from an older build, + or a field that went through an f-string on the way in) must never read as True -- which is + precisely what a bare `bool(value)` would do, and would have this feed report an entry that + never happened.""" + if isinstance(value, str): + return value.strip().lower() in {"true", "1", "yes"} + return bool(value) + + +def parse_events(lines: Iterable[str]) -> tuple[list[ActivityEvent], int]: + """Parse JSONL into `ActivityEvent`s, returning them with the count of lines that could not + be used. PURE -- takes an iterable of strings, so every degradation is testable without a + filesystem. + + A record with no usable `ts` inherits the previous record's timestamp rather than being + dropped: the log is append-ordered, so its neighbour's time is very nearly right, and showing + an event slightly imprecisely beats hiding it. Only a record with no usable timestamp AND no + predecessor to borrow one from is unplaceable, and is counted as skipped.""" + events: list[ActivityEvent] = [] + skipped = 0 + last_ts: float | None = None + + for raw in lines: + text = raw.strip() + if not text: + continue + try: + obj = json.loads(text) + except ValueError: + # A partial line from a crash mid-write, a rotation boundary, or simply not JSON. + skipped += 1 + continue + if not isinstance(obj, dict): + skipped += 1 + continue + + ts = _as_timestamp(obj.get("ts")) + if ts is None: + if last_ts is None: + skipped += 1 + continue + ts = last_ts + last_ts = ts + + raw_event = obj.get("event") + event = raw_event if isinstance(raw_event, str) and raw_event else "(unnamed event)" + raw_level = obj.get("level") + level = raw_level.upper() if isinstance(raw_level, str) and raw_level else "INFO" + raw_cycle = obj.get("cycle_id") + cycle_id = raw_cycle if isinstance(raw_cycle, str) and raw_cycle else None + + events.append( + ActivityEvent( + ts=ts, + level=level, + event=event, + cycle_id=cycle_id, + fields={k: v for k, v in obj.items() if k not in _ENVELOPE_KEYS}, + ) + ) + return events, skipped + + +# -- grouping + summarising (pure -- the part worth testing hardest) ------------------------------- + + +def _short_num(value: Any, places: int = 4) -> str: + """Trim a full-precision numeric string for display. The engine logs Decimals verbatim + (`stop="4197.09381782563408"`), which is right for a machine-readable log and wrong for a row + an operator scans -- but truncating in the LOG would lose real precision, so it is done here, + at the only place that has a column budget. + + `places` is a floor, not a ceiling, and that matters: keel trades sub-dollar assets alongside + four-figure ones, so a fixed two-decimal trim that reads perfectly as `4197.09` for PAXG turns + XLM's `0.161297` into `0.16` and ADA's entry and stop into the same number. Whenever the + integer part is zero, four more decimals are kept, so the small-priced products stay legible + without widening the big-priced ones.""" + text = str(value).strip() + if "." not in text: + return text + head, _, tail = text.partition(".") + if head.lstrip("-") in {"", "0"}: + places += 4 + tail = tail[:places].rstrip("0") + return f"{head}.{tail}" if tail else head + + +def _first_clause(text: str) -> str: + """The leading identifier of a `violation` string -- `"per_asset_concentration_cap: PAXG + exposure ... exceeds ..."` -> `"per_asset_concentration_cap"`. Which rail said no is what + belongs in a one-line summary; the arithmetic behind it belongs in the expansion.""" + head = text.split(":", 1)[0].strip() + return head or text.strip() + + +def _last_exc_line(text: str) -> str: + """The final line of a traceback -- the exception type and message. The frames above it are + the single largest thing in this log (they are why 330 lines occupy 815 KB) and the least + useful part of it on a dashboard.""" + for line in reversed(text.splitlines()): + if line.strip(): + return line.strip() + return text.strip() + + +def _add(seq: list[str], value: Any) -> None: + """Append `value` to `seq` if it is a non-empty string not already present -- order-preserving + de-duplication, used for the product/rule breadth and the highlight markers.""" + if isinstance(value, str) and value and value not in seq: + seq.append(value) + + +def summarise_cycle(cycle_id: str | None, events: Sequence[ActivityEvent]) -> ActivityCycle: + """Turn one cycle's events into the row the overlay shows. PURE. + + The five counts are deliberately the ones `keel agent`'s own human run-log one-liner already + taught an operator to read (`signals=0 blocked=0 entered=0 exited=0`), plus `errors`: + + * `signals` -- setups the rules produced, summed from `agent.signals_evaluated.signal_count` + (which is `len(enter_signals)`, exactly what the run-log line counts). Falls back to + counting `engine.setup_detected` for a cycle whose `signals_evaluated` records fell outside + the read window. + * `blocked` -- entries that did NOT become an order: an `agent.enter_evaluated` with + `placed=false` (rails vetoed it, or the confirm gate declined), plus an + `agent.entry_bar_not_ready` (withheld before it was ever evaluated). One per entry, never + one per *reason* -- the PAXG cycle of 2026-08-08 trips two guards on a single signal, and + reporting `blocked=2` there would imply two setups where there was one. + * `entered`/`exited` -- `agent.enter_evaluated`/`agent.exit_evaluated` with `placed=true`. + * `errors` -- ERROR-or-worse records, whatever emitted them. + + `highlights` is what makes a notable cycle notable at a glance, and is the reason the counts + alone were not enough: `blocked=1` says an entry did not happen, but not that + `per_asset_concentration_cap` is why, and the difference between those two is the difference + between "keel is broken" and "keel is working exactly as designed".""" + signals = 0 + saw_signal_counts = False + setups = 0 + blocked = 0 + entered = 0 + exited = 0 + errors = 0 + mode: str | None = None + products: list[str] = [] + rules: list[str] = [] + highlights: list[str] = [] + + for ev in events: + fields = ev.fields + name = ev.event + if ev.level in _ERROR_LEVELS: + errors += 1 + _add(highlights, f"error: {name}") + + _add(products, fields.get("product")) + _add(rules, fields.get("rule")) + polled = fields.get("products") + if isinstance(polled, list): + for item in polled: + _add(products, item) + + if name == "agent.signals_evaluated": + saw_signal_counts = True + signals += max(0, _as_int(fields.get("signal_count"))) + elif name == "engine.setup_detected": + setups += 1 + elif name == "agent.mode_resolved": + raw_mode = fields.get("mode") + if isinstance(raw_mode, str) and raw_mode: + mode = raw_mode + elif name == "agent.enter_evaluated": + if _as_bool(fields.get("placed")): + entered += 1 + _add(highlights, f"ENTERED {fields.get('product', '?')}") + else: + blocked += 1 + reason = fields.get("reason") + if isinstance(reason, str) and reason: + _add(highlights, f"not placed: {reason}") + else: + _add(highlights, f"not placed: {fields.get('product', '?')}") + elif name == "agent.exit_evaluated": + if _as_bool(fields.get("placed")): + exited += 1 + _add(highlights, f"EXITED {fields.get('product', '?')}") + elif name == "agent.entry_bar_not_ready": + blocked += 1 + elif name == "guards.check_failed": + violation = fields.get("violation") + if isinstance(violation, str) and violation: + _add(highlights, f"rail veto: {_first_clause(violation)}") + else: + _add(highlights, "rail veto") + elif name == "engine.setup_rejected": + _add( + highlights, + f"gate rejected: {fields.get('gate', '?')} ({fields.get('product', '?')})", + ) + elif name == "agent.entries_withheld": + _add(highlights, f"entries withheld ({_as_int(fields.get('blocked_count'))} blocked)") + elif name == "agent.cycle_skipped": + _add(highlights, f"cycle skipped: {fields.get('reason', '?')}") + elif name == "agent.feed_stale": + _add(highlights, f"stale feed: {fields.get('product', '?')}") + elif name == "equity.external_flow_recorded": + _add(highlights, f"external flow {fields.get('amount', '?')}") + elif name == "equity.unexplained_jump": + _add(highlights, "UNEXPLAINED equity jump") + + if not saw_signal_counts: + signals = setups + + kept = list(events[-_MAX_EVENTS_PER_CYCLE:]) + return ActivityCycle( + cycle_id=cycle_id, + started_ts=events[0].ts if events else 0.0, + ended_ts=events[-1].ts if events else 0.0, + mode=mode, + products=tuple(sorted(products)), + rules=tuple(sorted(rules)), + signals=signals, + blocked=blocked, + entered=entered, + exited=exited, + errors=errors, + highlights=tuple(highlights), + events=tuple(kept), + events_dropped=max(0, len(events) - len(kept)), + ) + + +def group_cycles(events: Sequence[ActivityEvent]) -> list[ActivityCycle]: + """Group events into cycles, in first-seen order. PURE. + + Correlated events are bucketed by `cycle_id` through a dict, not by contiguity, so a cycle + whose events are interleaved with another process's writes (two `keel` processes share one + log file) still comes back as one row. Uncorrelated events -- see the module docstring -- are + grouped by contiguity plus a `_UNCORRELATED_GAP_SEC` time gap instead, because contiguity is + the only signal they carry.""" + by_cycle: dict[str, list[ActivityEvent]] = {} + order: list[tuple[str | None, list[ActivityEvent]]] = [] + + for ev in events: + if ev.cycle_id is None: + tail = order[-1] if order else None + if ( + tail is not None + and tail[0] is None + and ev.ts - tail[1][-1].ts <= _UNCORRELATED_GAP_SEC + ): + tail[1].append(ev) + else: + order.append((None, [ev])) + continue + bucket = by_cycle.get(ev.cycle_id) + if bucket is None: + bucket = [] + by_cycle[ev.cycle_id] = bucket + order.append((ev.cycle_id, bucket)) + bucket.append(ev) + + return [summarise_cycle(cycle_id, evs) for cycle_id, evs in order] + + +def feed_from_lines( + lines: Iterable[str], + *, + source: str = "", + truncated: bool = False, + max_cycles: int = _MAX_CYCLES, +) -> ActivityFeed: + """THE pure core: JSONL lines in, a newest-first `ActivityFeed` out. Everything the overlay + shows is decided here, with no filesystem, no config, and no curses in sight. + + Newest-first is the whole point of the view -- "what has keel been doing" is answered from the + top down -- so cycles are sorted by start time descending, tie-broken by their position in the + file descending, which keeps two cycles that share a timestamp in a stable, reverse-file + order rather than an arbitrary one.""" + events, skipped = parse_events(lines) + cycles = group_cycles(events) + ordered = [ + cycle + for _, cycle in sorted( + enumerate(cycles), key=lambda pair: (pair[1].started_ts, pair[0]), reverse=True + ) + ] + dropped = max(0, len(ordered) - max_cycles) + kept = ordered[:max_cycles] + + if not events: + status = "unparseable" if skipped else "empty" + else: + status = "ok" + + return ActivityFeed( + status=status, + source=source, + cycles=tuple(kept), + detail=None, + lines_read=len(events) + skipped, + lines_skipped=skipped, + window_truncated=truncated or dropped > 0, + cycles_dropped=dropped, + ) + + +def build_activity_feed( + config: Any, + *, + max_bytes: int = _MAX_BYTES, + max_lines: int = _MAX_LINES, + max_cycles: int = _MAX_CYCLES, +) -> ActivityFeed: + """Resolve the log path from config, read its bounded tail, and build the feed. The thin I/O + seam over `feed_from_lines`. + + TOTAL, and the outer `except Exception` is not defensive padding: this is called from the + live loop's repaint path, where an escaping exception would take the dashboard down for a + problem in a file this process does not own. `read_log_window` already turns every + `OSError` into a status; this catches whatever a config object shaped differently than + expected could still throw, and turns it into the same kind of readable sentence.""" + try: + path = resolve_log_path(config) + window = read_log_window(path, max_bytes=max_bytes, max_lines=max_lines) + if window.status != "ok": + return ActivityFeed(status=window.status, source=str(path), detail=window.detail) + return feed_from_lines( + window.lines, + source=str(path), + truncated=window.truncated, + max_cycles=max_cycles, + ) + except Exception as exc: + return ActivityFeed( + status="unreadable", source="", detail=f"{type(exc).__name__}: {str(exc)[:160]}" + ) + + +# -- rendering helpers (pure text; the overlay adds the styles) --------------------------------- + + +#: What a timestamp renders as when it cannot be rendered at all. `parse_events` already rejects +#: out-of-range values, so nothing coming through the normal path reaches this -- it is the +#: backstop for a hand-built `ActivityCycle`/`ActivityEvent` (a caller, a future CLI view) whose +#: `ts` never went through the parser. These two functions are called from the live loop's repaint +#: path, where a raised `OverflowError` would take the dashboard down; a visible `??:??:??` is a +#: far better outcome than that. +_UNRENDERABLE_TS = "??" + + +def _safe_strftime(fmt: str, ts: float, width: int) -> str: + try: + return time.strftime(fmt, time.localtime(ts)) + except (OSError, OverflowError, ValueError): + return _UNRENDERABLE_TS * (width // len(_UNRENDERABLE_TS)) + + +def _clock(ts: float) -> str: + """Local `HH:MM:SS` for an expanded event row -- the cycle's own row already carries the + date, and repeating it on every event line would cost a fifth of the width for nothing.""" + return _safe_strftime("%H:%M:%S", ts, 8) + + +def _stamp(ts: float) -> str: + """Local `YYYY-MM-DD HH:MM:SS`, matching `keel/commands/tui.py`'s `_human_dt` so the feed's + timestamps and the dashboard's read identically. `ts` is a float epoch in the log; + `localtime` accepts it directly.""" + return _safe_strftime("%Y-%m-%d %H:%M:%S", ts, 19) + + +#: The column header for the collapsed rows, built with the SAME field widths +#: `render_cycle_row` uses so the two cannot drift out of alignment when either is edited. +ACTIVITY_HEADER = ( + f" {'when':<19} {'mode':<7} {'sig':>3} {'blk':>3} {'ent':>3} " + f"{'exi':>3} {'err':>3} what happened" +) + + +def render_cycle_row( + cycle: ActivityCycle, *, selected: bool = False, expanded: bool = False +) -> str: + """The collapsed one-line summary of a cycle, aligned under `ACTIVITY_HEADER`. + + Counts are abbreviated to fit five columns on an 80-column terminal WITH the notable markers + still visible, which is the trade this row exists to make: `signals=0 blocked=0 entered=0 + exited=0 errors=0` spelled out consumes 43 columns to say "nothing happened", and would push + the one genuinely informative part of a notable row off the right edge (`_paint` clips). The + header spells them out once, above.""" + caret = "▾" if expanded else "▸" + marker = ">" if selected else " " + mode = (cycle.mode or ("--" if cycle.is_uncorrelated else "?"))[:7] + tail_parts: list[str] = [] + if cycle.is_uncorrelated: + tail_parts.append("uncorrelated events (no cycle_id)") + elif cycle.products: + breadth = f"{len(cycle.products)} products" + if cycle.rules: + breadth += f" / {', '.join(cycle.rules[:2])}" + tail_parts.append(breadth) + if cycle.highlights: + shown = list(cycle.highlights[:_MAX_HIGHLIGHTS]) + extra = len(cycle.highlights) - len(shown) + if extra > 0: + shown.append(f"+{extra} more") + tail_parts.append(" | ".join(shown)) + elif cycle.is_quiet and not cycle.is_uncorrelated: + tail_parts.append("quiet -- looked, nothing to do") + tail = " ".join(tail_parts) + return ( + f"{marker}{caret} {_stamp(cycle.started_ts)} {mode:<7} " + f"{cycle.signals:>3} {cycle.blocked:>3} {cycle.entered:>3} " + f"{cycle.exited:>3} {cycle.errors:>3} {tail}" + ) + + +def cycle_style(cycle: ActivityCycle) -> str: + """Which `ScreenLine` style a collapsed row carries -- the "at a glance" half of the design. + + An error run is the loudest thing in this feed and gets `"alert"`, because on the real + deployment it is also the true answer to "why has nothing traded": weeks of + `cb_client.accounts_fetch_failed` are not background noise. A real fill is `"ok"`. Anything + withheld or vetoed is `"warn"` -- the system working as designed, not an emergency, exactly + the distinction `keel/commands/tui.py::_admission_line_style` already draws for a REJECT. A + cycle that produced signals but placed nothing is `"normal"`, and a quiet cycle is `"muted"` + so that a long run of them recedes into a calm background against which anything else stands + out.""" + if cycle.errors: + return "alert" + if cycle.entered or cycle.exited: + return "ok" + if cycle.blocked or cycle.highlights: + return "warn" + if cycle.signals: + return "normal" + return "muted" + + +def event_style(ev: ActivityEvent) -> str: + """Style for one expanded event line. `engine.no_signal` is muted on purpose: it is the + single most numerous event in the log (one per product per cycle) and it reports the absence + of news, so letting it read at the same weight as a rail veto would bury the veto.""" + if ev.level in _ERROR_LEVELS: + return "alert" + if ev.event in {"guards.check_failed", "engine.setup_rejected", "agent.entry_bar_not_ready"}: + return "warn" + if ev.event == "agent.enter_evaluated": + return "ok" if _as_bool(ev.fields.get("placed")) else "warn" + if ev.event == "agent.exit_evaluated": + return "ok" if _as_bool(ev.fields.get("placed")) else "normal" + if ev.event in {"engine.setup_detected", "equity.external_flow_recorded"}: + return "ok" + if ev.event in {"engine.no_signal", "agent.signals_evaluated"}: + return "muted" + return "normal" + + +def _generic_detail(ev: ActivityEvent) -> str: + """The fallback for an event this module has never been taught about -- every non-envelope + field as `key=value`. Deliberately NOT a "(no detail)" placeholder: the event vocabulary + grows faster than this renderer will, and a new event showing its raw fields is useful, while + one showing nothing is a bug that hides itself.""" + parts = [] + for key, value in ev.fields.items(): + if key == "exc" and isinstance(value, str): + parts.append(f"exc: {_last_exc_line(value)}") + else: + parts.append(f"{key}={value}") + return " ".join(parts) + + +def render_event_detail(ev: ActivityEvent) -> str: + """The human-readable right-hand side of one expanded event line -- the fields that MEAN + something for the events this system actually emits: a `violation` in full (an operator needs + the arithmetic, which is exactly what the collapsed row's `_first_clause` drops), the `gate` + that rejected a setup, the `reason` an entry was not placed, and a setup's entry/stop/target. + + Never raises on a missing or oddly-typed field -- every access is a `.get` with a visible `?` + fallback, because the whole file is written by a different process and possibly by a + different version of this codebase.""" + f = ev.fields + name = ev.event + detail: str + + if name == "agent.cycle_start": + detail = "cycle begins" + elif name == "agent.feed_polled": + polled = f.get("products") + listed = ", ".join(str(p) for p in polled) if isinstance(polled, list) else "?" + detail = ( + f"polled {f.get('candles_polled', '?')} candles, " + f"{f.get('rule_count', '?')} rules: {listed}" + ) + elif name == "agent.mode_resolved": + detail = f"mode={f.get('mode', '?')}" + elif name == "agent.paper_equity": + detail = ( + f"equity={f.get('equity', '?')} drawdown total={f.get('dd_total', '?')} " + f"weekly={f.get('dd_weekly', '?')}" + ) + elif name == "agent.signals_evaluated": + detail = ( + f"{f.get('product', '?')}: {f.get('signal_count', '?')} signal(s) " + f"from {f.get('rule_count', '?')} rule(s)" + ) + elif name == "engine.no_signal": + detail = ( + f"{f.get('product', '?')} {f.get('rule', '?')}: no signal at gate " + f"'{f.get('gate', '?')}' -- close={_short_num(f.get('close', '?'))} " + f"entry_level={_short_num(f.get('entry_level', '?'))} " + f"gap={_short_num(f.get('gap_pct', '?'), 2)}%" + ) + elif name == "engine.setup_detected": + detail = ( + f"{f.get('product', '?')} {f.get('rule', '?')}/{f.get('technique', '?')} " + f"cts={f.get('cts_score', '?')} entry={_short_num(f.get('entry', '?'), 2)} " + f"stop={_short_num(f.get('stop', '?'), 2)} " + f"target={_short_num(f.get('target', '?'), 2)}" + ) + elif name == "engine.setup_rejected": + detail = ( + f"{f.get('product', '?')} {f.get('rule', '?')}: REJECTED by gate " + f"'{f.get('gate', '?')}'" + ) + elif name == "guards.check_failed": + detail = ( + f"{f.get('product', '?')} {f.get('side', '?')} VETOED -- {f.get('violation', '?')}" + ) + elif name == "agent.enter_evaluated": + verdict = "PLACED" if _as_bool(f.get("placed")) else "NOT PLACED" + detail = ( + f"{f.get('product', '?')} {f.get('rule', '?')}/{f.get('technique', '?')} " + f"cts={f.get('cts_score', '?')} -> {verdict} -- {f.get('reason', 'no reason given')}" + ) + elif name == "agent.exit_evaluated": + verdict = "PLACED" if _as_bool(f.get("placed")) else "not placed" + detail = ( + f"{f.get('product', '?')} exit -> {verdict} -- " + f"{f.get('reason', 'no reason given')}" + ) + elif name == "agent.entry_bar_not_ready": + detail = ( + f"{f.get('product', '?')} {f.get('rule', '?')} {f.get('granularity', '?')}: " + f"entry WITHHELD -- {f.get('reason', '?')} (bars_behind={f.get('bars_behind', '?')})" + ) + elif name == "agent.entries_withheld": + detail = ( + f"every entry withheld this cycle -- {f.get('blocked_count', '?')} blocked on " + f"{f.get('products', '?')}" + ) + elif name == "agent.feed_stale": + detail = ( + f"{f.get('product', '?')}: feed STALE at {f.get('finest', '?')} " + f"(max_age_sec={f.get('max_age_sec', '?')})" + ) + elif name == "agent.cycle_skipped": + detail = f"cycle SKIPPED -- {f.get('reason', '?')}" + elif name == "equity.external_flow_recorded": + detail = ( + f"external flow {f.get('amount', '?')} -- high-water mark rebased to " + f"{f.get('rebased_hwm', '?')}" + ) + else: + detail = _generic_detail(ev) + + detail = " ".join(detail.split()) + if len(detail) > _DETAIL_MAX_CHARS: + detail = detail[: _DETAIL_MAX_CHARS - 3] + "..." + return detail + + +def render_event_row(ev: ActivityEvent) -> str: + """One expanded event line: local clock, the stable event id (never an interpolated sentence + -- the id is what an operator greps the raw log for), then the meaningful fields.""" + return f" {_clock(ev.ts)} {ev.event:<30} {render_event_detail(ev)}" + + +def describe_status(feed: ActivityFeed) -> list[str]: + """The lines shown INSTEAD of a feed when there is no feed to show -- one plain statement of + what is wrong and one of what to do about it. This is the function that keeps a broken log + from rendering as a blank overlay, which would be indistinguishable from the dead-looking + dashboard this whole feature exists to fix.""" + if feed.status == "missing": + return [ + f"No engine log found at {feed.source}.", + "", + "The activity feed reads the structured JSONL log the engine writes -- the path comes", + "from `logging.file` in config.yaml (default `logs/keel.log`, RESOLVED AGAINST THE", + "WORKING DIRECTORY). Run `keel tui` from the deployment root (the directory holding", + "config.yaml and logs/), or set `logging.file` to an absolute path.", + "", + "Nothing is wrong with the agent -- this overlay simply has nothing to read.", + ] + if feed.status == "empty": + return [ + f"The engine log at {feed.source} is empty.", + "", + "It exists but holds no records yet. `logging.verbose: false` (the default) records", + "only errors, so a healthy deployment writes nothing here until something fails --", + "set `logging.verbose: true` in config.yaml to record each cycle's decisions, which", + "is what this feed is built to show.", + ] + if feed.status == "oversized": + return [ + f"No complete record could be read from {feed.source}.", + "", + f"{feed.detail or 'no further detail'}", + "", + "The feed reads only the TAIL of the log so that a months-old deployment can never", + "slow this dashboard down. A single record larger than that whole window -- an error", + "carrying a very large traceback -- leaves nothing whole to parse.", + ] + if feed.status == "unparseable": + return [ + f"Nothing in {feed.source} could be parsed as a log record.", + "", + f"{feed.lines_skipped} line(s) were read and none was a JSON object. The engine writes", + "one JSON object per line (`keel_core.telemetry.JsonFormatter`); a file in any other", + "format is not the log this reads.", + ] + return [ + "The engine log could not be read.", + "", + f"{feed.detail or 'no further detail'}", + "", + f"Path tried: {feed.source or 'unresolved'}", + ] + + +def footer_notes(feed: ActivityFeed) -> list[str]: + """The honest small print under a rendered feed: what the bounded read did NOT show, and what + it could not parse. Reported rather than swallowed -- a feed that quietly under-reports while + looking complete is worse than one that admits its window.""" + notes: list[str] = [] + notes.append(f"source: {feed.source} ({feed.lines_read} records in window)") + if feed.window_truncated: + notes.append( + f"window BOUNDED: newest {_MAX_BYTES // 1024} KiB / {_MAX_LINES} lines / " + f"{_MAX_CYCLES} cycles at most -- older history is in the log, not here" + + (f" ({feed.cycles_dropped} older cycles dropped)" if feed.cycles_dropped else "") + ) + if feed.lines_skipped: + notes.append( + f"{feed.lines_skipped} line(s) skipped as unparseable (a partial record from a crash " + "mid-write, or a rotation boundary) -- everything else is shown" + ) + return notes + + +__all__ = [ + "ACTIVITY_HEADER", + "ActivityCycle", + "ActivityEvent", + "ActivityFeed", + "LogWindow", + "build_activity_feed", + "cycle_style", + "describe_status", + "event_style", + "feed_from_lines", + "footer_notes", + "group_cycles", + "parse_events", + "read_log_window", + "render_cycle_row", + "render_event_detail", + "render_event_row", + "resolve_log_path", + "summarise_cycle", +] diff --git a/keel/commands/tui.py b/keel/commands/tui.py index dd65708b..c47c5de8 100644 --- a/keel/commands/tui.py +++ b/keel/commands/tui.py @@ -52,6 +52,35 @@ None of the three attests, admits, or trades -- `attest` (the human judgment the whole gate rests on) stays deliberately CLI-only, `keel assets attest`. `screen`/`propose`/`discover` only ever PROPOSE or REPORT; they cannot themselves put an asset on `allowlist` in `config.yaml`. + +v4 (this revision) adds `v` **activity** -- `build_activity_overlay` over +`keel.commands.activity.build_activity_feed`, reusing that module's pure grouping/summarising +VERBATIM exactly as `i`/`s`/`p`/`d` reuse theirs. It answers the one question none of the other +five could: *what has keel been DOING*. Every overlay above this one reports STATE, and state is +what looks dead when nothing trades -- a deployment that has run flawlessly for three weeks and +correctly declined every setup shows exactly the same zeroes as one that died on day one. The +activity feed is the narrative instead: one row per engine cycle, newest first, expandable to the +events inside it, so a run of quiet cycles reads as the positive observation it is rather than as +an absence. + +Its source is the structured JSONL engine log -- NOT the database, and not a new table. See +`keel/commands/activity.py`'s own docstring for the full argument, but the short of it is that a +new table would start EMPTY on the very deployment this exists to explain, while the log is +already months deep. No schema change, no migration, no engine change. + +**That makes `v` the one overlay that reads a file rather than the DB, so it is worth saying +plainly why it is admissible.** This dashboard's iron rule -- stated for `s` screen above -- is +"DB reads only; never builds a broker, never touches the network." Reading a local log file is +NEITHER of the two things that rule forbids: no broker is constructed, no socket opened, no name +resolved. The rule exists so that opening an overlay can never place an order, spend money, or +block on a remote host, and a bounded read of a file on the same disk violates none of that. It +is the same latitude `p` propose already takes to read `config.proposals_dir`, and the network +exception count in this module stands unchanged at three. + +The read is BOUNDED -- 1 MiB of the log's tail, 5000 lines, 200 cycles, all named constants in +`activity.py` -- because the log grows without limit and this overlay rebuilds every poll. A +dashboard whose responsiveness degrades with how long the deployment has been running would be a +worse bug than the one this feature fixes. """ from __future__ import annotations @@ -66,6 +95,17 @@ import click from keel.commands._common import DISCLAIMER, _load_cfg, _open_repo +from keel.commands.activity import ( + ACTIVITY_HEADER, + ActivityFeed, + build_activity_feed, + cycle_style, + describe_status, + event_style, + footer_notes, + render_cycle_row, + render_event_row, +) from keel.commands.admission import ( DiscoverReport, ProposeView, @@ -331,14 +371,19 @@ def _footer_lines() -> list[ScreenLine]: and cramming `[s] screen [p] propose [d] discover` onto the end of it would either wrap on a normal terminal or silently truncate (`_paint` clips every line to the window width). A second line costs one more row of screen -- cheap, next to a footer line an operator can no - longer read.""" + longer read. + + That second line was labelled `admission:` while all three keys on it belonged to the + admission workflow. v4's `v` activity does not, so the label is now the accurate + `overlays:` -- a footer that mis-files a key is worse than one that groups it loosely, since + an operator hunting for the activity feed would not think to look under "admission".""" return [ ScreenLine( "keys: [q] quit [h] help [i] insights [r] refresh [a] autonomy [f] fetch", "muted", ), ScreenLine( - "admission: [s] screen [p] propose [d] discover (network)", + "overlays: [s] screen [p] propose [d] discover (network) [v] activity", "muted", ), ] @@ -411,6 +456,8 @@ def _note(text: str) -> None: _row(" p open the propose overlay (screens the newest shortlist file, read-only)") _row(" d open the discover overlay (propose NEW candidates from the venue)") _note(" armed, not run, on open -- see 'Discover overlay' below") + _row(" v open the activity feed (what keel has been DOING, cycle by cycle)") + _note(" reads the engine log, offline -- see 'Activity overlay' below") lines.append(_blank()) _row("Live balance") _note(" 'live account' shows the REAL account's spendable quote balance (e.g. USDC),") @@ -459,6 +506,36 @@ def _note(text: str) -> None: _row(" Enter run discover now (the ONE network call this overlay ever makes)") _row(" q / Esc / d close discover, back to the dashboard (discards the held result)") lines.append(_blank()) + _row("Activity overlay (v)") + _note(" OFFLINE, read-only: a chronological feed of what the agent has actually been doing,") + _note(" newest first, ONE ROW PER ENGINE CYCLE, grouped by the cycle_id every event carries.") + _note(" Every other overlay here reports STATE -- and state is what looks dead when nothing") + _note(" trades, because a deployment that ran flawlessly for three weeks and correctly") + _note(" declined every setup shows the same zeroes as one that died on day one. This shows") + _note(" the narrative instead. A QUIET cycle still gets a row: the run of quiet cycles IS") + _note(" the answer to 'is it alive'.") + _note(" Each row: local time, mode, and sig/blk/ent/exi/err (signals, blocked, entered,") + _note(" exited, errors), then what was notable -- a rail veto and its rule, the gate that") + _note(" rejected a setup, the reason an entry was not placed. Colour follows the same") + _note(" convention as the rest of the dashboard: quiet is muted, withheld/vetoed is a") + _note(" warning, a real fill is green, and an ERROR-level run is an alert.") + _note(" Source: the structured JSONL engine log at `logging.file` in config.yaml (default") + _note(" `logs/keel.log`, resolved against the WORKING DIRECTORY -- so run keel tui from the") + _note(" deployment root). Not the database: a new table would start empty on exactly the") + _note(" deployment this feed exists to explain, while the log is already months deep.") + _note(" Reading a local file is neither a broker nor the network, so this overlay keeps the") + _note(" same offline guarantee s and p do -- the three network exceptions above are still") + _note(" the only three.") + _note(" The read is BOUNDED (newest 1 MiB / 5000 lines / 200 cycles) so a log that grows for") + _note(" months can never slow the dashboard down; the feed says when the bound bit.") + _note(" A missing, empty, unreadable or unparseable log is explained in plain words -- never") + _note(" a traceback, and never a blank screen.") + _row(" up / k select the previous (newer) cycle") + _row(" down / j select the next (older) cycle") + _row(" Enter / Space expand or collapse the selected cycle's events") + _row(" PgUp / PgDn / Home / End move the selection by a page, or to either end") + _row(" q / Esc / v close activity, back to the dashboard") + lines.append(_blank()) _row("Safety notes") _note( " autonomy OFF is immediate and ungated -- de-risking must never be obstructed, so" @@ -481,8 +558,8 @@ def _note(text: str) -> None: ) _note(" endpoints. It places no orders and touches no rails.") lines.append(_blank()) - _note(" screen and propose are fully OFFLINE: DB (and, for propose, local filesystem)") - _note(" reads only. Neither ever constructs a broker or touches the network.") + _note(" screen, propose and activity are fully OFFLINE: DB reads, plus (for propose and") + _note(" activity) local filesystem reads. None constructs a broker or touches the network.") lines.append(_blank()) _note( " discover is the THIRD deliberate network exception in this dashboard. The other two" @@ -719,6 +796,148 @@ def build_discover_overlay( return lines +#: The lines the activity overlay renders when the log parsed fine but held no cycle at all -- +#: distinct from `describe_status`'s cases, which are about the FILE. A readable log with zero +#: cycles in the window is a real, if unusual, state (a log holding only uncorrelated errors from +#: a build predating `cycle_id`, say), and it must say so rather than render an empty screen. +_ACTIVITY_NO_CYCLES = "No cycles in the window -- the log was read, but held no grouped events." + + +def _activity_lines( + feed: ActivityFeed, *, cursor: int = 0, expanded: frozenset[str] = frozenset() +) -> tuple[list[ScreenLine], int]: + """The activity overlay's lines, PLUS the index of the line the cursor currently sits on. + + Returning both from ONE function is deliberate, and is why `build_activity_overlay` is a thin + wrapper over this rather than the other way round. This overlay is the only one of the six + with a *cursor* -- the others scroll a fixed body, but a feed of collapsible rows needs a + selected row to collapse. Keeping the cursor's screen position as a separate function would + mean a second copy of the layout arithmetic ("a row is 1 line, plus one per event when + expanded, plus a note line when events were dropped"), and the two copies would drift the + first time the layout changed -- with the symptom being a cursor that scrolls to the wrong + row, which is exactly the class of bug that is invisible in a unit test of either half alone. + + PURE: `feed` is already built by the caller (`run_live`, via `build_activity_feed`), and this + only styles what `keel.commands.activity`'s renderers already rendered -- the same discipline + `build_insights_screen` and `build_admission_screen_overlay` keep toward their own modules. + Never raises, and never returns an empty body: a broken log renders `describe_status`'s + explanation, which is the whole point (a blank overlay would look exactly like the dead + dashboard this feature exists to disprove).""" + lines: list[ScreenLine] = [ScreenLine("keel tui -- activity", "heading"), _blank()] + # Clamped here as well as in `run_live`, which already clamps it every poll against a feed + # that can shrink underneath it. Belt and braces for the same reason `_visible_slice` clamps + # its own offset: an out-of-range `cursor` would otherwise mark no row as selected while + # `cursor_line` still reported the first row's position, and the view would scroll to a row + # nothing appears to have selected. + cursor = max(0, min(cursor, max(0, len(feed.cycles) - 1))) + + if feed.status != "ok": + for text in describe_status(feed): + lines.append(ScreenLine(text, "warn") if text else _blank()) + lines.append(_blank()) + lines.append(ScreenLine("Press v or Esc to return to the dashboard.", "muted")) + return lines, 0 + + lines.append(ScreenLine(ACTIVITY_HEADER, "heading")) + cursor_line = len(lines) + + if not feed.cycles: + lines.append(ScreenLine(_ACTIVITY_NO_CYCLES, "warn")) + for index, cycle in enumerate(feed.cycles): + is_open = cycle.key in expanded + selected = index == cursor + if selected: + cursor_line = len(lines) + lines.append( + ScreenLine( + render_cycle_row(cycle, selected=selected, expanded=is_open), cycle_style(cycle) + ) + ) + if not is_open: + continue + if cycle.events_dropped: + lines.append( + ScreenLine( + f" ... {cycle.events_dropped} earlier event(s) in this cycle are not " + "retained (per-cycle cap) -- the counts above still cover all of them", + "muted", + ) + ) + for ev in cycle.events: + lines.append(ScreenLine(render_event_row(ev), event_style(ev))) + + lines.append(_blank()) + for text in footer_notes(feed): + lines.append(ScreenLine(text, "muted")) + lines.append(_blank()) + lines.append( + ScreenLine( + "up/k down/j move · Enter/Space expand or collapse · PgUp/PgDn/Home/End · " + "q/Esc/v close", + "muted", + ) + ) + return lines, cursor_line + + +def build_activity_overlay( + feed: ActivityFeed, *, cursor: int = 0, expanded: frozenset[str] = frozenset() +) -> list[ScreenLine]: + """The activity overlay's lines alone -- the pure, directly-testable surface, matching the + shape of every other `build_*_overlay` in this module. `run_live` uses `_activity_lines` + instead, because it also needs the cursor's screen position to scroll it into view.""" + return _activity_lines(feed, cursor=cursor, expanded=expanded)[0] + + +def _activity_cursor(ch: int, cursor: int, height: int, total: int, curses_mod: Any) -> int: + """The new, clamped SELECTED-ROW index for a keypress in the activity overlay -- the cursor + analogue of `_scroll_offset`, taking `curses_mod` as a parameter for the identical reasons + (lazy `curses` import; testable against the suite's existing fake curses module). + + The same keys move it that scroll the other five overlays, on purpose: an operator should not + have to remember that this one overlay rebound up/down. What differs is what they move -- a + row, not a line -- because a row here can be one line or seventy, and scrolling by lines + through an expanded cycle would make selecting the next cycle a matter of counting its + events. `_follow_cursor` then does the scrolling, so the view still moves. + + `total` is the number of CYCLES. A page is `height - 3` rows (leaving the title, blank and + header rows in view), floored at 1 so a two-line terminal still advances.""" + if total <= 0: + return 0 + page = max(height - 3, 1) + if ch in (curses_mod.KEY_UP, ord("k")): + cursor -= 1 + elif ch in (curses_mod.KEY_DOWN, ord("j")): + cursor += 1 + elif ch == curses_mod.KEY_PPAGE: + cursor -= page + elif ch == curses_mod.KEY_NPAGE: + cursor += page + elif ch == curses_mod.KEY_HOME: + cursor = 0 + elif ch == curses_mod.KEY_END: + cursor = total - 1 + return max(0, min(cursor, total - 1)) + + +def _follow_cursor(offset: int, cursor_line: int, height: int) -> int: + """The smallest change to `offset` that brings `cursor_line` back into a `height`-line + window -- scroll up to it if it is above, down to it if it is below, leave the view exactly + where it is otherwise. PURE, and total: a zero or negative `height` (a terminal mid-resize) + returns the offset unchanged rather than dividing by anything. + + "Smallest change" is the behaviour that matters: recentring on every keypress would make the + whole feed jump under the operator's eyes each time they moved one row, which is precisely + what makes a scrolling list unreadable.""" + if height <= 0: + return max(0, offset) + if cursor_line < offset: + return max(0, cursor_line) + if cursor_line >= offset + height: + return max(0, cursor_line - height + 1) + return max(0, offset) + + def _visible_slice(lines: list[ScreenLine], offset: int, height: int) -> list[ScreenLine]: """The `height`-line window of `lines` starting at `offset`, clamped so `offset` never runs past what would leave a partial screen at the end (or before the start). PURE -- never raises @@ -1064,25 +1283,34 @@ def run_live(open_state: OpenState, now_fn: NowFn, interval: float) -> None: process -- gathers a fresh report, paints it, then waits up to `interval` seconds for a keypress. - Six modes: `normal` (the dashboard, plus a transient one-line `message` toast from the last + Seven modes: `normal` (the dashboard, plus a transient one-line `message` toast from the last action), `help` (a scrolled window of `build_help_screen()`), `insights` (a scrolled window of `build_insights_screen()` -- a READ-ONLY overlay over `build_insights_report`/ `build_journal_report`, rebuilt fresh each poll while open, fail-soft exactly like the normal-mode status read below), `screen` and `propose` (the OFFLINE admission-workflow overlays, `build_admission_screen_overlay`/`build_propose_overlay` over `_do_screen_report`/ `_do_propose_view`, rebuilt fresh each poll while open, fail-soft the same way insights is), - and `discover` (the one overlay that touches the network -- see below). All five scrollable - overlays share one scrolling helper, `_scroll_offset`. + `discover` (the one overlay that touches the network -- see below), and `activity` (the + chronological, one-row-per-cycle feed over the engine LOG rather than the DB -- also OFFLINE, + also rebuilt each poll, and also fail-soft, though `build_activity_feed` is itself total so + the handler's `try` only ever catches `open_state()` failing). Five of the six scrollable + overlays share one scrolling helper, `_scroll_offset`; `activity` is the exception, driving + `_activity_cursor` + `_follow_cursor` instead because its up/down keys move a SELECTED ROW + (which may be one line or seventy) rather than one line of a fixed body. Normal-mode keys: `q`/`Q` quit; `h`/`?` open help; `i` open insights; `s` open screen; `p` - open propose; `d` open discover; `r` refresh now; `a` toggle autonomy (`toggle_autonomy`, + open propose; `d` open discover; `v` open activity; `r` refresh now; `a` toggle autonomy + (`toggle_autonomy`, gated by `_confirm_arm_autonomy` on the OFF->ON direction only); `f` fetch all data (`_do_fetch`, money-safe). `a` and `f` are both wrapped in `_guarded` so a failure becomes a toast, never a crash. help/insights/screen/propose all scroll (`up`/`k`, `down`/`j`, `PgUp`/`PgDn`, `Home`/`End`) and close back to normal on `q`/`Esc`/. + `activity` binds the same keys to moving its selected row, and adds Enter/Space to expand or + collapse that row's cycle into its individual events. - `discover` is different on purpose, and is the whole reason this docstring calls out FIVE - overlays rather than treating them identically: it needs the network, and that network call + `discover` is different on purpose, and is the whole reason this docstring calls out the + overlays individually rather than treating them identically: it needs the network, and that + network call must never fire just from pressing `d`. Opening it renders an ARMED, not-yet-run explanation (`build_discover_overlay(None)`) with NO call made. Only Enter (`10`/`13`/`curses.KEY_ENTER`), pressed INSIDE the overlay, runs `_do_discover_report` -- the one @@ -1128,6 +1356,13 @@ def _loop(stdscr: Any) -> None: screen_offset = 0 propose_offset = 0 discover_offset = 0 + activity_offset = 0 + activity_cursor = 0 + # Keyed by `ActivityCycle.key`, NOT by row index: the feed is rebuilt from the log every + # poll, so a new cycle appearing at the top would silently shift every index down one and + # expand the wrong row. The key is stable across rebuilds, so an expanded cycle stays + # expanded even as the feed grows underneath it. + activity_expanded: frozenset[str] = frozenset() discover_result: DiscoverReport | None = None discover_error: str | None = None message: str | None = None @@ -1246,6 +1481,59 @@ def _loop(stdscr: Any) -> None: ) continue + if mode == "activity": + # OFFLINE + fail-soft, like screen/propose above -- but reading a FILE, not the + # DB (see the module docstring for why that is admissible under this dashboard's + # own iron rule). `build_activity_feed` is itself total: a missing, empty, + # unreadable or unparseable log already comes back as a status this overlay + # explains in plain words. This `try` therefore catches only what is left -- + # `open_state()` itself failing, e.g. a locked DB from a concurrent `keel agent` + # writer -- and turns it into the same kind of readable feed rather than a crash. + try: + _activity_repo, activity_config = open_state() + activity_feed = build_activity_feed(activity_config) + # Re-clamp every poll, not just on a keypress: the feed is rebuilt from a + # file another process is writing, so it can SHRINK between polls (a rotation + # empties it) and leave the cursor past the end. + activity_cursor = max( + 0, min(activity_cursor, max(0, len(activity_feed.cycles) - 1)) + ) + activity_lines, activity_cursor_line = _activity_lines( + activity_feed, cursor=activity_cursor, expanded=activity_expanded + ) + except Exception as exc: + # The RENDER is inside this `try`, not just the feed build, and that is + # load-bearing rather than tidy: `build_activity_feed` is total, but the + # renderers it feeds are handed values written by another process (a `ts` a + # bad clock put in the year 5,000,000, say). Guarding only the build would + # leave the one call that actually formats those values outside the net, and + # an exception there would escape `curses.wrapper` and kill the dashboard. + activity_feed = ActivityFeed( + status="unreadable", source="", detail=str(exc)[:200] + ) + activity_lines, activity_cursor_line = _activity_lines(activity_feed) + + height, _width = stdscr.getmaxyx() + activity_offset = _follow_cursor(activity_offset, activity_cursor_line, height) + _paint(stdscr, _visible_slice(activity_lines, activity_offset, height)) + stdscr.timeout(int(interval * 1000)) + ch = stdscr.getch() + if ch in (ord("q"), 27, ord("v")): + mode = "normal" + activity_offset = 0 + activity_cursor = 0 + activity_expanded = frozenset() + elif ch in (10, 13, ord(" "), curses.KEY_ENTER): + if 0 <= activity_cursor < len(activity_feed.cycles): + activity_expanded = activity_expanded ^ { + activity_feed.cycles[activity_cursor].key + } + else: + activity_cursor = _activity_cursor( + ch, activity_cursor, height, len(activity_feed.cycles), curses + ) + continue + if mode == "discover": # NETWORK-GATED, on purpose -- see the module docstring and `build_discover_ # overlay`'s. Unlike every branch above, this one does NOT rebuild anything on an @@ -1336,6 +1624,14 @@ def _loop(stdscr: Any) -> None: mode = "propose" propose_offset = 0 continue + if ch == ord("v"): + mode = "activity" + activity_offset = 0 + activity_cursor = 0 + # Opens fully collapsed: the feed's value is the shape of the WHOLE run, and an + # overlay that reopened with one cycle already exploded would bury it. + activity_expanded = frozenset() + continue if ch == ord("d"): mode = "discover" discover_offset = 0 @@ -1435,7 +1731,12 @@ def tui_cmd(ctx: click.Context, interval: float, once: bool) -> None: admission verdicts, reusing `keel assets screen`'s own gate); `p` opens a READ-ONLY propose overlay (screens the newest shortlist file in `config.proposals_dir`); `d` opens the discover overlay ARMED but not yet run -- it explains itself and waits for Enter before making its one - live venue call, then holds that result until Enter is pressed again or the overlay closes. + live venue call, then holds that result until Enter is pressed again or the overlay closes; + `v` opens the READ-ONLY activity feed -- a chronological, newest-first, one-row-per-cycle + account of what the agent has actually been doing, read (offline, and boundedly) from the + structured engine log rather than the DB, and expandable to the individual events inside any + cycle. It is the answer to "keel has not traded -- is it even alive?", which the state-only + dashboard cannot give: a quiet cycle still gets a row, and the run of them is the answer. None of `screen`/`propose`/`discover` attests, admits, or trades -- `attest` (the human judgment this whole gate rests on) stays deliberately CLI-only, `keel assets attest`. `a` toggles autonomy (turning it OFF is instant, turning it ON needs a typed "yes" at the diff --git a/tests/commands/test_activity.py b/tests/commands/test_activity.py new file mode 100644 index 00000000..570e2fa7 --- /dev/null +++ b/tests/commands/test_activity.py @@ -0,0 +1,1368 @@ +"""Tests for `keel.commands.activity` -- the pure substrate of `keel tui`'s `v` activity feed. + +The whole module exists so that the grouping and summarising can be tested exhaustively while +the curses rendering stays a thin, separately-smoke-tested layer (`tests/commands/test_tui.py`). +So this file is deliberately heavy on two things: + +* **Realistic fixtures.** Every event shape below is copied from a real deployment's + `logs/keel.log` -- the PAXG rail veto of 2026-08-08 (an `engine.setup_detected` followed by two + `guards.check_failed` and an `agent.enter_evaluated` with `placed=false`), the + `choppy_regime` `engine.setup_rejected`, and the uncorrelated + `cb_client.accounts_fetch_failed`/`executor.quote_fetch_failed` pairs that carry no `cycle_id` + at all. A test built from an invented shape proves nothing about a parser whose entire job is + to read someone else's file. +* **Degradation.** The log is written by another process, possibly by another version of this + codebase, and may be rotated mid-read. A missing file, an empty one, a partial JSON line from a + crash mid-write, a line that is valid JSON but not an object, an event with no `cycle_id`, an + event with fields this code has never seen -- each has a test, because the requirement is not + "usually works" but "never a traceback and never a blank overlay". +""" + +from __future__ import annotations + +import json +import time +from typing import Any + +import pytest + +from keel.commands.activity import ( + _MAX_BYTES, + _MAX_EVENTS_PER_CYCLE, + _UNCORRELATED_GAP_SEC, + ACTIVITY_HEADER, + ActivityCycle, + ActivityEvent, + ActivityFeed, + _short_num, + build_activity_feed, + cycle_style, + describe_status, + event_style, + feed_from_lines, + footer_notes, + group_cycles, + parse_events, + read_log_window, + render_cycle_row, + render_event_detail, + render_event_row, + resolve_log_path, + summarise_cycle, +) + +# A weekday morning cycle, the cadence the real deployment actually runs at. +T0 = 1786194006.0 # 2026-08-08 09:00:06 UTC + + +# -- fixture builders (real shapes, from a real deployment's log) --------------------------------- + + +def _line(event: str, ts: float, cycle_id: str | None = "cyc0000000000001", **fields: Any) -> str: + """One JSONL record in exactly `keel_core.telemetry.JsonFormatter`'s shape: the envelope keys + it always writes, plus whatever the call site passed. `cycle_id=None` omits the key entirely, + which is what an event emitted outside an engine cycle (or by a build predating the + correlation id) actually looks like -- NOT a `null`.""" + payload: dict[str, Any] = { + "ts": ts, + "level": fields.pop("level", "INFO"), + "logger": fields.pop("logger", "keel.agent"), + "event": event, + "venue": "coinbase", + } + if cycle_id is not None: + payload["cycle_id"] = cycle_id + payload.update(fields) + return json.dumps(payload) + + +def _quiet_cycle_lines(cycle_id: str, start: float) -> list[str]: + """The overwhelmingly commonest cycle in the real log: polled everything, evaluated every + rule, found nothing. Five products, one rule each, zero signals.""" + products = ["ADA-USD", "BTC-USD", "ETH-USD", "PAXG-USD", "XLM-USD"] + lines = [ + _line("agent.cycle_start", start, cycle_id, now_ts=int(start)), + _line( + "agent.feed_polled", + start + 4, + cycle_id, + candles_polled=605, + rule_count=5, + products=products, + ), + _line("agent.mode_resolved", start + 4, cycle_id, mode="paper"), + _line( + "agent.paper_equity", + start + 4, + cycle_id, + equity="11000", + dd_total="0", + dd_weekly="0", + ), + ] + for product in products: + lines.append( + _line( + "engine.no_signal", + start + 5, + cycle_id, + rule="turtle_breakout", + product=product, + gate="donchian_high", + close=0.19929, + entry_level=0.21146, + gap_pct=6.106678709418443, + ) + ) + lines.append( + _line( + "agent.signals_evaluated", + start + 5, + cycle_id, + product=product, + rule_count=1, + signal_count=0, + ) + ) + return lines + + +def _rail_veto_cycle_lines(cycle_id: str = "b9871abe9898404e", start: float = T0) -> list[str]: + """The 2026-08-08 PAXG cycle, verbatim in shape: a real setup, two guard violations on the + single signal, and an entry that was not placed.""" + return [ + _line("agent.cycle_start", start, cycle_id, now_ts=int(start)), + _line("agent.mode_resolved", start + 5, cycle_id, mode="paper"), + _line( + "engine.setup_detected", + start + 5, + cycle_id, + rule="turtle_breakout", + product="PAXG-USD", + cts_score=5, + technique="signal_candle", + entry="4342.52", + stop="4197.09381782563408", + target="5215.07709304619552", + ), + _line( + "agent.signals_evaluated", + start + 5, + cycle_id, + product="PAXG-USD", + rule_count=1, + signal_count=1, + ), + _line( + "guards.check_failed", + start + 5, + cycle_id, + product="PAXG-USD", + side="BUY", + violation=( + "per_asset_concentration_cap: PAXG exposure 3284.671252850915628790264696 " + "exceeds 0.5 of max_exposure_usd (2500.0)" + ), + ), + _line( + "guards.check_failed", + start + 5, + cycle_id, + product="PAXG-USD", + side="BUY", + violation=( + "monthly_subscription_allowance: month-to-date BUY spend 0 + " + "3284.671252850915628790264696 = 3284.671252850915628790264696 exceeds the " + "allowance cap 500 -- remaining allowance 500" + ), + ), + _line( + "agent.enter_evaluated", + start + 5, + cycle_id, + product="PAXG-USD", + rule="turtle_breakout", + technique="signal_candle", + cts_score=5, + placed=False, + reason="paper: vetoed by rails", + ), + ] + + +def _fetch_failure_pair(start: float) -> list[str]: + """The uncorrelated pair the real log holds 64 of -- no `cycle_id`, ERROR level, a full + traceback in `exc`.""" + traceback = ( + 'Traceback (most recent call last):\n File "/Users/x/keel/keel/data/cb_client.py", ' + "line 120, in get_accounts\n raise\nrequests.exceptions.HTTPError: 401 Unauthorized" + ) + return [ + _line( + "cb_client.accounts_fetch_failed", + start, + None, + level="ERROR", + logger="keel.data.cb_client", + exc=traceback, + ), + _line( + "executor.quote_fetch_failed", + start, + None, + level="ERROR", + logger="keel.execution.executor", + quote_currency="USD", + exc=traceback, + ), + ] + + +def _cycle_by_id(feed: ActivityFeed, cycle_id: str) -> ActivityCycle: + return next(c for c in feed.cycles if c.cycle_id == cycle_id) + + +# -- parse_events: the happy path ----------------------------------------------------------------- + + +def test_parse_events_reads_envelope_and_keeps_the_rest_as_fields() -> None: + (event,), skipped = parse_events( + [_line("engine.setup_rejected", T0, "abc123", rule="turtle_breakout", gate="choppy_regime")] + ) + + assert skipped == 0 + assert event.ts == T0 + assert event.level == "INFO" + assert event.event == "engine.setup_rejected" + assert event.cycle_id == "abc123" + # `venue` is envelope and is excluded; the call site's own kwargs survive whole. + assert event.fields == {"rule": "turtle_breakout", "gate": "choppy_regime"} + + +def test_parse_events_skips_blank_lines_without_counting_them_as_malformed() -> None: + events, skipped = parse_events(["", " ", _line("agent.cycle_start", T0), "\n"]) + + assert len(events) == 1 + assert skipped == 0 + + +def test_parse_events_accepts_a_string_timestamp() -> None: + """`ts` is a float today, but a build that stringified it must still place the event.""" + (event,), skipped = parse_events(['{"ts": "1786194006.5", "event": "agent.cycle_start"}']) + + assert skipped == 0 + assert event.ts == pytest.approx(1786194006.5) + + +def test_parse_events_uppercases_the_level_so_error_matching_is_case_insensitive() -> None: + (event,), _ = parse_events(['{"ts": 1.0, "event": "x.y", "level": "error"}']) + + assert event.level == "ERROR" + + +# -- parse_events: degradation -------------------------------------------------------------------- + + +def test_parse_events_survives_a_truncated_line_from_a_crash_mid_write() -> None: + """A crash between `write()` and the newline leaves a partial JSON object on disk. It must be + counted and stepped over -- the records around it are perfectly good.""" + good = _line("agent.cycle_start", T0) + partial = '{"ts": 1786194011.2, "level": "INFO", "logger": "keel.agent", "eve' + events, skipped = parse_events([good, partial, good]) + + assert len(events) == 2 + assert skipped == 1 + + +@pytest.mark.parametrize( + "raw", + [ + "null", + "[]", + '"just a string"', + "12345", + "true", + "not json at all", + "{", + ], +) +def test_parse_events_counts_every_non_object_line_as_skipped(raw: str) -> None: + events, skipped = parse_events([raw]) + + assert events == [] + assert skipped == 1 + + +def test_parse_events_borrows_the_previous_timestamp_when_ts_is_missing() -> None: + """The log is append-ordered, so a neighbour's timestamp is very nearly right -- showing an + event slightly imprecisely beats hiding it.""" + events, skipped = parse_events( + [_line("agent.cycle_start", T0), '{"event": "agent.mode_resolved", "mode": "paper"}'] + ) + + assert skipped == 0 + assert len(events) == 2 + assert events[1].ts == T0 + + +def test_parse_events_skips_a_timestampless_line_with_no_predecessor_to_borrow_from() -> None: + events, skipped = parse_events(['{"event": "agent.mode_resolved"}']) + + assert events == [] + assert skipped == 1 + + +@pytest.mark.parametrize("bad_ts", [True, [1], {"a": 1}, None, "not-a-number"]) +def test_parse_events_treats_a_wrongly_typed_ts_as_missing(bad_ts: Any) -> None: + """`True` is the interesting one: `float(True)` is `1.0`, which would silently place a 2026 + event in 1970.""" + events, skipped = parse_events([json.dumps({"ts": bad_ts, "event": "x.y"})]) + + assert events == [] + assert skipped == 1 + + +def test_parse_events_names_an_event_that_has_no_name() -> None: + (event,), skipped = parse_events(['{"ts": 1.0, "product": "BTC-USD"}']) + + assert skipped == 0 + assert event.event == "(unnamed event)" + assert event.fields == {"product": "BTC-USD"} + + +def test_parse_events_ignores_a_non_string_cycle_id_rather_than_grouping_by_it() -> None: + (event,), _ = parse_events(['{"ts": 1.0, "event": "x.y", "cycle_id": 17}']) + + assert event.cycle_id is None + + +# -- grouping -------------------------------------------------------------------------------------- + + +def test_group_cycles_puts_every_event_of_one_cycle_in_one_group() -> None: + events, _ = parse_events(_quiet_cycle_lines("cycle-a", T0)) + + (cycle,) = group_cycles(events) + + assert cycle.cycle_id == "cycle-a" + assert len(cycle.events) == len(events) + + +def test_group_cycles_regroups_interleaved_cycles_by_id_not_by_adjacency() -> None: + """Two `keel` processes can share one log file, so a cycle's events are not guaranteed to be + contiguous. Grouping by adjacency would split one cycle into several rows.""" + events, _ = parse_events( + [ + _line("agent.cycle_start", T0, "cycle-a"), + _line("agent.cycle_start", T0 + 1, "cycle-b"), + _line("agent.mode_resolved", T0 + 2, "cycle-a", mode="paper"), + _line("agent.mode_resolved", T0 + 3, "cycle-b", mode="live"), + ] + ) + + cycles = group_cycles(events) + + assert [c.cycle_id for c in cycles] == ["cycle-a", "cycle-b"] + assert all(len(c.events) == 2 for c in cycles) + + +def test_group_cycles_keeps_uncorrelated_events_instead_of_dropping_them() -> None: + """The 64 fetch failures in the real log carry no `cycle_id`. They are the single most + informative thing in it -- dropping them would hide why nothing traded.""" + events, _ = parse_events(_fetch_failure_pair(T0)) + + (cycle,) = group_cycles(events) + + assert cycle.cycle_id is None + assert cycle.is_uncorrelated + assert cycle.errors == 2 + + +def test_group_cycles_splits_uncorrelated_runs_on_a_time_gap() -> None: + """Two failed polls sixteen minutes apart are two attempts, not one.""" + later = T0 + _UNCORRELATED_GAP_SEC + 1 + events, _ = parse_events(_fetch_failure_pair(T0) + _fetch_failure_pair(later)) + + cycles = group_cycles(events) + + assert len(cycles) == 2 + assert all(c.is_uncorrelated for c in cycles) + assert [c.started_ts for c in cycles] == [T0, later] + + +def test_group_cycles_keeps_one_uncorrelated_run_together_within_the_gap() -> None: + events, _ = parse_events( + _fetch_failure_pair(T0) + _fetch_failure_pair(T0 + _UNCORRELATED_GAP_SEC - 1) + ) + + cycles = group_cycles(events) + + assert len(cycles) == 1 + assert cycles[0].errors == 4 + + +def test_group_cycles_starts_a_new_uncorrelated_group_after_a_correlated_one() -> None: + """An uncorrelated event that follows a cycle must not be glued onto the previous + uncorrelated group across it -- otherwise a row would span an unrelated cycle.""" + events, _ = parse_events( + _fetch_failure_pair(T0) + + [_line("agent.cycle_start", T0 + 1, "cycle-a")] + + _fetch_failure_pair(T0 + 2) + ) + + cycles = group_cycles(events) + + assert [c.cycle_id for c in cycles] == [None, "cycle-a", None] + + +def test_summarise_cycle_on_no_events_does_not_raise() -> None: + cycle = summarise_cycle("cycle-a", []) + + assert cycle.started_ts == 0.0 + assert cycle.is_quiet + + +# -- summarising: the counts --------------------------------------------------------------------- + + +def test_quiet_cycle_counts_are_all_zero_and_it_reads_as_quiet() -> None: + feed = feed_from_lines(_quiet_cycle_lines("cycle-a", T0)) + (cycle,) = feed.cycles + + assert (cycle.signals, cycle.blocked, cycle.entered, cycle.exited, cycle.errors) == ( + 0, + 0, + 0, + 0, + 0, + ) + assert cycle.is_quiet + assert cycle.mode == "paper" + assert cycle.products == ("ADA-USD", "BTC-USD", "ETH-USD", "PAXG-USD", "XLM-USD") + assert cycle.rules == ("turtle_breakout",) + + +def test_rail_veto_cycle_counts_one_signal_and_one_block_not_one_per_violation() -> None: + """The real PAXG cycle trips TWO guards on a SINGLE signal. Counting `blocked=2` would imply + two setups where there was one -- `blocked` counts entries that did not become an order.""" + feed = feed_from_lines(_rail_veto_cycle_lines()) + (cycle,) = feed.cycles + + assert cycle.signals == 1 + assert cycle.blocked == 1 + assert cycle.entered == 0 + assert cycle.errors == 0 + + +def test_rail_veto_cycle_highlights_name_the_rails_and_the_reason() -> None: + feed = feed_from_lines(_rail_veto_cycle_lines()) + (cycle,) = feed.cycles + + assert "rail veto: per_asset_concentration_cap" in cycle.highlights + assert "rail veto: monthly_subscription_allowance" in cycle.highlights + assert "not placed: paper: vetoed by rails" in cycle.highlights + + +def test_setup_rejected_cycle_is_highlighted_with_its_gate() -> None: + """The 2026-08-11 `choppy_regime` rejection: zero signals, zero blocks, and yet emphatically + not a quiet cycle -- the engine looked at a setup and declined it.""" + lines = _quiet_cycle_lines("cycle-a", T0) + [ + _line( + "engine.setup_rejected", + T0 + 5, + "cycle-a", + rule="turtle_breakout", + product="PAXG-USD", + gate="choppy_regime", + ) + ] + feed = feed_from_lines(lines) + (cycle,) = feed.cycles + + assert cycle.highlights == ("gate rejected: choppy_regime (PAXG-USD)",) + assert cycle_style(cycle) == "warn" + + +def test_entered_and_exited_count_only_placed_results() -> None: + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + _line( + "agent.enter_evaluated", + T0 + 1, + "cycle-a", + product="BTC-USD", + rule="turtle_breakout", + placed=True, + reason="placed", + ), + _line( + "agent.exit_evaluated", T0 + 2, "cycle-a", product="ETH-USD", placed=True, reason="tp" + ), + _line( + "agent.exit_evaluated", + T0 + 3, + "cycle-a", + product="ADA-USD", + placed=False, + reason="no exit signal", + ), + ] + feed = feed_from_lines(lines) + (cycle,) = feed.cycles + + assert cycle.entered == 1 + assert cycle.exited == 1 + # A not-placed EXIT is routine (no exit signal) and is not a blocked ENTRY. + assert cycle.blocked == 0 + assert "ENTERED BTC-USD" in cycle.highlights + assert "EXITED ETH-USD" in cycle.highlights + + +def test_a_stringified_placed_false_does_not_read_as_an_entry() -> None: + """`bool("false")` is `True`. Getting this wrong would have the feed report a fill that never + happened, which is the single worst thing this module could say.""" + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + _line( + "agent.enter_evaluated", + T0 + 1, + "cycle-a", + product="BTC-USD", + placed="false", + reason="paper: vetoed by rails", + ), + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle.entered == 0 + assert cycle.blocked == 1 + + +def test_entry_bar_not_ready_counts_as_blocked_even_though_no_entry_was_evaluated() -> None: + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + _line( + "agent.entry_bar_not_ready", + T0 + 1, + "cycle-a", + level="WARNING", + product="BTC-USD", + rule="turtle_breakout", + granularity="ONE_DAY", + bars_behind=1, + reason="stored bar is behind the expected one", + ), + _line( + "agent.entries_withheld", + T0 + 1, + "cycle-a", + level="WARNING", + blocked_count=1, + products=["BTC-USD"], + rules=["turtle_breakout"], + ), + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle.blocked == 1 + assert "entries withheld (1 blocked)" in cycle.highlights + + +def test_signals_falls_back_to_counting_setups_when_signals_evaluated_is_out_of_window() -> None: + """A cycle whose `agent.signals_evaluated` records fell off the front of the bounded read + must still report the setup it detected, not a misleading `signals=0`.""" + lines = [ + _line( + "engine.setup_detected", + T0, + "cycle-a", + rule="turtle_breakout", + product="PAXG-USD", + entry="4342.52", + ) + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle.signals == 1 + + +def test_errors_are_counted_at_any_level_above_warning() -> None: + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + _line("cb_client.spot_fetch_failed", T0 + 1, "cycle-a", level="ERROR", exc="boom"), + _line("agent.feed_stale", T0 + 2, "cycle-a", level="WARNING", product="XLM-USD"), + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle.errors == 1 + assert "stale feed: XLM-USD" in cycle.highlights + + +def test_a_products_field_that_is_not_a_list_is_ignored_not_exploded() -> None: + """`agent.feed_polled.products` is a list today. A build that wrote a dict there must not + take the overlay down, and must not scatter dict keys into the product breadth.""" + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + _line("agent.feed_polled", T0 + 1, "cycle-a", products={"a": 1}, candles_polled=5), + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle.products == () + + +def test_events_beyond_the_per_cycle_cap_are_dropped_but_the_counts_still_cover_them() -> None: + over = _MAX_EVENTS_PER_CYCLE + 10 + lines = [ + _line( + "agent.enter_evaluated", + T0 + i, + "cycle-a", + product="BTC-USD", + placed=False, + reason="paper: vetoed by rails", + ) + for i in range(over) + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle.blocked == over # counted over ALL events... + assert len(cycle.events) == _MAX_EVENTS_PER_CYCLE # ...but only the newest are retained + assert cycle.events_dropped == 10 + + +# -- ordering + bounds ---------------------------------------------------------------------------- + + +def test_feed_is_newest_first() -> None: + lines = ( + _quiet_cycle_lines("oldest", T0) + + _quiet_cycle_lines("middle", T0 + 86400) + + _quiet_cycle_lines("newest", T0 + 172800) + ) + + feed = feed_from_lines(lines) + + assert [c.cycle_id for c in feed.cycles] == ["newest", "middle", "oldest"] + + +def test_cycles_sharing_a_timestamp_keep_a_stable_reverse_file_order() -> None: + lines = [ + _line("agent.cycle_start", T0, "first"), + _line("agent.cycle_start", T0, "second"), + ] + + feed = feed_from_lines(lines) + + assert [c.cycle_id for c in feed.cycles] == ["second", "first"] + + +def test_max_cycles_keeps_the_newest_and_reports_what_it_dropped() -> None: + lines: list[str] = [] + for i in range(10): + lines.extend(_quiet_cycle_lines(f"cycle-{i:02d}", T0 + i * 86400)) + + feed = feed_from_lines(lines, max_cycles=3) + + assert [c.cycle_id for c in feed.cycles] == ["cycle-09", "cycle-08", "cycle-07"] + assert feed.cycles_dropped == 7 + assert feed.window_truncated is True + assert any("BOUNDED" in note for note in footer_notes(feed)) + + +def test_a_quiet_cycle_still_gets_a_row() -> None: + """The load-bearing requirement: the run of quiet cycles IS the answer to "is it alive". A + feed that omitted them would reproduce exactly the dead-looking dashboard it replaces.""" + lines: list[str] = [] + for i in range(12): + lines.extend(_quiet_cycle_lines(f"cycle-{i:02d}", T0 + i * 86400)) + + feed = feed_from_lines(lines) + + assert len(feed.cycles) == 12 + assert all(c.is_quiet for c in feed.cycles) + + +# -- feed_from_lines: whole-input degradation ------------------------------------------------------ + + +def test_feed_from_no_lines_is_empty_not_an_exception() -> None: + feed = feed_from_lines([]) + + assert feed.status == "empty" + assert feed.cycles == () + + +def test_feed_from_only_unparseable_lines_says_unparseable_not_empty() -> None: + """The two have completely different fixes -- "the file has no records yet" versus "this is + not the log you think it is".""" + feed = feed_from_lines(["not json", "", "{"]) + + assert feed.status == "unparseable" + assert feed.lines_skipped == 3 + text = " ".join(describe_status(feed)) + assert "3 line(s) were read" in text + assert "JSON object" in text + + +def test_feed_reports_skipped_lines_rather_than_swallowing_them() -> None: + feed = feed_from_lines([*_quiet_cycle_lines("cycle-a", T0), "{partial"]) + + assert feed.status == "ok" + assert feed.lines_skipped == 1 + assert any("skipped as unparseable" in note for note in footer_notes(feed)) + + +# -- read_log_window: the file-level degradation --------------------------------------------------- + + +def test_read_log_window_missing_file(tmp_path: Any) -> None: + window = read_log_window(tmp_path / "nope.log") + + assert window.status == "missing" + assert "nope.log" in (window.detail or "") + + +def test_read_log_window_empty_file(tmp_path: Any) -> None: + path = tmp_path / "keel.log" + path.write_text("") + + window = read_log_window(path) + + assert window.status == "empty" + + +def test_read_log_window_whitespace_only_file_is_empty_not_ok(tmp_path: Any) -> None: + path = tmp_path / "keel.log" + path.write_text("\n\n \n") + + assert read_log_window(path).status == "empty" + + +def test_read_log_window_directory_is_unreadable_not_a_crash(tmp_path: Any) -> None: + """`open()` on a directory raises `IsADirectoryError` (an `OSError`). A misconfigured + `logging.file` pointing at a directory must read as one sentence, not a traceback.""" + window = read_log_window(tmp_path) + + assert window.status == "unreadable" + assert window.detail + + +def test_read_log_window_unreadable_file_reports_the_reason(tmp_path: Any) -> None: + path = tmp_path / "keel.log" + path.write_text(_line("agent.cycle_start", T0)) + path.chmod(0o000) + try: + window = read_log_window(path) + finally: + path.chmod(0o600) + + # Running as root defeats the permission bit entirely; skip rather than assert a falsehood. + if window.status == "ok": + pytest.skip("filesystem permissions are not enforced for this user") + assert window.status == "unreadable" + assert "Error" in (window.detail or "") + + +def test_read_log_window_reads_the_whole_file_when_it_is_under_the_byte_cap(tmp_path: Any) -> None: + lines = _quiet_cycle_lines("cycle-a", T0) + path = tmp_path / "keel.log" + path.write_text("\n".join(lines) + "\n") + + window = read_log_window(path) + + assert window.status == "ok" + assert window.truncated is False + assert len(window.lines) == len(lines) + + +def test_read_log_window_without_a_trailing_newline_keeps_the_last_record(tmp_path: Any) -> None: + """The engine's handler is mid-write far more often than not, and the newest record is the + one an operator most wants.""" + lines = _quiet_cycle_lines("cycle-a", T0) + path = tmp_path / "keel.log" + path.write_text("\n".join(lines)) # no trailing newline + + window = read_log_window(path) + + assert len(window.lines) == len(lines) + + +def test_read_log_window_byte_cap_drops_the_partial_first_line(tmp_path: Any) -> None: + """Seeking to `size - max_bytes` lands mid-record. Feeding that half-object to the parser + would count a phantom malformed line on every single repaint.""" + lines = [_line("agent.cycle_start", T0 + i, f"cycle-{i:03d}") for i in range(50)] + blob = "\n".join(lines) + "\n" + path = tmp_path / "keel.log" + path.write_text(blob) + + # A cap that lands squarely inside a record, not on a boundary. + window = read_log_window(path, max_bytes=len(lines[-1].encode()) * 3 + 7) + + assert window.truncated is True + assert window.lines # something survived + events, skipped = parse_events(window.lines) + assert skipped == 0 # and it is all whole records + assert events + + +def test_read_log_window_byte_cap_smaller_than_one_record_yields_no_lines_not_a_crash( + tmp_path: Any, +) -> None: + path = tmp_path / "keel.log" + path.write_text(_line("agent.cycle_start", T0) + "\n") + + window = read_log_window(path, max_bytes=8) + + # Nothing whole survived the boundary trim -- reported as `oversized`, never as a partial + # record, and deliberately not as `empty` (the file is anything but). + assert window.status == "oversized" + assert window.lines == () + + +def test_read_log_window_line_cap_keeps_the_newest_lines(tmp_path: Any) -> None: + lines = [_line("agent.cycle_start", T0 + i, f"cycle-{i:03d}") for i in range(50)] + path = tmp_path / "keel.log" + path.write_text("\n".join(lines) + "\n") + + window = read_log_window(path, max_lines=5) + + assert len(window.lines) == 5 + assert window.truncated is True + assert "cycle-049" in window.lines[-1] + + +def test_read_log_window_decodes_non_utf8_bytes_instead_of_raising(tmp_path: Any) -> None: + """A truncated multi-byte character at a rotation boundary must cost one replacement + character, not the whole overlay.""" + path = tmp_path / "keel.log" + path.write_bytes(b"\xff\xfe garbage\n" + _line("agent.cycle_start", T0).encode() + b"\n") + + window = read_log_window(path) + + assert window.status == "ok" + events, skipped = parse_events(window.lines) + assert len(events) == 1 + assert skipped == 1 + + +def test_read_log_window_after_rotation_reads_the_new_small_file(tmp_path: Any) -> None: + """`RotatingFileHandler` renames the old file aside and opens a fresh one. Opening by PATH on + every build (rather than holding a handle) is what makes that a non-event.""" + path = tmp_path / "keel.log" + path.write_text("\n".join(_quiet_cycle_lines("old-cycle", T0)) + "\n") + assert read_log_window(path).status == "ok" + + path.rename(tmp_path / "keel.log.1") + path.write_text(_line("agent.cycle_start", T0 + 86400, "new-cycle") + "\n") + + window = read_log_window(path) + feed = feed_from_lines(window.lines) + + assert [c.cycle_id for c in feed.cycles] == ["new-cycle"] + + +# -- build_activity_feed: config -> feed, and its totality ----------------------------------------- + + +class _FakeLogging: + def __init__(self, file: Any) -> None: + self.file = file + + +class _FakeConfig: + def __init__(self, file: Any) -> None: + self.logging = _FakeLogging(file) + + +def test_resolve_log_path_uses_the_configured_logging_file(tmp_path: Any) -> None: + path = tmp_path / "custom" / "engine.log" + + assert resolve_log_path(_FakeConfig(str(path))) == path.resolve() + + +@pytest.mark.parametrize("bad", [None, "", " ", 17, object()]) +def test_resolve_log_path_falls_back_to_the_default_for_an_unusable_setting(bad: Any) -> None: + assert resolve_log_path(_FakeConfig(bad)).name == "keel.log" + + +def test_resolve_log_path_on_a_config_without_a_logging_section_does_not_raise() -> None: + assert resolve_log_path(object()).name == "keel.log" + + +def test_build_activity_feed_end_to_end(tmp_path: Any) -> None: + path = tmp_path / "keel.log" + path.write_text( + "\n".join(_quiet_cycle_lines("quiet-one", T0) + _rail_veto_cycle_lines("veto", T0 + 86400)) + + "\n" + ) + + feed = build_activity_feed(_FakeConfig(str(path))) + + assert feed.status == "ok" + assert feed.source == str(path.resolve()) + assert [c.cycle_id for c in feed.cycles] == ["veto", "quiet-one"] + assert _cycle_by_id(feed, "veto").blocked == 1 + + +def test_build_activity_feed_on_a_missing_log_is_a_status_not_an_exception(tmp_path: Any) -> None: + feed = build_activity_feed(_FakeConfig(str(tmp_path / "gone.log"))) + + assert feed.status == "missing" + assert feed.cycles == () + assert describe_status(feed) # and it has something to say about it + + +def test_build_activity_feed_never_raises_on_a_hostile_config( + tmp_path: Any, monkeypatch: pytest.MonkeyPatch +) -> None: + # `resolve_log_path` falls back to the RELATIVE default, which resolves against the cwd -- + # chdir into an empty directory so this asserts the fallback, not whatever `logs/keel.log` + # another test in the run happened to leave next to pytest's working directory. + monkeypatch.chdir(tmp_path) + + class _Exploding: + @property + def logging(self) -> Any: # pragma: no cover - the raise IS the behaviour under test + raise RuntimeError("config went bad") + + feed = build_activity_feed(_Exploding()) + + # The property error is swallowed and the default path used -- a status, never a traceback. + assert feed.status == "missing" + assert describe_status(feed) + + +# -- describe_status: never blank, always actionable ----------------------------------------------- + + +@pytest.mark.parametrize("status", ["missing", "empty", "unparseable", "unreadable"]) +def test_describe_status_always_says_something_useful(status: str) -> None: + feed = ActivityFeed(status=status, source="/tmp/keel.log", detail="reason", lines_skipped=3) + + lines = describe_status(feed) + + assert lines + assert any(line.strip() for line in lines) + + +def test_describe_status_for_a_missing_log_explains_the_working_directory_trap() -> None: + """The commonest cause by far: `keel tui` run from anywhere but the deployment root resolves + the relative default against the wrong cwd.""" + feed = ActivityFeed(status="missing", source="/somewhere/logs/keel.log") + + text = " ".join(describe_status(feed)) + + assert "/somewhere/logs/keel.log" in text + assert "WORKING DIRECTORY" in text + assert "logging.file" in text + + +def test_describe_status_for_an_empty_log_mentions_the_verbose_toggle() -> None: + """`logging.verbose: false` is the default and records only errors, so a healthy deployment + genuinely writes nothing -- that is the fix, not a bug report.""" + text = " ".join(describe_status(ActivityFeed(status="empty", source="/tmp/keel.log"))) + + assert "verbose" in text + + +# -- rendering ------------------------------------------------------------------------------------ + + +def test_header_and_row_columns_line_up() -> None: + """The header is built from the same field widths as the row, so this asserts the property + that keeps them honest rather than a hardcoded column number.""" + (cycle,) = feed_from_lines(_quiet_cycle_lines("cycle-a", T0)).cycles + row = render_cycle_row(cycle) + + # Each column starts at the same offset in the header as it does in the row. + assert ACTIVITY_HEADER.index("mode") == row.index("paper") + assert ACTIVITY_HEADER.index("sig") == row.index(f"{cycle.signals:>3}") + assert ACTIVITY_HEADER.index("when") == row.index("2") # the timestamp's leading digit + + +def test_cycle_row_renders_local_time_not_an_epoch_float() -> None: + (cycle,) = feed_from_lines(_quiet_cycle_lines("cycle-a", T0)).cycles + + row = render_cycle_row(cycle) + + assert time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(T0)) in row + assert "1786194006" not in row + + +def test_cycle_row_caret_and_marker_reflect_selection_and_expansion() -> None: + (cycle,) = feed_from_lines(_quiet_cycle_lines("cycle-a", T0)).cycles + + assert render_cycle_row(cycle).startswith(" ▸") + assert render_cycle_row(cycle, selected=True).startswith(">▸") + assert render_cycle_row(cycle, selected=True, expanded=True).startswith(">▾") + + +def test_quiet_row_says_so_rather_than_rendering_a_bare_line_of_zeroes() -> None: + (cycle,) = feed_from_lines(_quiet_cycle_lines("cycle-a", T0)).cycles + + assert "quiet -- looked, nothing to do" in render_cycle_row(cycle) + + +def test_uncorrelated_row_labels_itself() -> None: + (cycle,) = feed_from_lines(_fetch_failure_pair(T0)).cycles + + assert "uncorrelated events (no cycle_id)" in render_cycle_row(cycle) + + +def test_row_summarises_highlights_beyond_the_display_cap() -> None: + lines = [_line("agent.cycle_start", T0, "cycle-a")] + for i in range(6): + lines.append( + _line( + "guards.check_failed", + T0 + i, + "cycle-a", + product="BTC-USD", + side="BUY", + violation=f"rail_{i}: too much", + ) + ) + (cycle,) = feed_from_lines(lines).cycles + + assert "+3 more" in render_cycle_row(cycle) + + +@pytest.mark.parametrize( + ("lines", "expected"), + [ + (_fetch_failure_pair(T0), "alert"), + (_rail_veto_cycle_lines(), "warn"), + (_quiet_cycle_lines("cycle-a", T0), "muted"), + ], +) +def test_cycle_style_distinguishes_notable_cycles_from_quiet_ones( + lines: list[str], expected: str +) -> None: + (cycle,) = feed_from_lines(lines).cycles + + assert cycle_style(cycle) == expected + + +def test_a_cycle_that_placed_an_order_reads_as_ok() -> None: + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + _line( + "agent.signals_evaluated", + T0 + 1, + "cycle-a", + product="BTC-USD", + rule_count=1, + signal_count=1, + ), + _line( + "agent.enter_evaluated", + T0 + 2, + "cycle-a", + product="BTC-USD", + placed=True, + reason="placed", + ), + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle_style(cycle) == "ok" + + +def test_signals_without_a_fill_read_as_normal_neither_quiet_nor_alarming() -> None: + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + _line( + "agent.signals_evaluated", + T0 + 1, + "cycle-a", + product="BTC-USD", + rule_count=1, + signal_count=2, + ), + ] + (cycle,) = feed_from_lines(lines).cycles + + assert cycle_style(cycle) == "normal" + + +# -- rendering: one event's detail ----------------------------------------------------------------- + + +def _detail_for(lines: list[str], event_name: str) -> str: + (cycle,) = feed_from_lines(lines).cycles + ev = next(e for e in cycle.events if e.event == event_name) + return render_event_detail(ev) + + +def test_setup_detected_detail_shows_entry_stop_and_target() -> None: + detail = _detail_for(_rail_veto_cycle_lines(), "engine.setup_detected") + + assert "PAXG-USD" in detail + assert "entry=4342.52" in detail + assert "stop=4197.09" in detail # trimmed from 4197.09381782563408 + assert "target=5215.07" in detail + assert "cts=5" in detail + + +def test_guards_check_failed_detail_shows_the_whole_violation_string() -> None: + """The collapsed row keeps only the rail's NAME. The expansion is where an operator gets the + arithmetic that explains it, so it must not be trimmed away here too.""" + detail = _detail_for(_rail_veto_cycle_lines(), "guards.check_failed") + + assert "per_asset_concentration_cap" in detail + assert "exceeds 0.5 of max_exposure_usd (2500.0)" in detail + assert "VETOED" in detail + + +def test_enter_evaluated_detail_states_the_verdict_and_the_reason() -> None: + detail = _detail_for(_rail_veto_cycle_lines(), "agent.enter_evaluated") + + assert "NOT PLACED" in detail + assert "paper: vetoed by rails" in detail + + +def test_setup_rejected_detail_names_the_gate() -> None: + lines = [ + _line( + "engine.setup_rejected", + T0, + "cycle-a", + rule="turtle_breakout", + product="PAXG-USD", + gate="choppy_regime", + ) + ] + + assert "choppy_regime" in _detail_for(lines, "engine.setup_rejected") + + +def test_an_error_events_detail_is_the_exception_line_not_the_whole_traceback() -> None: + """A traceback is why 330 records occupy 815 KB, and is the least useful part of it on a + dashboard.""" + detail = _detail_for(_fetch_failure_pair(T0), "cb_client.accounts_fetch_failed") + + assert "401 Unauthorized" in detail + assert "Traceback" not in detail + assert "File \"" not in detail + + +def test_an_unknown_event_renders_its_own_fields_rather_than_nothing() -> None: + """The event vocabulary grows faster than this renderer will. An event showing raw fields is + useful; one showing nothing is a bug that hides itself.""" + lines = [_line("executor.stop_rolled", T0, "cycle-a", position_id=7, new_stop="123.45")] + + detail = _detail_for(lines, "executor.stop_rolled") + + assert "position_id=7" in detail + assert "new_stop=123.45" in detail + + +def test_event_detail_is_capped_so_one_field_cannot_define_the_row_width() -> None: + lines = [ + _line( + "guards.check_failed", + T0, + "cycle-a", + product="BTC-USD", + side="BUY", + violation="x" * 5000, + ) + ] + + detail = _detail_for(lines, "guards.check_failed") + + assert len(detail) <= 220 + assert detail.endswith("...") + + +def test_event_detail_never_raises_on_an_event_with_no_fields_at_all() -> None: + for name in ( + "agent.cycle_start", + "agent.feed_polled", + "agent.mode_resolved", + "agent.paper_equity", + "agent.signals_evaluated", + "engine.no_signal", + "engine.setup_detected", + "engine.setup_rejected", + "guards.check_failed", + "agent.enter_evaluated", + "agent.exit_evaluated", + "agent.entry_bar_not_ready", + "agent.entries_withheld", + "agent.feed_stale", + "agent.cycle_skipped", + "equity.external_flow_recorded", + "some.brand_new_event", + ): + ev = ActivityEvent(ts=T0, level="INFO", event=name, cycle_id="c", fields={}) + assert isinstance(render_event_detail(ev), str) + assert isinstance(render_event_row(ev), str) + assert isinstance(event_style(ev), str) + + +def test_event_row_shows_the_stable_event_id_so_it_can_be_grepped_in_the_raw_log() -> None: + ev = ActivityEvent(ts=T0, level="INFO", event="guards.check_failed", cycle_id="c", fields={}) + + assert "guards.check_failed" in render_event_row(ev) + + +def test_no_signal_is_muted_so_it_cannot_bury_a_rail_veto() -> None: + quiet = ActivityEvent(ts=T0, level="INFO", event="engine.no_signal", cycle_id="c", fields={}) + veto = ActivityEvent(ts=T0, level="INFO", event="guards.check_failed", cycle_id="c", fields={}) + + assert event_style(quiet) == "muted" + assert event_style(veto) == "warn" + + +@pytest.mark.parametrize( + ("raw", "places", "expected"), + [ + ("4197.09381782563408", 2, "4197.09"), + ("0.161297", 2, "0.161297"), # sub-dollar assets keep their precision + ("1979.0", 2, "1979"), + ("605", 2, "605"), + ("-0.00012345678", 2, "-0.000123"), + ("not a number", 2, "not a number"), + ], +) +def test_short_num(raw: str, places: int, expected: str) -> None: + assert _short_num(raw, places) == expected + + +def test_footer_notes_always_name_the_source_so_the_operator_knows_what_was_read() -> None: + feed = feed_from_lines(_quiet_cycle_lines("cycle-a", T0), source="/tmp/keel.log") + + assert any("/tmp/keel.log" in note for note in footer_notes(feed)) + + +def test_footer_notes_state_the_bound_in_the_units_it_is_enforced_in() -> None: + feed = feed_from_lines(_quiet_cycle_lines("cycle-a", T0), truncated=True) + + text = " ".join(footer_notes(feed)) + + assert f"{_MAX_BYTES // 1024} KiB" in text + + +# -- the whole thing, on a realistic mixed log ----------------------------------------------------- + + +def test_a_realistic_mixed_log_reads_as_the_story_it_actually_is() -> None: + """Three weeks of quiet daily cycles, one rail veto, one gate rejection, and a run of + uncorrelated fetch failures -- the exact shape of the deployment this feature was built for. + The point of the assertion is that all four kinds survive together, in order, and that the + notable ones are distinguishable from the quiet ones by style alone.""" + lines: list[str] = [] + for i in range(5): + lines.extend(_quiet_cycle_lines(f"quiet-{i}", T0 + i * 86400)) + lines.extend(_fetch_failure_pair(T0 + 5 * 86400)) + lines.extend(_rail_veto_cycle_lines("veto", T0 + 6 * 86400)) + lines.extend( + _quiet_cycle_lines("rejected", T0 + 7 * 86400) + + [ + _line( + "engine.setup_rejected", + T0 + 7 * 86400 + 5, + "rejected", + rule="turtle_breakout", + product="PAXG-USD", + gate="choppy_regime", + ) + ] + ) + lines.append("{truncated mid-write") + + feed = feed_from_lines(lines, source="/tmp/keel.log") + + assert feed.status == "ok" + assert feed.lines_skipped == 1 + assert [c.cycle_id for c in feed.cycles][:3] == ["rejected", "veto", None] + styles = {c.cycle_id: cycle_style(c) for c in feed.cycles} + assert styles["veto"] == "warn" + assert styles["rejected"] == "warn" + assert styles[None] == "alert" + assert styles["quiet-0"] == "muted" + + +# -- hostile numeric input: the renderers run inside the live loop's repaint path ----------------- + + +@pytest.mark.parametrize("hostile_ts", [1e20, -1e20, "nan", "inf", "-inf", 1e300]) +def test_a_timestamp_outside_the_renderable_range_is_treated_as_missing(hostile_ts: Any) -> None: + """`time.localtime`/`time.strftime` RAISE on these rather than degrade, and the renderer runs + on the dashboard's repaint path -- one such record would take the whole TUI down. It is + treated exactly like a missing `ts`: the neighbour's time is borrowed.""" + lines = [ + _line("agent.cycle_start", T0, "cycle-a"), + json.dumps({"ts": hostile_ts, "event": "agent.mode_resolved", "cycle_id": "cycle-a"}), + ] + + feed = feed_from_lines(lines) + (cycle,) = feed.cycles + + assert len(cycle.events) == 2 + assert cycle.events[1].ts == T0 + assert render_cycle_row(cycle) # and it renders, which is the point + assert all(render_event_row(e) for e in cycle.events) + + +def test_a_hostile_timestamp_with_no_predecessor_is_skipped_not_rendered() -> None: + feed = feed_from_lines([json.dumps({"ts": 1e20, "event": "agent.cycle_start"})]) + + assert feed.cycles == () + assert feed.lines_skipped == 1 + + +def test_rendering_a_hand_built_event_with_an_impossible_ts_does_not_raise() -> None: + """The backstop for a caller that never went through `parse_events` -- a `??:??:??` on screen + is a far better outcome than an exception on the repaint path.""" + ev = ActivityEvent(ts=1e20, level="INFO", event="agent.cycle_start", cycle_id="c", fields={}) + cycle = summarise_cycle("c", [ev]) + + assert "?" in render_event_row(ev) + assert "?" in render_cycle_row(cycle) + + +def test_one_garbled_count_does_not_discard_every_other_cycle_in_the_window() -> None: + """`float("inf")` PARSES; it is `int()` that raises `OverflowError`, which is not a + `ValueError`. Letting that escape would abort the whole grouping pass, so a single bad line + would empty a feed holding weeks of perfectly good cycles.""" + lines = [ + *_quiet_cycle_lines("good-before", T0), + _line( + "agent.signals_evaluated", + T0 + 100, + "garbled", + product="BTC-USD", + rule_count=1, + signal_count="inf", + ), + *_quiet_cycle_lines("good-after", T0 + 86400), + ] + + feed = feed_from_lines(lines) + + assert feed.status == "ok" + assert {c.cycle_id for c in feed.cycles} == {"good-before", "garbled", "good-after"} + assert _cycle_by_id(feed, "garbled").signals == 0 + + +def test_a_read_window_holding_no_whole_record_is_not_reported_as_empty(tmp_path: Any) -> None: + """One ERROR record carrying a traceback can be kilobytes on its own. Reusing the `empty` + status here would print "engine log is empty (N bytes)", which is self-contradictory and + sends an operator after the wrong problem.""" + path = tmp_path / "keel.log" + path.write_text(_line("cb_client.accounts_fetch_failed", T0, None, exc="x" * 4000) + "\n") + + # A window that lands inside the single huge record: everything before the first newline is + # a partial record and is trimmed, and the only newline in range is the file's trailing one. + window = read_log_window(path, max_bytes=64) + + assert window.status == "oversized" + assert "no complete record" in (window.detail or "") + assert window.size_bytes > 64 + + feed = ActivityFeed(status=window.status, source=str(path), detail=window.detail) + text = " ".join(describe_status(feed)) + assert "empty" not in text + assert "No complete record" in text diff --git a/tests/commands/test_tui.py b/tests/commands/test_tui.py index e25b5d6a..e4805f13 100644 --- a/tests/commands/test_tui.py +++ b/tests/commands/test_tui.py @@ -22,6 +22,7 @@ import keel.commands.tui as tui_mod from keel.cli import cli +from keel.commands.activity import ActivityFeed, feed_from_lines from keel.commands.admission import DiscoverReport from keel.commands.insights import ( AccountSummary as InsightsAccountSummary, @@ -48,9 +49,12 @@ _SHORT_VERSION, AvailableBalance, ScreenLine, + _activity_cursor, + _activity_lines, _admission_line_style, _available_lines, _confirm_arm_autonomy, + _follow_cursor, _footer_lines, _freshness_style, _guarded, @@ -63,6 +67,7 @@ _stdio_is_interactive, _style_attrs, _visible_slice, + build_activity_overlay, build_admission_screen_overlay, build_discover_overlay, build_help_screen, @@ -81,6 +86,7 @@ Caps, Config, DcaConfig, + LoggingConfig, MarketDataConfig, MoneyMgmtConfig, ) @@ -2292,3 +2298,473 @@ def test_the_refresh_toast_reads_as_ok_not_as_a_failure() -> None: """It is a routine, successful action -- it must not paint in the alert/warn colours reserved for a failure, a cancelled action, or arming autonomy.""" assert _message_style(_REFRESH_MESSAGE) == "ok" + + +# -- activity overlay (v): the pure builder ------------------------------------------------------ + + +def _activity_line(event: str, ts: float, cycle_id: str | None = "cyc-1", **fields: Any) -> str: + """One JSONL record in `keel_core.telemetry.JsonFormatter`'s shape. A local copy of + `tests/commands/test_activity.py`'s helper on purpose: the exhaustive parsing/grouping + coverage lives over there, and these tests only need enough of a log to prove the OVERLAY + renders and scrolls it.""" + payload: dict[str, Any] = { + "ts": ts, + "level": fields.pop("level", "INFO"), + "logger": "keel.agent", + "event": event, + "venue": "coinbase", + } + if cycle_id is not None: + payload["cycle_id"] = cycle_id + payload.update(fields) + return json.dumps(payload) + + +#: A two-cycle log: an ordinary quiet cycle, then the real 2026-08-08 PAXG shape -- a setup, a +#: guard violation, and an entry that was not placed. +_ACTIVITY_TS = 1_786_194_006.0 + + +def _activity_log_lines() -> list[str]: + return [ + _activity_line("agent.cycle_start", _ACTIVITY_TS, "quiet-1"), + _activity_line("agent.mode_resolved", _ACTIVITY_TS + 1, "quiet-1", mode="paper"), + _activity_line( + "agent.signals_evaluated", + _ACTIVITY_TS + 2, + "quiet-1", + product="BTC-USD", + rule_count=1, + signal_count=0, + ), + _activity_line("agent.cycle_start", _ACTIVITY_TS + 86400, "veto-1"), + _activity_line("agent.mode_resolved", _ACTIVITY_TS + 86401, "veto-1", mode="paper"), + _activity_line( + "engine.setup_detected", + _ACTIVITY_TS + 86402, + "veto-1", + rule="turtle_breakout", + product="PAXG-USD", + cts_score=5, + technique="signal_candle", + entry="4342.52", + stop="4197.09381782563408", + target="5215.07709304619552", + ), + _activity_line( + "agent.signals_evaluated", + _ACTIVITY_TS + 86402, + "veto-1", + product="PAXG-USD", + rule_count=1, + signal_count=1, + ), + _activity_line( + "guards.check_failed", + _ACTIVITY_TS + 86402, + "veto-1", + product="PAXG-USD", + side="BUY", + violation=( + "per_asset_concentration_cap: PAXG exposure 3284.671252850915628790264696 " + "exceeds 0.5 of max_exposure_usd (2500.0)" + ), + ), + _activity_line( + "agent.enter_evaluated", + _ACTIVITY_TS + 86402, + "veto-1", + product="PAXG-USD", + rule="turtle_breakout", + technique="signal_candle", + cts_score=5, + placed=False, + reason="paper: vetoed by rails", + ), + ] + + +def _write_activity_log(tmp_path: Any) -> str: + path = tmp_path / "logs" / "keel.log" + path.parent.mkdir(parents=True, exist_ok=True) + path.write_text("\n".join(_activity_log_lines()) + "\n") + return str(path) + + +def _activity_feed() -> Any: + return feed_from_lines(_activity_log_lines(), source="/tmp/keel.log") + + +def test_build_activity_overlay_is_titled_and_lists_one_row_per_cycle_newest_first() -> None: + lines = build_activity_overlay(_activity_feed()) + texts = [line.text for line in lines] + + assert texts[0] == "keel tui -- activity" + veto_idx = next(i for i, t in enumerate(texts) if "rail veto" in t) + quiet_idx = next(i for i, t in enumerate(texts) if "quiet -- looked" in t) + assert veto_idx < quiet_idx # newest first + + +def test_build_activity_overlay_collapsed_does_not_list_individual_events() -> None: + texts = [line.text for line in build_activity_overlay(_activity_feed())] + + assert not any("engine.setup_detected" in t for t in texts) + + +def test_build_activity_overlay_expanded_lists_the_cycles_events_in_time_order() -> None: + feed = _activity_feed() + texts = [ + line.text + for line in build_activity_overlay(feed, cursor=0, expanded=frozenset({"veto-1"})) + ] + + setup_idx = next(i for i, t in enumerate(texts) if "engine.setup_detected" in t) + guard_idx = next(i for i, t in enumerate(texts) if "guards.check_failed" in t) + enter_idx = next(i for i, t in enumerate(texts) if "agent.enter_evaluated" in t) + assert setup_idx < guard_idx < enter_idx + # ...and the fields that carry the meaning, not just the event names. + assert any("entry=4342.52" in t for t in texts) + assert any("per_asset_concentration_cap" in t for t in texts) + assert any("paper: vetoed by rails" in t for t in texts) + + +def test_activity_overlay_styles_a_veto_cycle_differently_from_a_quiet_one() -> None: + """The at-a-glance requirement: a rail veto must not read the same as a quiet cycle.""" + lines = build_activity_overlay(_activity_feed()) + veto = next(line for line in lines if "rail veto" in line.text) + quiet = next(line for line in lines if "quiet -- looked" in line.text) + + assert veto.style != quiet.style + assert quiet.style == "muted" + + +def test_activity_overlay_tells_the_operator_how_to_use_it() -> None: + texts = [line.text for line in build_activity_overlay(_activity_feed())] + + footer = texts[-1] + assert "expand" in footer + assert "close" in footer + + +@pytest.mark.parametrize( + ("status", "expected_fragment"), + [ + ("missing", "No engine log found"), + ("empty", "is empty"), + ("unparseable", "could be parsed"), + ("oversized", "No complete record"), + ("unreadable", "could not be read"), + ], +) +def test_activity_overlay_explains_a_broken_log_instead_of_rendering_blank( + status: str, expected_fragment: str +) -> None: + """A blank overlay would be indistinguishable from the dead-looking dashboard this whole + feature exists to disprove -- so every failure mode renders words.""" + feed = ActivityFeed(status=status, source="/tmp/keel.log", detail="because reasons") + + lines = build_activity_overlay(feed) + texts = [line.text for line in lines] + + assert texts[0] == "keel tui -- activity" + assert any(expected_fragment in t for t in texts) + assert any("Press v or Esc" in t for t in texts) + + +def test_activity_overlay_on_a_readable_log_with_no_cycles_says_so() -> None: + feed = ActivityFeed(status="ok", source="/tmp/keel.log", cycles=()) + + texts = [line.text for line in build_activity_overlay(feed)] + + assert any("No cycles in the window" in t for t in texts) + + +# -- activity overlay: the cursor ---------------------------------------------------------------- + + +def test_activity_cursor_line_points_at_the_selected_row() -> None: + feed = _activity_feed() + + for cursor in range(len(feed.cycles)): + lines, cursor_line = _activity_lines(feed, cursor=cursor) + assert lines[cursor_line].text.startswith(">") + + +def test_activity_cursor_line_survives_a_row_above_it_being_expanded() -> None: + """The arithmetic that would drift if the cursor's screen position were computed by a second + copy of the layout: expanding the FIRST row pushes the second one down by its event count.""" + feed = _activity_feed() + + lines, cursor_line = _activity_lines(feed, cursor=1, expanded=frozenset({"veto-1"})) + + assert lines[cursor_line].text.startswith(">") + assert "quiet -- looked" in lines[cursor_line].text + + +def test_activity_cursor_line_on_an_empty_feed_is_in_range() -> None: + lines, cursor_line = _activity_lines(ActivityFeed(status="ok", source="x", cycles=())) + + assert 0 <= cursor_line < len(lines) + + +@pytest.mark.parametrize( + ("key", "start", "expected"), + [ + ("KEY_DOWN", 0, 1), + ("KEY_UP", 3, 2), + ("KEY_HOME", 4, 0), + ("KEY_END", 0, 4), + ("KEY_NPAGE", 0, 4), # a page is larger than this feed -- clamped to the last row + ("KEY_PPAGE", 4, 0), + ], +) +def test_activity_cursor_moves_by_rows_and_clamps(key: str, start: int, expected: int) -> None: + fake_curses = _fake_curses() + + assert _activity_cursor(getattr(fake_curses, key), start, 24, 5, fake_curses) == expected + + +def test_activity_cursor_accepts_the_same_vi_keys_the_other_overlays_scroll_with() -> None: + fake_curses = _fake_curses() + + assert _activity_cursor(ord("j"), 0, 24, 5, fake_curses) == 1 + assert _activity_cursor(ord("k"), 2, 24, 5, fake_curses) == 1 + + +def test_activity_cursor_never_leaves_the_feed() -> None: + fake_curses = _fake_curses() + + assert _activity_cursor(fake_curses.KEY_UP, 0, 24, 5, fake_curses) == 0 + assert _activity_cursor(fake_curses.KEY_DOWN, 4, 24, 5, fake_curses) == 4 + # An empty feed has no row to select at all. + assert _activity_cursor(fake_curses.KEY_DOWN, 0, 24, 0, fake_curses) == 0 + + +def test_activity_cursor_ignores_an_unrelated_key() -> None: + fake_curses = _fake_curses() + + assert _activity_cursor(ord("z"), 2, 24, 5, fake_curses) == 2 + assert _activity_cursor(-1, 2, 24, 5, fake_curses) == 2 # the no-key poll timeout + + +@pytest.mark.parametrize( + ("offset", "cursor_line", "height", "expected"), + [ + (0, 5, 24, 0), # already visible -- do not move the view at all + (10, 5, 24, 5), # above the window -- scroll up to it + (0, 30, 24, 7), # below the window -- scroll down the minimum + (0, 5, 0, 0), # a terminal mid-resize must not divide by anything + (3, 3, 1, 3), + ], +) +def test_follow_cursor_makes_the_smallest_change_that_reveals_the_cursor( + offset: int, cursor_line: int, height: int, expected: int +) -> None: + assert _follow_cursor(offset, cursor_line, height) == expected + + +# -- activity overlay: the live loop ------------------------------------------------------------- + + +def test_footer_lines_advertise_the_activity_key() -> None: + texts = [line.text for line in _footer_lines()] + + assert any("[v] activity" in t for t in texts) + + +def test_help_screen_documents_the_activity_overlay_and_its_keys() -> None: + texts = [line.text for line in build_help_screen()] + joined = " ".join(texts) + + assert any(t.strip().startswith("v ") for t in texts) + assert "Activity overlay (v)" in joined + assert "q / Esc / v" in joined + assert "Enter / Space" in joined + # The two claims the design rests on: it is offline, and the read is bounded. + assert "BOUNDED" in joined + assert "logging.file" in joined + + +def test_run_live_v_opens_activity_overlay_and_esc_closes_it( + repo: Repository, monkeypatch: pytest.MonkeyPatch, tmp_path: Any +) -> None: + """Mirrors the 's'/'p' tests: 'v' opens, Esc closes back to the dashboard.""" + config = _config(logging=LoggingConfig(file=_write_activity_log(tmp_path))) + stdscr = _KeySequenceStdscr(height=24, width=200, keys=[ord("v"), -1, 27]) + + fake_curses = _fake_curses() + fake_curses.wrapper = lambda fn: fn(stdscr) + monkeypatch.setitem(sys.modules, "curses", fake_curses) + + def open_state() -> tuple[Repository, Any]: + return repo, config + + run_live(open_state, lambda: NOW_TS, interval=0.01) + + painted_texts = [call[2] for call in stdscr.calls] + activity_idx = next(i for i, t in enumerate(painted_texts) if "keel tui -- activity" in t) + dashboard_after_idx = next( + i for i, t in enumerate(painted_texts) if i > activity_idx and "paper mode" in t + ) + assert dashboard_after_idx > activity_idx + + +def test_run_live_activity_overlay_paints_the_real_cycles_from_the_configured_log( + repo: Repository, monkeypatch: pytest.MonkeyPatch, tmp_path: Any +) -> None: + """The end-to-end claim: the path comes from `logging.file`, the rows come from that file, + and a rail-vetoed cycle is legible without expanding anything.""" + config = _config(logging=LoggingConfig(file=_write_activity_log(tmp_path))) + stdscr = _KeySequenceStdscr(height=40, width=240, keys=[ord("v"), -1]) + + fake_curses = _fake_curses() + fake_curses.wrapper = lambda fn: fn(stdscr) + monkeypatch.setitem(sys.modules, "curses", fake_curses) + + def open_state() -> tuple[Repository, Any]: + return repo, config + + run_live(open_state, lambda: NOW_TS, interval=0.01) + + painted_texts = [call[2] for call in stdscr.calls] + assert any("rail veto: per_asset_concentration_cap" in t for t in painted_texts) + assert any("quiet -- looked, nothing to do" in t for t in painted_texts) + + +def test_run_live_activity_enter_expands_the_selected_cycle( + repo: Repository, monkeypatch: pytest.MonkeyPatch, tmp_path: Any +) -> None: + config = _config(logging=LoggingConfig(file=_write_activity_log(tmp_path))) + # poll1: normal -> 'v'. poll2: activity, Enter expands row 0 (the newest, vetoed cycle). + # poll3: activity, repainted expanded. poll4: 'q' (the stdscr's post-exhaustion default). + stdscr = _KeySequenceStdscr(height=40, width=240, keys=[ord("v"), 10, -1]) + + fake_curses = _fake_curses() + fake_curses.wrapper = lambda fn: fn(stdscr) + monkeypatch.setitem(sys.modules, "curses", fake_curses) + + def open_state() -> tuple[Repository, Any]: + return repo, config + + run_live(open_state, lambda: NOW_TS, interval=0.01) + + painted_texts = [call[2] for call in stdscr.calls] + assert any("guards.check_failed" in t for t in painted_texts) + assert any("paper: vetoed by rails" in t for t in painted_texts) + + +def test_run_live_activity_overlay_reports_a_missing_log_rather_than_crashing( + repo: Repository, monkeypatch: pytest.MonkeyPatch, tmp_path: Any +) -> None: + config = _config(logging=LoggingConfig(file=str(tmp_path / "nowhere" / "keel.log"))) + stdscr = _KeySequenceStdscr(height=24, width=200, keys=[ord("v"), -1]) + + fake_curses = _fake_curses() + fake_curses.wrapper = lambda fn: fn(stdscr) + monkeypatch.setitem(sys.modules, "curses", fake_curses) + + def open_state() -> tuple[Repository, Any]: + return repo, config + + run_live(open_state, lambda: NOW_TS, interval=0.01) + + painted_texts = [call[2] for call in stdscr.calls] + assert any("No engine log found" in t for t in painted_texts) + + +def test_run_live_activity_survives_a_transient_read_error_and_keeps_polling( + repo: Repository, monkeypatch: pytest.MonkeyPatch, tmp_path: Any +) -> None: + """`open_state()` itself failing (a locked DB from a concurrent `keel agent` writer) must + become a readable overlay, not a crash -- the same contract the insights/screen/propose + branches keep.""" + config = _config(logging=LoggingConfig(file=_write_activity_log(tmp_path))) + stdscr = _KeySequenceStdscr(height=24, width=200, keys=[ord("v"), -1, -1]) + + fake_curses = _fake_curses() + fake_curses.wrapper = lambda fn: fn(stdscr) + monkeypatch.setitem(sys.modules, "curses", fake_curses) + + opens: list[int] = [] + + def open_state() -> tuple[Repository, Any]: + opens.append(1) + # Fail on the FIRST call made from inside the activity branch (calls 1 and 2 are the + # normal-mode status read and its balance refresh). + if len(opens) == 3: + raise sqlite3.OperationalError("database is locked") + return repo, config + + run_live(open_state, lambda: NOW_TS, interval=0.01) + + painted_texts = [call[2] for call in stdscr.calls] + assert any("could not be read" in t for t in painted_texts) + # ...and it kept polling: a later frame rendered the real feed. + assert any("rail veto" in t for t in painted_texts) + + +def test_run_live_activity_overlay_never_builds_a_broker( + repo: Repository, monkeypatch: pytest.MonkeyPatch, tmp_path: Any +) -> None: + """The overlay's whole admissibility argument is that reading a local file is neither a + broker nor the network. Opening it must add ZERO broker constructions on top of the ones the + normal-mode dashboard already makes (one slow-cadence balance refresh, here).""" + config = _config(logging=LoggingConfig(file=_write_activity_log(tmp_path))) + stdscr = _KeySequenceStdscr(height=24, width=200, keys=[ord("v"), -1, -1, 27]) + + fake_curses = _fake_curses() + fake_curses.wrapper = lambda fn: fn(stdscr) + monkeypatch.setitem(sys.modules, "curses", fake_curses) + + built: list[Any] = [] + + def _recording_build_broker(cfg: Any, **kwargs: Any) -> Any: + built.append(cfg) + raise RuntimeError("no venue in tests") + + monkeypatch.setattr("keel.commands._common._build_broker", _recording_build_broker) + + def open_state() -> tuple[Repository, Any]: + return repo, config + + run_live(open_state, lambda: NOW_TS, interval=0.01) + + painted_texts = [call[2] for call in stdscr.calls] + assert any("keel tui -- activity" in t for t in painted_texts) + # `now_fn` is constant, so the ~30s balance cadence fires exactly once, on the first poll. + # Any second construction could only have come from the activity branch. + assert len(built) == 1 + + +def test_run_live_activity_survives_a_log_record_whose_timestamp_cannot_be_rendered( + repo: Repository, monkeypatch: pytest.MonkeyPatch, tmp_path: Any +) -> None: + """The renderer, not just the feed builder, runs on the repaint path. A `ts` no `strftime` + can format (a bad clock, a corrupted byte) must not escape `curses.wrapper` and kill the + dashboard -- which is why `run_live` wraps the RENDER, not only the build.""" + path = tmp_path / "keel.log" + path.write_text( + "\n".join( + [ + *_activity_log_lines(), + json.dumps({"ts": 1e20, "event": "agent.cycle_start", "cycle_id": "from-mars"}), + ] + ) + + "\n" + ) + config = _config(logging=LoggingConfig(file=str(path))) + stdscr = _KeySequenceStdscr(height=40, width=240, keys=[ord("v"), -1]) + + fake_curses = _fake_curses() + fake_curses.wrapper = lambda fn: fn(stdscr) + monkeypatch.setitem(sys.modules, "curses", fake_curses) + + def open_state() -> tuple[Repository, Any]: + return repo, config + + run_live(open_state, lambda: NOW_TS, interval=0.01) # must not raise + + painted_texts = [call[2] for call in stdscr.calls] + assert any("keel tui -- activity" in t for t in painted_texts) + assert any("rail veto" in t for t in painted_texts)