fix(web): the CSV export sent a body on HEAD, dropped connections, an…

keel/commands/timeline.py

@@ -59,11 +59,14 @@
 
 #: The characters a spreadsheet treats as the start of a formula. OWASP's list.
 #:
+#: `\n` and `\r` are here alongside `\t` because a cell can only be re-parsed from its start,
+#: and a leading line break is one of the ways a value smuggles itself into that position.
+#:
 #: `-` and `+` are here because they are formulas too, not only signs -- which means a negative
 #: figure gets quoted. That is the correct trade for an audit export: a spreadsheet shows
 #: `'-12.30` as text rather than evaluating it, the value is still readable and still
 #: re-importable, and losing numeric typing is a smaller harm than executing a cell.
-_FORMULA_TRIGGERS = ("=", "+", "-", "@", "\t", "\r")
+_FORMULA_TRIGGERS = ("=", "+", "-", "@", "\t", "\r", "\n")
 
 
 def csv_safe(value: Any) -> str:
@@ -85,7 +88,16 @@ def csv_safe(value: Any) -> str:
     if value is None:
         return ""
     text = str(value)
-    if text.startswith(_FORMULA_TRIGGERS):
+    # Checked against the LEADING-WHITESPACE-STRIPPED text, and the ORIGINAL is what gets quoted.
+    # A strict first-character test is defeated by one space: `" =cmd|..."` is a legal
+    # `coinbase_id` out of an imported venue CSV, it lands in a cell by itself, and Google Sheets
+    # and LibreOffice trim on import before deciding whether a cell is a formula. Excel treats a
+    # leading space as text -- but a defence that holds in one spreadsheet and not the two this
+    # file will also be opened in is not a defence.
+    # `lstrip(" ")` and not a bare `lstrip()`: tab and carriage return are TRIGGERS themselves,
+    # so stripping all whitespace would consume the very characters being looked for and let
+    # "\t=cmd" through. Spaces are the only thing skipped over.
+    if text.lstrip(" ").startswith(_FORMULA_TRIGGERS):
         return "'" + text
     return text
 
@@ -125,13 +137,15 @@ class TimelineReport:
     scope_start_ts: int | None
     #: The applied `kind` filter, echoed back, or `""` for every kind.
     kind: str
-    limit: int
+    #: The applied row cap, or `None` when the caller asked for no slice (the CSV export).
+    limit: int | None
     #: Rows across all four sources inside the scope, before `kind` and before `limit`.
     scoped_count: int
     #: Rows after `kind`, before `limit` -- what `rows` is a page of.
     filtered_count: int
     rows: tuple[TimelineRow, ...]
 
+
     #: Every kind present in the SCOPED set, in `TIMELINE_KINDS` order -- what a chip bar is
     #: built from. STORED rather than derived from `rows`, because `rows` is what the chip and
     #: the cap left: derived from those, selecting Flows would delete the Trades chip and leave
@@ -143,21 +157,50 @@ class TimelineReport:
     #: bar that reordered itself as history arrived would move under the reader.
     kinds_present: tuple[str, ...]
 
+    #: `read_log_window`'s own word for how the engine log read went: `ok`, `missing`, `empty`,
+    #: `oversized`, `unreadable`. Carried rather than acted on, so the page and the CSV can SAY
+    #: the log did not reach this report.
+    #:
+    #: The alternative was tried and was wrong in both directions. Discarding it made an
+    #: unreadable log indistinguishable from an idle engine -- under-reporting reality while
+    #: looking healthy, which `activity.py`'s own docstring names as the failure. RAISING on it
+    #: made an EMPTY log (an ordinary state: a fresh handler, the moment after a rotation) take
+    #: out orders, flows and attestations too, a total outage to report a non-problem.
+    log_status: str = "ok"
+
     @property
     def shown_count(self) -> int:
         """How many rows this report carries. Derived rather than stored, and held here because
         `keel/web/payload.py` may not call `len()` (Rule 6e)."""
         return len(self.rows)
 
+    @property
+    def log_gap(self) -> bool:
+        """Whether the engine log's contents are MISSING FROM this report.
+
+        `missing` is not a gap: a deployment that has never run has no log, and that is an
+        ordinary fact rather than a hole in the record. Every other non-`ok` status is -- the
+        file is there and what it holds did not reach this report, which is precisely what an
+        auditor reading the CSV needs told rather than left to infer from an absence of rows.
+        """
+        return self.log_status not in ("ok", "missing")
+
 
 
-#: The cap on one merged read. Four stores, three of them unbounded, joined into one response:
-#: without a cap this route's cost is the size of the deployment's whole history. Newest-first
-#: and capped means the page always answers, and the counts below say how much it did not show.
+#: The cap on one PAGE of the merged feed -- the response slice, not the read.
+#:
+#: Stated precisely because the first version of this note was wrong: the four reads underneath
+#: are unfiltered (`get_orders`, `get_transactions` and both attestation reads are `SELECT *`,
+#: scoped in Python afterwards), so the READ cost is the deployment's whole history whatever this
+#: number says. That matches `gather_orders`' own convention and is not a regression -- but the
+#: cap bounds what crosses the wire and what a browser renders, and claiming more than that is
+#: the kind of comfortable inaccuracy this codebase's documentation standard exists to catch.
+#:
+#: Newest-first and capped means the page always answers, and the counts say how much it did not
+#: show. `export_rows` deliberately does not use it.
 DEFAULT_TIMELINE_LIMIT = 200
 MAX_TIMELINE_LIMIT = 2000
 
-
 def _order_rows(repo: Repository, since_ts: int | None) -> list[TimelineRow]:
     """`orders` -> trade rows.
 
@@ -316,8 +359,9 @@ def gather_timeline(
     now_ts: int,
     scope: str = "all",
     kind: str = "",
-    limit: int = DEFAULT_TIMELINE_LIMIT,
+    limit: int | None = DEFAULT_TIMELINE_LIMIT,
     cycles: Sequence[Any] = (),
+    log_status: str = "ok",
 ) -> TimelineReport:
     """One chronology over four stores, newest first, scoped, chip-filtered and capped.
 
@@ -334,8 +378,19 @@ def gather_timeline(
     filtering the rows it happened to receive and calling the result "every flow this month".
     """
     resolved_scope = normalise_scope(scope)
-    resolved_kind = (kind or "").strip().lower()
-    resolved_limit = max(1, min(int(limit), MAX_TIMELINE_LIMIT))
+    # An unrecognised kind is COLLAPSED to "every kind", not applied. `?kind=trades` -- the
+    # obvious typo, since the chips read "trade" -- would otherwise return a page that looks like
+    # an empty deployment: a non-zero `scoped_count`, zero rows, and no chip marked current.
+    # That is the outcome `normalise_scope`, which this function sits beside and reuses, exists
+    # to never produce. The applied value is echoed in `kind`, so the substitution is visible.
+    requested_kind = (kind or "").strip().lower()
+    resolved_kind = requested_kind if requested_kind in TIMELINE_KINDS else ""
+    # `None` means NO SLICE, and it has to be a distinct case rather than a very large number.
+    # The first attempt at an uncapped export passed `2**31` through this clamp, which is
+    # `min(2**31, 2000)` -- so the "whole scope" export quietly stopped at 2000 rows, and the
+    # test written for it seeded 225 and could not see that. A sentinel that the clamp silently
+    # eats is not a sentinel.
+    resolved_limit = None if limit is None else max(1, min(int(limit), MAX_TIMELINE_LIMIT))
     since = scope_start_ts(resolved_scope, now_ts)
 
     scoped: list[TimelineRow] = []
@@ -359,11 +414,50 @@ def gather_timeline(
         limit=resolved_limit,
         scoped_count=len(scoped),
         filtered_count=len(filtered),
-        rows=tuple(filtered[:resolved_limit]),
+        rows=tuple(filtered if resolved_limit is None else filtered[:resolved_limit]),
+        log_status=log_status,
         kinds_present=tuple(kind for kind in TIMELINE_KINDS if kind in present),
     )
 
 
+def export_rows(
+    repo: Repository,
+    *,
+    now_ts: int,
+    scope: str = "all",
+    kind: str = "",
+    cycles: Sequence[Any] = (),
+    log_status: str = "ok",
+) -> TimelineReport:
+    """The whole scope, uncapped -- what the CSV export reads.
+
+    **Deliberately not `gather_timeline`'s cap.** That cap exists because the console polls the
+    JSON route every 15 seconds; an export is a deliberate download, requested once, of a record
+    an operator may hand to an auditor or a tax preparer. Inheriting the page's limit made the
+    file 200 rows of a 5,000-event deployment with nothing in it saying so -- a partial record
+    that reads as complete, which is worse than no export at all.
+
+    The SCOPE still bounds it: `?scope=today|7d|all` is the operator's own choice about how much
+    they are asking for, and `all` on a long-lived deployment is a large file by request rather
+    than by accident.
+
+    **The whole file is materialised in memory** -- as a `str`, then as `bytes`, because the
+    response carries a `Content-Length`. That is an accepted cost for a download an operator
+    asked for once, and it is the reason the paged route keeps its cap: the same read on a
+    15-second poll would not be acceptable. Streaming it is the change to make if `all` on a
+    multi-year deployment ever stops fitting comfortably.
+    """
+    return gather_timeline(
+        repo,
+        now_ts=now_ts,
+        scope=scope,
+        kind=kind,
+        limit=None,
+        cycles=cycles,
+        log_status=log_status,
+    )
+
+
 def to_csv(report: TimelineReport) -> str:
     """The audit export: one row per event, every text cell neutralised (`csv_safe`).
 
@@ -376,6 +470,18 @@ def to_csv(report: TimelineReport) -> str:
     """
     buffer = io.StringIO()
     writer = csv.writer(buffer)
+    if report.log_gap:
+        # Stated IN THE FILE, above the header, because this file leaves the application. An
+        # auditor holding a CSV cannot ask the page whether a source was missing from it, and
+        # rows that are simply absent look identical to rows that never existed.
+        writer.writerow(
+            [
+                csv_safe(
+                    f"# NOTE: the engine log could not be read ({report.log_status}); "
+                    "cycle rows are missing from this export"
+                )
+            ]
+        )
     writer.writerow(
         [
             "ts",

keel/web/api.py

@@ -359,15 +359,45 @@ def read_balances(cfg: ServeConfig, _query: Query, _state: Any, now_ts: int) ->
     return payload.balances_payload(report)
 
 
+def _log_cycles(config: Any) -> tuple[tuple[Any, ...], str]:
+    """`(cycles, status)` -- the engine log's cycles, and how the read of it went.
+
+    Read through `activity`'s own bounded window rather than re-parsed here: that module owns
+    finding the file, reading a bounded tail and turning it into cycles, and a second
+    implementation would be a second answer to "what did the agent do".
+
+    **A log that could not be READ is not a log with nothing in it**, and it is also not a
+    reason to fail the page. `read_log_window` returns a `LogWindow` for every outcome -- it
+    catches its own `OSError` -- and names the outcome in `status`. Both other options were tried
+    and both were wrong:
+
+    * Discarding the status dropped every `system` row and dropped `system` from the chips, which
+      in an auditor's CSV is indistinguishable from "the engine never ran". `activity.py`'s own
+      docstring names that failure: silently discarding input is how a feed comes to under-report
+      reality while looking healthy.
+    * RAISING on any status but `ok`/`missing` made an EMPTY log -- an ordinary state, a freshly
+      created handler or the moment after a rotation -- take out orders, flows and attestations
+      as well. A total outage to report a non-problem, and a divergence from `/api/activity`,
+      which renders these same statuses as a stated feed state.
+
+    So the status is returned, the report carries it, and the page and the CSV say it.
+    """
+    from keel.commands.activity import feed_from_lines, read_log_window, resolve_log_path
+
+    log_path = resolve_log_path(config)
+    window = read_log_window(log_path)
+    # `LogWindow` carries the lines and a read status, not the path -- `source` is the feed's own
+    # label for where the lines came from, so it is passed the path we resolved.
+    cycles = feed_from_lines(
+        window.lines, source=str(log_path), truncated=window.truncated
+    ).cycles
+    return cycles, window.status
+
+
 def _timeline_report(cfg: ServeConfig, query: Query, now_ts: int) -> Any:
     """The merged timeline for one request. Shared by the JSON route and the CSV export so the
     file an operator downloads is the same chronology the page showed them -- two builders would
     be two answers to "what happened", and the export is the one that goes to an auditor."""
-    from keel.commands.activity import (
-        feed_from_lines,
-        read_log_window,
-        resolve_log_path,
-    )
     from keel.commands.timeline import (
         DEFAULT_TIMELINE_LIMIT,
         MAX_TIMELINE_LIMIT,
@@ -380,23 +410,7 @@ def _timeline_report(cfg: ServeConfig, query: Query, now_ts: int) -> Any:
         DEFAULT_TIMELINE_LIMIT if not raw_limit else _whole_number(raw_limit, MAX_TIMELINE_LIMIT)
     )
 
-    # The engine log is read through `activity`'s own bounded window rather than re-parsed here:
-    # that module owns finding the file, reading a bounded tail of it and turning it into cycles,
-    # and a second implementation would be a second answer to "what did the agent do".
-    cycles: tuple[Any, ...] = ()
-    try:
-        log_path = resolve_log_path(config)
-        window = read_log_window(log_path)
-        # `LogWindow` carries the lines and a read status, not the path -- `source` is the
-        # feed's own label for where the lines came from, so it is passed the path we resolved.
-        cycles = feed_from_lines(
-            window.lines, source=str(log_path), truncated=window.truncated
-        ).cycles
-    except OSError:
-        # No log yet, or an unreadable one. The timeline still has three other sources, and a
-        # missing log is not a reason to fail the whole page -- the `system` rows are simply
-        # absent, which is what an unread log honestly means.
-        cycles = ()
+    cycles, log_status = _log_cycles(config)
 
     repo = open_repo(cfg.db_path)
     try:
@@ -407,6 +421,7 @@ def _timeline_report(cfg: ServeConfig, query: Query, now_ts: int) -> Any:
             kind=_first(query, "kind") or "",
             limit=limit,
             cycles=cycles,
+            log_status=log_status,
         )
     finally:
         close_repo(repo)
@@ -702,7 +717,10 @@ class ApiRoute:
         html_route="/timeline",
         read=read_timeline,
         collection="rows",
-        sortable=("ts", "kind", "provenance", "source", "product_id"),
+        # `at`, not `ts`: the payload emits `at` (a `moment` field), and a `sortable` entry
+        # naming a key the rows do not carry is accepted, echoed back as applied, and silently
+        # does nothing -- which is the failure refusing an unknown column exists to prevent.
+        sortable=("at", "kind", "provenance", "source", "product_id"),
     ),
     "/api/rules": ApiRoute(
         html_route="/rules",
@@ -974,6 +992,19 @@ def sortable_columns() -> Mapping[str, Sequence[str]]:
 CSV_EXPORT_PATH = "/api/timeline/export.csv"
 
 
+def export_failure_envelope(exc: Exception) -> tuple[int, dict[str, Any]]:
+    """Any other export failure as `(status, document)` -- `respond`'s 500 arm, reachable from
+    the one route that is not in its table. Names the exception type and message, exactly as
+    `respond` does, so an operator has something to act on."""
+    now_ts = int(time.time())
+    return 500, payload.error_envelope(
+        now_ts,
+        status=500,
+        title="That export could not be built",
+        detail=f"{type(exc).__name__}: {exc}",
+    )
+
+
 def export_timeline_csv(cfg: ServeConfig, query: Query) -> tuple[str, str]:
     """`(csv_text, filename)` for the timeline export.
 
@@ -984,9 +1015,25 @@ def export_timeline_csv(cfg: ServeConfig, query: Query) -> tuple[str, str]:
     to be opened in Excel or Sheets, both of which execute a cell beginning `=`, `+`, `-` or `@`,
     and several columns carry text keel did not write.
     """
-    from keel.commands.timeline import to_csv
+    from keel.commands.timeline import export_rows, to_csv
 
     now_ts = int(time.time())
-    report = _timeline_report(cfg, query, now_ts)
+    cycles, log_status = _log_cycles(load_config(cfg.config_path))
+    repo = open_repo(cfg.db_path)
+    try:
+        # `export_rows`, NOT `_timeline_report`: the paged read is capped because the console
+        # polls it every 15 seconds, and an audit record that silently inherited that cap would
+        # be 200 rows of a 5,000-event deployment with nothing in the file saying so -- a partial
+        # record that reads as complete, handed to a tax preparer. The scope still bounds it.
+        report = export_rows(
+            repo,
+            now_ts=now_ts,
+            scope=_first(query, "scope") or "all",
+            kind=_first(query, "kind") or "",
+            cycles=cycles,
+            log_status=log_status,
+        )
+    finally:
+        close_repo(repo)
     stamp = datetime.fromtimestamp(now_ts, tz=UTC).strftime("%Y%m%d-%H%M%S")
     return to_csv(report), f"keel-activity-{stamp}.csv"

keel/web/server.py

@@ -418,7 +418,12 @@ def _send_csv(self, text: str, filename: str) -> None:
         for name, value in _API_HEADERS:
             self.send_header(name, value)
         self.end_headers()
-        self.wfile.write(body)
+        # The same guard `_send`, `_send_json` and `_serve_static` all carry. `do_HEAD` delegates
+        # to `do_GET`, so without it a HEAD sends the headers AND the whole file -- and on a
+        # keep-alive connection those bytes are framed as the next response, which is a
+        # same-origin response desync rather than merely a wasted transfer.
+        if self.command != "HEAD":
+            self.wfile.write(body)
 
     def _send_json(self, code: int, document: dict[str, Any]) -> None:
         """One JSON response, with its own headers.
@@ -874,7 +879,23 @@ def do_GET(self) -> None:  # noqa: N802 - stdlib's naming, not ours
             # loopback-plus-session model unchanged -- an export of the whole audit trail is the
             # last thing that should be reachable more easily than the page it came from.
             if parsed.path == api.CSV_EXPORT_PATH:
-                text, filename = api.export_timeline_csv(self.cfg, query)
+                # Wrapped, because `respond` is what normally guarantees this server never
+                # answers a GET by raising: it turns an `ApiRefusal` into a 400 and anything else
+                # into a 500 envelope. This branch does not go through it, so without this a
+                # `?limit=abc` propagated out of the handler -- the client saw a reset connection
+                # with no response at all, and a traceback of absolute source paths reached the
+                # stderr that `log_message` is overridden to keep quiet.
+                try:
+                    text, filename = api.export_timeline_csv(self.cfg, query)
+                except Exception as exc:  # noqa: BLE001 - a failed export must still answer
+                    # One arm, because nothing on the export path raises `ApiRefusal`: it reads
+                    # no `?limit=` and no `?sort=`, which are the two refusing helpers. A second
+                    # arm for it was written and removed -- an unreachable error path is one
+                    # nothing exercises, and it rots. Re-add it the day a refusing helper joins
+                    # this path.
+                    code, document = api.export_failure_envelope(exc)
+                    self._send_json(code, document)
+                    return
                 self._send_csv(text, filename)
                 return
             code, document = api.respond(self.cfg, parsed.path, query)