diff --git a/keel/commands/timeline.py b/keel/commands/timeline.py index 97b5e46..2c273ec 100644 --- a/keel/commands/timeline.py +++ b/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", diff --git a/keel/web/api.py b/keel/web/api.py index 74500d2..9fe7ba4 100644 --- a/keel/web/api.py +++ b/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" diff --git a/keel/web/server.py b/keel/web/server.py index fbc9296..9169ce9 100644 --- a/keel/web/server.py +++ b/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) diff --git a/keel/web/static/js/render.js b/keel/web/static/js/render.js index c53ee21..9695f4b 100644 --- a/keel/web/static/js/render.js +++ b/keel/web/static/js/render.js @@ -1193,10 +1193,14 @@ export function timelineView(data, sort, onSort, onKind) { // The export, carrying the page's own scope and chip so the file matches the screen. const actions = el("p", "note"); const link = el("a", "chartaction", "Export CSV"); - link.setAttribute( - "href", - ["/api/timeline/export.csv?scope=", plain(data.scope), "&kind=", plain(data.kind)].join(""), - ); + // Encoded, like every other URL this client builds (`api.js` uses `searchParams`). `kind` is + // the server's echo of caller-supplied text, and a value carrying `&` or `#` would otherwise + // reshape the query rather than travel in it. Not reachable with hostile input today -- the + // params are in-memory and seeded from `data.kinds` -- so this is the convention, kept. + const target = new URL("/api/timeline/export.csv", window.location.origin); + target.searchParams.set("scope", plain(data.scope)); + target.searchParams.set("kind", plain(data.kind)); + link.setAttribute("href", target.pathname.concat(target.search)); link.setAttribute("download", ""); actions.append(link); actions.append(" — every row with its provenance; hashes are not recorded yet."); @@ -1207,7 +1211,10 @@ export function timelineView(data, sort, onSort, onKind) { table( "h-timeline", [ - { label: "when (UTC)", numeric: false, key: "ts" }, + // `at`, matching the payload and `sortable`. It was left as `ts` when the server side + // was renamed, and `headerCell` only draws a sort control for a key the server declares + // -- so the timestamp column of a CHRONOLOGY page silently became an unclickable label. + { label: "when (UTC)", numeric: false, key: "at" }, { label: "kind", numeric: false, key: "kind" }, { label: "how we know", numeric: false, key: "provenance" }, { label: "source", numeric: false, key: "source" }, diff --git a/tests/commands/test_timeline.py b/tests/commands/test_timeline.py index ea43e59..3d7dfb3 100644 --- a/tests/commands/test_timeline.py +++ b/tests/commands/test_timeline.py @@ -12,6 +12,8 @@ from __future__ import annotations +import csv +import io from decimal import Decimal from pathlib import Path from typing import Any @@ -97,14 +99,41 @@ def test_the_four_sources_merge_into_one_chronology(repo: Repository, tmp_path: def test_rows_are_newest_first(repo: Repository, tmp_path: Path) -> None: """One chronology, and the newest thing that happened is the thing an operator opened this - page to see.""" - _attestation(repo) # oldest - _transaction(repo) - _order(repo) # newest + page to see. + + The timestamps are SCRAMBLED relative to the order the sources are concatenated in + (`_order_rows`, then `_transaction_rows`, then `_attestation_rows`). The first version of + this test seeded oldest-to-newest, which happened to match that concatenation -- so deleting + the sort entirely left it green. Here the orders are the OLDEST and the attestation the + newest, so an unsorted merge comes back ascending and fails. + """ + _order(repo, created_at=NOW_TS - 10_000) + _order(repo, created_at=NOW_TS - 9_000) + _transaction(repo, ts=NOW_TS - 5_000) + _attestation(repo, attested_at=NOW_TS - 100) timestamps = [row.ts for row in gather_timeline(repo, now_ts=NOW_TS, scope="all").rows] - assert timestamps == sorted(timestamps, reverse=True) + assert timestamps == [NOW_TS - 100, NOW_TS - 5_000, NOW_TS - 9_000, NOW_TS - 10_000] + + +def test_two_events_at_one_instant_keep_a_stable_order(repo: Repository, tmp_path: Path) -> None: + """The tie-break. Without it two rows sharing a second come back in whatever order the merge + happened to produce, and the page reshuffles them between polls under a reader's cursor.""" + _order(repo, created_at=NOW_TS - 60) + _transaction(repo, ts=NOW_TS - 60) + _attestation(repo, attested_at=NOW_TS - 60) + + references = [row.reference for row in gather_timeline(repo, now_ts=NOW_TS, scope="all").rows] + + # The tie-break's CONTENT, not merely that two calls agree: `list.sort` is stable and the + # merge order deterministic, so a report with NO tie-break also returns the same list twice. + # Asserting repeatability alone passed against the missing tie-break. + assert references == sorted(references, reverse=True), ( + "at one instant, `reference` descending is the order -- and it is what makes the page " + "stop reshuffling between polls" + ) + assert len(set(references)) == 3, "three distinct events, not one collapsed row" def test_a_live_fill_is_venue_reported_and_a_paper_fill_is_not( @@ -276,3 +305,130 @@ def test_an_empty_book_is_an_empty_timeline(repo: Repository, tmp_path: Path) -> assert report.rows == () assert report.scoped_count == 0 + + +# -- every cell of the export is neutralised, not only the one with a test (#703 review) -------- + + +def test_every_text_column_of_the_export_is_neutralised(repo: Repository, tmp_path: Path) -> None: + """`csv_safe` is applied to all ten cells; before this, only `reference` was pinned. + + Removing it from the other nine left the whole suite green -- so the module's load-bearing + claim ("applied to EVERY text cell, not to a list of the risky ones") was untested for nine + columns, including `summary`, which carries an imported `notes` field verbatim. + + Every hostile value below lands at the START of its own cell, which is the only position a + spreadsheet evaluates. + """ + from keel.commands.timeline import to_csv + + # Hostile values in every cell whose content this module does NOT write: the reference, the + # summary's ingredients, and the amount. A fixture that leaves the rest keel-written pins + # three cells while the docstring claims ten -- which is how the previous version of this + # test passed while six columns were unprotected. + _order( + repo, + product_id="=cmd|product", + side="=cmd|side", + status="=cmd|status", + created_at=NOW_TS - 30, + ) + _transaction( + repo, + coinbase_id="=cmd|ref", + type="=cmd|kind", + asset="=cmd|asset", + notes="", + total=Decimal("-500.25"), + ) + + rows = list(csv.reader(io.StringIO(to_csv(gather_timeline(repo, now_ts=NOW_TS, scope="all"))))) + header = rows[0] + by_source = {r[header.index("source")]: dict(zip(header, r, strict=True)) for r in rows[1:]} + + order_cells = by_source["orders"] + assert order_cells["product_id"].startswith("'"), "product_id" + assert order_cells["summary"].startswith("'"), "summary -- it begins with the status" + + cells = by_source["transactions"] + assert cells["reference"].startswith("'"), "reference" + assert cells["summary"].startswith("'"), "summary -- it begins with the transaction type" + # A negative amount is a formula trigger and a real figure. Quoted, and still legible. + assert cells["amount"] == "'-500.25", cells["amount"] + # And nothing that was safe got mangled. + assert cells["kind"] == "flow" + assert cells["provenance"] == "imported-ledger" + + +def test_the_export_carries_one_row_per_event_plus_a_header( + repo: Repository, tmp_path: Path +) -> None: + """The shape an auditor's spreadsheet sees.""" + from keel.commands.timeline import to_csv + + _order(repo) + _transaction(repo) + _attestation(repo) + + rows = list(csv.reader(io.StringIO(to_csv(gather_timeline(repo, now_ts=NOW_TS, scope="all"))))) + + assert rows[0][0] == "ts" + assert len(rows) == 4 + + +# -- a log that could not be read is a STATED gap, not a failed page (#703 review round 2) ------ + + +@pytest.mark.parametrize("status", ["ok", "missing", "empty", "oversized", "unreadable"]) +def test_every_log_read_outcome_still_produces_a_report(status: str, repo, tmp_path) -> None: + """Four sources, and one of them having nothing to say must not take out the other three. + + The first fix for this raised on any status but `ok`/`missing` -- which made an EMPTY log + (an ordinary state: a freshly created handler, or the moment after a rotation) 500 the whole + Timeline page, losing orders, flows and attestations to report a non-problem. `read_log_window` + also returns `oversized` for one very long record, which is likewise not a read failure. + + The report carries the outcome instead, so the page and the CSV can SAY the log was + unreadable rather than either failing or silently under-reporting. + """ + _order(repo) + + report = gather_timeline(repo, now_ts=NOW_TS, scope="all", log_status=status) + + assert report.rows, "the other sources still report" + assert report.log_status == status + + +def test_a_healthy_log_reports_no_gap(repo, tmp_path) -> None: + _order(repo) + + assert gather_timeline(repo, now_ts=NOW_TS, scope="all", log_status="ok").log_gap is False + + +@pytest.mark.parametrize("status", ["empty", "oversized", "unreadable"]) +def test_an_unhealthy_log_is_reported_as_a_gap(status: str, repo, tmp_path) -> None: + """`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. The rest are: the file is there and its + contents did not reach this report, which is exactly what an auditor needs told.""" + _order(repo) + + assert gather_timeline(repo, now_ts=NOW_TS, scope="all", log_status=status).log_gap is True + + +def test_a_missing_log_is_not_a_gap(repo, tmp_path) -> None: + _order(repo) + + assert gather_timeline(repo, now_ts=NOW_TS, scope="all", log_status="missing").log_gap is False + + +def test_the_kind_collapse_is_applied_and_echoed(repo, tmp_path) -> None: + """An unrecognised kind is collapsed to "every kind", not applied -- `?kind=trades` (the + plural typo, since the chips read "trade") would otherwise return a page that looks like an + empty deployment. Unpinned until now: reverting the collapse left every test green.""" + _order(repo) + _transaction(repo) + + report = gather_timeline(repo, now_ts=NOW_TS, scope="all", kind="trades") + + assert report.kind == "", "the applied value is echoed, so the substitution is visible" + assert report.shown_count == 2, "and nothing was filtered out" diff --git a/tests/commands/test_timeline_csv.py b/tests/commands/test_timeline_csv.py index 44fd72f..ae7c7f8 100644 --- a/tests/commands/test_timeline_csv.py +++ b/tests/commands/test_timeline_csv.py @@ -54,6 +54,24 @@ def test_ordinary_text_is_left_exactly_as_it_is(ordinary: str) -> None: assert csv_safe(ordinary) == ordinary +@pytest.mark.parametrize( + "dangerous", + [" =SUM(A1:A10)", " @malicious", " -1+1"], +) +def test_leading_whitespace_does_not_smuggle_a_formula_past(dangerous: str) -> None: + """A strict first-character test is defeated by one space, and `" =cmd|..."` is a legal + `coinbase_id` out of an imported venue CSV that lands in a cell by itself. Google Sheets and + LibreOffice trim leading whitespace before deciding whether a cell is a formula. + + The ORIGINAL text is what gets quoted: an audit record must not have its cells silently + reformatted, only made inert. + """ + escaped = csv_safe(dangerous) + + assert escaped.startswith("'"), f"{dangerous!r} slipped past the trigger check" + assert escaped[1:] == dangerous, "the original text, unaltered, after the quote" + + def test_a_negative_number_is_still_neutralised_and_still_readable() -> None: """`-12.30` is a formula trigger AND a real figure this export carries. Quoting it is the correct trade: a spreadsheet shows `-12.30` as text rather than evaluating it, and the value diff --git a/tests/web/test_api.py b/tests/web/test_api.py index 1085033..0fe25ee 100644 --- a/tests/web/test_api.py +++ b/tests/web/test_api.py @@ -531,12 +531,20 @@ def test_every_declared_sort_column_is_a_column_the_rows_actually_have( and then order every row identically -- an accepted request that silently does nothing, which is exactly what refusing an unknown column exists to prevent. - Checked over the two endpoints this test can seed rows into. A collection with no rows proves - nothing here, which is why the seeding is not optional.""" + Checked over every endpoint this test can seed rows into. A collection with no rows proves + nothing here, which is why the seeding is not optional. + + `/api/timeline` (#703) joined this list after shipping with `sortable=("ts", ...)` while its + payload emits `at` -- accepted, echoed back as applied, and ordering nothing. That is the + exact rot this pin exists for, and it went unnoticed because the route was not in it.""" _seed_positions(running.db_path, (("BTC-USD", "0.01", "50000"),)) _seed_rules(running.db_path, ("breakout",)) - for path, collection in (("/api/status", "open_positions"), ("/api/rules", "rules")): + for path, collection in ( + ("/api/status", "open_positions"), + ("/api/rules", "rules"), + ("/api/timeline", "rows"), + ): _status, _headers, document = _json(running, path) rows = document["data"][collection] diff --git a/tests/web/test_client_assets.py b/tests/web/test_client_assets.py index 907bd97..dfa4ad4 100644 --- a/tests/web/test_client_assets.py +++ b/tests/web/test_client_assets.py @@ -1523,6 +1523,7 @@ def test_every_table_emits_one_cell_per_declared_header() -> None: "Object", "Set", "String", + "URL", "console", "document", "window", diff --git a/tests/web/test_timeline_export.py b/tests/web/test_timeline_export.py index 6f75023..2469f5f 100644 --- a/tests/web/test_timeline_export.py +++ b/tests/web/test_timeline_export.py @@ -137,3 +137,112 @@ def test_a_negative_amount_is_inert_and_still_legible(tmp_path: Path) -> None: from keel.commands.timeline import csv_safe assert csv_safe("-500.25") == "'-500.25" + + +# -- the export answers like every other route when it cannot (#703 review) --------------------- + + +def test_a_query_parameter_the_export_does_not_read_is_harmless(running: Any) -> None: # noqa: F811 + """`?limit=` belongs to the paged JSON route. The export deliberately does not read it -- it + carries the whole scope -- so a value that would be refused there is simply not consulted + here, and the file still comes back.""" + status, headers, _body = _get(running, EXPORT + "?limit=abc", cookie=_session(running)) + + assert status == 200 + assert headers["Content-Type"] == "text/csv; charset=utf-8" + + +def test_an_export_that_raises_answers_instead_of_dropping_the_connection( + running: Any, # noqa: F811 + monkeypatch: Any, +) -> None: + """`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. The CSV branch does not go + through it, so before this it propagated -- the client saw a reset connection with no + response at all, and a traceback of absolute source paths reached the stderr `log_message` is + overridden to keep quiet. + + A JSON envelope is the right answer even from a route whose success case is CSV: the failure + is not a file, and a browser handed a truncated download learns nothing. + """ + from keel.web import api as web_api + + def boom(*_args: Any, **_kwargs: Any) -> tuple[str, str]: + raise RuntimeError("the log is on fire") + + monkeypatch.setattr(web_api, "export_timeline_csv", boom) + + status, headers, body = _get(running, EXPORT, cookie=_session(running)) + + assert status == 500, "a failed export must still answer" + assert headers["Content-Type"].startswith("application/json") + assert "the log is on fire" in body + + +def test_head_returns_no_body(running: Any) -> None: # noqa: F811 + """`_send`, `_send_json` and `_serve_static` all guard the write with + `if self.command != "HEAD"`. This sender did not, and `do_HEAD` delegates to `do_GET` -- so a + HEAD returned the headers plus the whole CSV. On a keep-alive connection those bytes are + framed as the next response: a same-origin response desync, and a violation of RFC 9110. + + Read off a RAW SOCKET, not through `http.client`: that library knows a HEAD carries no body + and never reads one, so it reports an empty body whether or not the server sent bytes. A test + written through it passes against the bug -- which is what the first version of this test did. + """ + import socket + + request = ( + f"HEAD {EXPORT} HTTP/1.1\r\n" + f"Host: {running.host}:{running.port}\r\n" + f"Cookie: {_session(running)}\r\n" + "Connection: close\r\n\r\n" + ) + with socket.create_connection((running.host, running.port), timeout=10) as sock: + sock.sendall(request.encode("ascii")) + raw = b"" + while chunk := sock.recv(4096): + raw += chunk + + head, _, body = raw.partition(b"\r\n\r\n") + assert b"text/csv" in head, "the headers still describe the resource" + assert body == b"", f"a HEAD must send no body; got {len(body)} bytes" + + +def test_the_export_carries_every_row_in_scope_not_the_pages_worth(tmp_path: Path) -> None: + """The page is capped because it polls every 15 seconds. The export is a deliberate download + of an audit record, and inheriting that cap made it a PARTIAL record that reads as complete + -- 200 rows of a 5,000-event deployment, with nothing in the file saying so, handed to a tax + preparer. + + Seeded above `MAX_TIMELINE_LIMIT`, not merely above the paged default. The first version of + this test used `DEFAULT_TIMELINE_LIMIT + 25` = 225 rows and passed while the export was still + capped at 2000: `export_rows` handed a huge `limit` to `gather_timeline`, which clamps it with + `min(limit, MAX_TIMELINE_LIMIT)`. A test whose fixture sits under the real cap cannot see the + cap -- which is the same failure this PR exists to fix, committed inside the fix. + """ + from keel.commands.timeline import MAX_TIMELINE_LIMIT, export_rows, to_csv + + conn = connect(str(tmp_path / "keel.db")) + migrate(conn) + repo = Repository(conn) + total = MAX_TIMELINE_LIMIT + 25 + for index in range(total): + repo.upsert_transaction( + { + "coinbase_id": f"cb-{index}", + "source": "coinbase", + "type": "deposit", + "asset": "USD", + "ts": 1_800_000_000 - index * 60, + "qty": Decimal("1"), + "total": Decimal("1"), + "notes": "", + } + ) + + text = to_csv(export_rows(repo, now_ts=1_800_000_000, scope="all")) + data_rows = list(csv.reader(io.StringIO(text)))[1:] + + assert len(data_rows) == total, ( + f"the export must carry the whole scope; got {len(data_rows)} of {total}" + )