From 1142af155257c4ad16ed7f83ab492afe04e024aa Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Tue, 11 Aug 2026 11:23:20 -0400 Subject: [PATCH] feat(tui): add the `v` activity feed -- what keel has been DOING, cycle by cycle keel has been running fine for weeks and has not traded, and the dashboard makes that look like death. It cannot help: every one of its six panels reports STATE, and state is exactly what a correctly-idle deployment and a crashed one have in common -- the same zeroes, the same empty position list, the same flat equity. What is missing is the narrative. The narrative already exists. Every cycle emits `agent.cycle_start`, `agent.feed_polled`, `agent.signals_evaluated`, `engine.setup_detected` / `setup_rejected`, `guards.check_failed` and `agent.enter_evaluated` into the structured JSONL engine log, all correlated by the `cycle_id` `keel/agent.py` binds via `keel_core.telemetry.bind_cycle`. Nothing surfaced it. `v` does. A chronological feed, newest first, ONE ROW PER CYCLE, expandable to the events inside it. A quiet cycle still gets a row -- the run of quiet cycles IS the answer to "is it alive", and a feed that omitted them would reproduce the very impression it exists to fix. The source is the LOG, not the database, and not a new table. A table would have been tidier and wrong: it would start EMPTY on precisely the deployment this feature exists to explain, and stay uninformative for however many weeks it took to fill. The log is already months deep. No schema change, no migration, no engine change -- `keel/commands/activity.py` only reads. That makes `v` the one overlay that reads a file rather than the DB, so the module and the TUI docstring both say plainly why that is admissible. The dashboard's iron rule is "DB reads only; never builds a broker, never touches the network". Reading a local file is NEITHER: no broker, no socket, no name resolution. The rule exists so opening an overlay can never place an order, spend money, or block on a remote host, and a bounded local read violates none of that -- the same latitude `p` propose already takes for `config.proposals_dir`. The network-exception count stands at three. The read is BOUNDED because the log grows without limit and this rebuilds on every poll: the newest 1 MiB, 5000 lines, 200 cycles, 400 events per cycle, all named constants. On the real deployment's 815 KB log that is the whole file in 3.7 ms; against a 25 MB rotated one the cost is unchanged. When a cap bites, the feed says so rather than quietly presenting its window as history. Everything degrades to a sentence. Missing file (with the working-directory trap named, since that is the commonest cause), empty file, permissions error, a partial JSON line from a crash mid-write, a line that is valid JSON but not an object, a record with no `ts`, a record with no `cycle_id` at all (the 64 uncorrelated fetch failures in the real log are grouped by contiguity rather than dropped), a `ts` no `strftime` can format, a garbled count, a rotated log, a window holding no whole record -- each has a defined outcome and a test. Never a traceback, and never a blank overlay. The parsing, grouping and summarising are pure functions in a separate module with 116 tests built from the real event shapes; `tui.py` only styles what they render, exactly as it already does for `insights` and `admission`. --- keel/commands/activity.py | 1053 ++++++++++++++++++++++++ keel/commands/tui.py | 323 +++++++- tests/commands/test_activity.py | 1368 +++++++++++++++++++++++++++++++ tests/commands/test_tui.py | 476 +++++++++++ 4 files changed, 3209 insertions(+), 11 deletions(-) create mode 100644 keel/commands/activity.py create mode 100644 tests/commands/test_activity.py 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)