From f47952b2eee71787f936a3a35ab9ed8fa2fe7f42 Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Thu, 6 Aug 2026 18:57:38 -0400 Subject: [PATCH 1/4] fix(agent): gate entries on a confirmed trading bar, not just a polled feed Anchoring the live detector to 01:20 UTC (#172) cut ~13h of lag, but it also cut the data-publication margin from ~13 hours to 20 minutes -- and nothing measured whether the bar the rule decides on had actually arrived. THE BUG. `turtle_breakout._completed_days` withholds the just-closed daily bar until the 00:00-01:00 UTC hourly bar has closed. At 01:20 UTC on UTC date X, verified against the real function: both series current -> effective newest daily bar = X-1 (correct) ONE_HOUR one bar late -> effective newest daily bar = X-2 (REGRESSED) ONE_DAY not yet stored -> effective newest daily bar = X-2 (REGRESSED) X-2 is the bar YESTERDAY's 01:20 UTC cycle already evaluated. So a late candle makes the cycle re-enter a bar it has already traded. Nothing on the live path dedupes an ENTRY -- `get_open_positions` gates exits/reconcile/status but never entry, the `signals` table is never read back, `client_order_id` is a fresh uuid4, and the rails are DOLLAR caps, not per-day counters -- so that re-evaluation is a DUPLICATE REAL-MONEY ORDER, not a delayed one. At the old 13:05 UTC schedule even twelve hours of hourly lag was harmless; at 01:20 UTC one bar is not. WHY NOTHING CAUGHT IT. `market_feed.poll_once` writes nothing and raises nothing when the venue has no new bar. `run_once` sets `last_feed_ts = now_ts` unconditionally, so rail 12 -- which measures whether the POLLER ran, not whether DATA ARRIVED -- is blind to it. And `market_feed.is_fresh` is measured against the FINEST configured granularity (FIFTEEN_MINUTE live), never against ONE_DAY. The cycle exited 0, the runner stamped the day, and there was no retry. THE FIX. `data/freshness.py` already had `expected_last_ts` and the `bars_behind` arithmetic but had zero references from `agent.py`, `execution/` or `strategy/`. New `entry_bar_ready()` uses them: the gated series must be `bars_behind == 0`, AND every FINER configured series must have advanced past that bar's CLOSE. That second condition is `_completed_days`'s own condition stated generically, so the gate cannot read "ready" while `_completed_days` would still withhold the bar -- and it is no stricter than it has to be, since it only asks that the finer series crossed the boundary, not that it is at its own newest bar (an hourly series five bars late at 14:20 UTC still confirms fine). Deliberately NOT reusing `assess()`/`DEFAULT_TOLERANCE_BARS`: that two-bar tolerance exists so an operator-facing staleness ALERT does not fire on the normal forming-bar lag. A one-bar-late hourly series is precisely the condition that duplicates an order, and the alert tolerance would wave it through. ENTRIES ONLY. Exits still run for every rule, unfiltered: an open position's rule-driven channel exit runs in-process (the protective stop rests at the broker, the channel exit does not), and holding a losing position an extra cycle is strictly worse than a delayed entry. WHY NOT FIX RAIL 12 INSTEAD. Rail 12's threshold is `interval_sec * 3`, and it answers "did the poller run". Making `last_feed_ts` advance only on new data would, in a once-daily deployment, leave it ~24h stale every single cycle and veto everything. Rail 12 is also a per-ORDER veto: it yields `placed=False` and a ZERO exit, so the runner would still stamp the day and the fresh bar would never be evaluated at all -- trading a duplicate order for a silently missed day. The gate therefore lives in `run_once`, where it can fail the CYCLE. Single-cycle `keel agent` now exits `DATA_NOT_READY_EXIT` (4) when an entry was withheld, so `keel-live-run.sh` declines to stamp and one of the remaining 23 hourly triggers retries an hour later -- converting "duplicate order" into "<= 60 minutes of delay". `--loop` is deliberately unchanged: it skips the cycle and tries again next interval. `_entry_gate_granularity` falls back to the COARSEST configured granularity, diverging from `engine._trading_granularity`'s finest-fallback on purpose: `Dca` declares no timeframe yet reads `candles_by_tf[ONE_DAY]` directly and keys its cadence off that bar's timestamp, so gating it on FIFTEEN_MINUTE would miss the same hazard entirely. Co-Authored-By: Claude Opus 5 (1M context) --- keel/agent.py | 115 ++++++++++++- keel/cli.py | 26 ++- keel/data/freshness.py | 146 ++++++++++++++++- tests/data/test_freshness.py | 156 +++++++++++++++++- tests/test_agent.py | 306 +++++++++++++++++++++++++++++++++++ tests/test_cli.py | 105 ++++++++++++ 6 files changed, 847 insertions(+), 7 deletions(-) diff --git a/keel/agent.py b/keel/agent.py index 5250c876..fca661eb 100644 --- a/keel/agent.py +++ b/keel/agent.py @@ -62,7 +62,7 @@ from keel_core.telemetry import bind_cycle, log_event, new_cycle_id, unbind_cycle from keel.config import Config -from keel.data import market_feed +from keel.data import freshness, market_feed from keel.data.repository import Repository from keel.execution import equity as equity_mod from keel.execution import executor, guards, reconcile, streak @@ -79,6 +79,17 @@ logger = logging.getLogger(__name__) +#: `keel agent` (single-cycle, non-`--loop`) exits with this status when `run_once` blocked at +#: least one entry on `freshness.entry_bar_ready` (Finding 1, HIGH: a re-evaluated daily bar is +#: a DUPLICATE REAL-MONEY ORDER, not a delayed one -- see `_entry_gate_granularity`/`run_once` +#: below). `keel-live-run.sh` only stamps the UTC day as done on a ZERO exit, so this nonzero +#: exit makes the runner decline to stamp, and one of the remaining 23 hourly LaunchAgent +#: triggers retries an hour later -- converting "duplicate order" into "<= 60 minutes of delay". +#: The `--loop` path never uses this (see `agent_cmd` in `keel/cli.py`): a long-running loop +#: just skips the blocked cycle and tries again next interval: exiting the process would kill a +#: healthy long-running loop over what is usually a transient publication lag. +DATA_NOT_READY_EXIT = 4 + # -- rule reconstruction: DB row (kind, JSON-plain params) -> a real Rule instance ------------- RULE_REGISTRY: dict[str, type[Rule]] = { @@ -167,6 +178,53 @@ def _finest_granularity(granularities: list[Granularity]) -> Granularity | None: return min(granularities, key=lambda g: _GRANULARITY_ORDER.get(g, 0)) +def _entry_gate_granularity(rule: Rule, granularities: list[Granularity]) -> Granularity | None: + """Which granularity's freshness should gate `rule`'s ENTRIES (Finding 1, HIGH)? + + A rule that DECLARES its trading timeframe (`self.granularity` on `TurtleBreakout`/ + `PullbackContinuation`, `self.timeframe` on `RsiMeanReversion`) is gated on exactly that -- + the same attribute `strategy.engine._trading_granularity` reads. + + Absent a declaration, this falls back to the COARSEST configured granularity -- the ONE + place this deliberately diverges from `_trading_granularity`'s own fallback, which picks the + FINEST. That divergence is not an oversight: `Dca` (`strategy/rules/dca.py`) declares + neither attribute, yet `Dca.detect` reads `candles_by_tf[Granularity.ONE_DAY]` directly and + keys its cadence off `latest.ts // 86400 % cadence_days`, so a STALE daily bar re-fires the + same cadence hit and buys twice. Falling back to the finest configured granularity (as + `_trading_granularity` does, correctly, for its own job of picking CTS *scoring* data) would + gate DCA on FIFTEEN_MINUTE and miss that hazard entirely -- the daily bar could be weeks + stale while FIFTEEN_MINUTE stayed perfectly fresh. The coarsest granularity is the fallback + that fails in the safe direction for any rule that does not tell us what it actually reads: + it is the input most likely to be what a rule silent about its timeframe is keying off, per + this codebase's rules so far. + + Returns `None` only when `granularities` itself is empty -- nothing to gate on at all. + """ + for attr in ("granularity", "timeframe"): + value = getattr(rule, attr, None) + if isinstance(value, Granularity): + return value + if not granularities: + return None + return max(granularities, key=lambda g: _GRANULARITY_ORDER.get(g, 0)) + + +@dataclass(frozen=True) +class BlockedEntry: + """One rule's entry, withheld this cycle because its gating bar was not confirmed ready -- + see `freshness.entry_bar_ready` and the gate in `run_once` below. Recorded on `LoopResult` + so a caller (the CLI, a log line, a test) can say exactly which bar was missing without + re-deriving it. + """ + + product: str + rule_name: str + granularity: Granularity + expected_ts: int + stored_ts: int | None + reason: str + + # -- held-position reconstruction (mirrors execution.executor._held_position) ----------------- @@ -655,6 +713,10 @@ class LoopResult: enter_signals: list[Signal] = field(default_factory=list) enter_results: list[ExecutionResult] = field(default_factory=list) exit_results: list[ExecutionResult] = field(default_factory=list) + # Finding 1 (HIGH): rules whose entry this cycle withheld because their gating bar wasn't + # confirmed ready (`freshness.entry_bar_ready`, applied in `run_once` below) -- see + # `BlockedEntry`. Defaulted so every existing `LoopResult(...)` construction stays valid. + blocked_entries: list[BlockedEntry] = field(default_factory=list) # Paper-forward observability (P4 Task 9): the synthetic account's equity + Rail 11's # drawdown scalars for THIS cycle. `None` in every non-paper cycle -- there is no synthetic # account to report on -- so all existing `LoopResult(...)` constructions stay valid. @@ -758,6 +820,7 @@ def run_once( enter_results: list[ExecutionResult] = [] exit_results: list[ExecutionResult] = [] stale_products: list[str] = [] + blocked_entries: list[BlockedEntry] = [] # Reconcile FIRST, before equity and before any entry. A bracket that filled since the # last cycle has already changed the position and the cash balance; reading equity or @@ -885,7 +948,54 @@ def run_once( ) exit_results.extend(product_exit_results) - product_signals = engine.evaluate(product_rules, candles_by_tf, repo=repo) + # Finding 1 (HIGH), ENTRIES ONLY. EXITS above already ran for every rule regardless + # of this gate: an open position's rule-driven channel exit runs IN-PROCESS (the + # protective stop rests at the broker, but the channel exit does not), so it must + # never be held hostage by a stale feed -- staying in a losing position an extra + # cycle is strictly worse than a delayed entry. ENTRIES are different: nothing else + # on the live path dedupes one (see this module's docstring), so re-evaluating a bar + # already traded is a DUPLICATE REAL-MONEY ORDER, not a delayed one. Applied in + # EVERY mode, live and paper alike -- paper is the rehearsal for live (`candidate -> + # paper -> live`), and paper's own dedupe (`PaperTrader`) only refuses a second entry + # while the product is ALREADY OPEN; it does not stop a re-evaluated bar re-entering + # after a flat close. `strategy/backtest.py` and `sim/portfolio_sim.py` never call + # `run_once` at all, so neither is affected by this gate. + ready_rules: list[Rule] = [] + for rule in product_rules: + gate_gran = _entry_gate_granularity(rule, granularities) + if gate_gran is None: + ready_rules.append(rule) + continue + readiness = freshness.entry_bar_ready(candles_by_tf, gate_gran, now_ts) + if readiness.ready: + ready_rules.append(rule) + continue + log_event( + logger, + logging.WARNING, + "agent.entry_bar_not_ready", + product=product_id, + rule=rule.name, + granularity=gate_gran.value, + expected_ts=readiness.expected_ts, + stored_ts=readiness.stored_ts, + bars_behind=readiness.bars_behind, + reason=readiness.reason, + blocked_by=None if readiness.blocked_by is None else readiness.blocked_by.value, + blocked_by_ts=readiness.blocked_by_ts, + ) + blocked_entries.append( + BlockedEntry( + product=product_id, + rule_name=rule.name, + granularity=gate_gran, + expected_ts=readiness.expected_ts, + stored_ts=readiness.stored_ts, + reason=readiness.reason or "unknown", + ) + ) + + product_signals = engine.evaluate(ready_rules, candles_by_tf, repo=repo) log_event( logger, logging.INFO, @@ -958,6 +1068,7 @@ def run_once( enter_signals=enter_signals, enter_results=enter_results, exit_results=exit_results, + blocked_entries=blocked_entries, paper_equity=result_paper_equity, drawdown_total_pct=result_drawdown_total_pct, drawdown_weekly_pct=result_drawdown_weekly_pct, diff --git a/keel/cli.py b/keel/cli.py index 6816c0fe..003d93e2 100644 --- a/keel/cli.py +++ b/keel/cli.py @@ -1130,7 +1130,8 @@ def _print_loop_result(result: agent.LoopResult) -> None: click.echo( f"[{result.ts}] mode={result.mode} polled={result.polled} " f"products={result.products} stale={result.stale_products} " - f"signals={len(result.enter_signals)} entered={entered} exited={exited}" + f"signals={len(result.enter_signals)} blocked={len(result.blocked_entries)} " + f"entered={entered} exited={exited}" ) if result.paper_equity is not None: click.echo( @@ -1176,9 +1177,22 @@ def agent_cmd( if not loop: confirm_fn = _interactive_confirm - _print_loop_result( - agent.run_once(broker, repo, config, now_ts=int(time.time()), confirm_fn=confirm_fn) + result = agent.run_once( + broker, repo, config, now_ts=int(time.time()), confirm_fn=confirm_fn ) + _print_loop_result(result) + if result.blocked_entries: + # Finding 1 (HIGH): a green exit here is exactly what lets a cron/LaunchAgent + # wrapper stamp the day as done and never retry -- see `agent.DATA_NOT_READY_EXIT`'s + # docstring for the mechanism this closes (duplicate order -> bounded delay). + for blocked in result.blocked_entries: + click.echo( + f"blocked: {blocked.rule_name} on {blocked.product} needs a confirmed " + f"{blocked.granularity.value} bar at {blocked.expected_ts} " + f"(have {blocked.stored_ts}, reason={blocked.reason})", + err=True, + ) + ctx.exit(agent.DATA_NOT_READY_EXIT) return interval = interval_sec if interval_sec is not None else config.auto_trade.interval_sec @@ -1189,6 +1203,12 @@ def stop_flag(_count: list[int] = [0]) -> bool: # noqa: B006 - intentional muta _count[0] += 1 return False + # Deliberately NO `ctx.exit(agent.DATA_NOT_READY_EXIT)` here, unlike the non-`--loop` branch + # above: a long-running loop process is supposed to skip a blocked cycle and try again next + # `interval`, exactly like it already does for a stale feed or the kill-switch -- exiting + # the process would take the whole scheduled loop down over what is usually a transient + # publication lag, and `agent.loop` has no supervisor watching for this exit code to restart + # it. `_print_loop_result`'s `blocked=N` token still surfaces it for whoever reads the log. confirm_fn = _interactive_confirm for result in agent.loop(broker, repo, config, interval, stop_flag, confirm_fn=confirm_fn): _print_loop_result(result) diff --git a/keel/data/freshness.py b/keel/data/freshness.py index ba6ba8c6..bdcbfd27 100644 --- a/keel/data/freshness.py +++ b/keel/data/freshness.py @@ -14,10 +14,11 @@ from __future__ import annotations +from collections.abc import Mapping, Sequence from dataclasses import dataclass from keel.data.history import GRANULARITY_SECONDS, CoverageInfo -from keel.types import Granularity +from keel.types import Candle, Granularity #: Bars of lag tolerated before a series is called stale. See the module docstring: one bar is #: the normal forming-bar lag, two absorbs a fetch straddling a bar boundary. @@ -93,6 +94,149 @@ def assess( ) +@dataclass(frozen=True) +class BarReadiness: + """Is the bar `keel.agent`'s entry gate needs to trade on ACTUALLY DONE -- not merely + cached, but confirmed closed by a finer series? + + This is a different question from `Freshness.stale`, and deliberately does not reuse + `assess()`/`DEFAULT_TOLERANCE_BARS`: that tolerance exists so an operator-facing staleness + ALERT does not fire on the normal forming-bar lag (see the module docstring). An ENTRY GATE + on real money needs `bars_behind == 0` -- a 1-bar-late hourly series is exactly the condition + that produces a duplicate real-money order (see `entry_bar_ready`'s docstring), and the + alert tolerance would wave it through. + """ + + granularity: Granularity + expected_ts: int + stored_ts: int | None + #: `-1` when nothing is stored at all, matching `Freshness.bars_behind`'s "unknown" sentinel. + bars_behind: int + #: The blocking FINER-than-`granularity` series that failed to confirm the close, or `None` + #: if nothing blocked (either everything confirmed, or `granularity` itself was + #: missing/behind and confirmation was never reached). When several finer series fail, this + #: names the COARSEST of them -- see `entry_bar_ready`'s docstring for why. + blocked_by: Granularity | None + blocked_by_ts: int | None + ready: bool + #: `"missing" | "behind" | "unconfirmed" | None` (the last only when `ready`). + reason: str | None + + +def entry_bar_ready( + candles_by_tf: Mapping[Granularity, Sequence[Candle]], + granularity: Granularity, + now_ts: int, +) -> BarReadiness: + """Is the newest `granularity` bar in `candles_by_tf` both CACHED and CONFIRMED CLOSED -- + safe for `keel.agent` to gate a real-money ENTRY on? + + **Why this exists (Finding 1, HIGH).** The live LaunchAgent fires at :20 past every UTC + hour; the runner gates on UTC hour >= 1, so the first eligible trigger is 01:20 UTC. + `turtle_breakout.py::_completed_days` withholds the just-closed ONE_DAY bar until the + 00:00-01:00 UTC ONE_HOUR bar has closed at 01:00 UTC -- normally a 20-minute margin. If the + ONE_HOUR series is even one bar late (a common publication lag), `_completed_days` withholds + ONE MORE daily bar than it should and the rule re-evaluates a bar it already traded + yesterday. Nothing else on the live path dedupes an ENTRY (see `keel/agent.py`'s module + docstring), so that re-evaluation is a DUPLICATE REAL-MONEY ORDER, not a delayed one. + + **The confirmation condition is `_completed_days`'s own condition, generalized.** At 01:20 + UTC, `expected_ts` for ONE_DAY is day X-1's 00:00, and `expected_ts + step` is day X's + 00:00 -- precisely the ts of the 00:00-01:00 UTC hourly bar `_completed_days` waits for. So + requiring every FINER configured series to have a newest ts `>= expected_ts + step` is + exactly `_completed_days`'s own wait, stated generically over whatever finer series the + agent happens to poll (today ONE_HOUR; a future FIFTEEN_MINUTE-only deployment would confirm + against that instead). It is therefore STRICTLY STRONGER than `_completed_days` -- it cannot + read "ready" while `_completed_days` would still withhold the bar. + + **It is NOT over-strict.** The confirmation only demands that the finer series has crossed + the boundary -- not that the finer series is itself at its own newest expected bar. At 14:20 + UTC an hourly series five bars behind ITS OWN expectation still confirms the daily bar fine, + because it crossed the boundary hours ago. A `bars_behind == 0` requirement on ONE_HOUR (or + FIFTEEN_MINUTE) would have been far too strict -- the 01:20 trigger gives only 5 minutes of + margin on a 15-minute bar -- and would block entries routinely rather than only in the + narrow post-midnight window this predicate targets. + + Order of checks, each short-circuiting the next: + 1. `stored_ts is None` (the key is absent, or the series is empty) -> `"missing"`. + 2. `bars_behind = max(0, (expected_ts - stored_ts) // step)`; `> 0` -> `"behind"`. The + floor division is deliberately forgiving of a series whose bars are not aligned to the + granularity boundary -- see `assess()`'s identical arithmetic; many existing callers + build such series and a bar less than one full step behind is not "behind". + 3. Otherwise, every granularity `g` present in `candles_by_tf` with + `GRANULARITY_SECONDS[g] < step` must have a newest stored ts `>= expected_ts + step`. + A present-but-empty finer series fails this exactly like a late one -- there is nothing + to confirm against. When several finer series fail, the COARSEST of them is reported + (deterministic: same inputs always name the same blocker, so an operator's alert + doesn't flap between messages across identical cycles). + """ + gran = Granularity(granularity) + step = GRANULARITY_SECONDS[gran] + expected_ts = expected_last_ts(now_ts, gran) + + series = candles_by_tf.get(gran) + stored_ts = series[-1].ts if series else None + + if stored_ts is None: + return BarReadiness( + granularity=gran, + expected_ts=expected_ts, + stored_ts=None, + bars_behind=-1, + blocked_by=None, + blocked_by_ts=None, + ready=False, + reason="missing", + ) + + bars_behind = max(0, (expected_ts - stored_ts) // step) + if bars_behind > 0: + return BarReadiness( + granularity=gran, + expected_ts=expected_ts, + stored_ts=stored_ts, + bars_behind=bars_behind, + blocked_by=None, + blocked_by_ts=None, + ready=False, + reason="behind", + ) + + close_ts = expected_ts + step + blockers: list[tuple[Granularity, int | None]] = [] + for g, candles in candles_by_tf.items(): + g = Granularity(g) + if GRANULARITY_SECONDS[g] >= step: + continue # not FINER than `granularity` -- nothing to confirm against here + newest = candles[-1].ts if candles else None + if newest is None or newest < close_ts: + blockers.append((g, newest)) + + if blockers: + blocker_gran, blocker_ts = max(blockers, key=lambda item: GRANULARITY_SECONDS[item[0]]) + return BarReadiness( + granularity=gran, + expected_ts=expected_ts, + stored_ts=stored_ts, + bars_behind=0, + blocked_by=blocker_gran, + blocked_by_ts=blocker_ts, + ready=False, + reason="unconfirmed", + ) + + return BarReadiness( + granularity=gran, + expected_ts=expected_ts, + stored_ts=stored_ts, + bars_behind=0, + blocked_by=None, + blocked_by_ts=None, + ready=True, + reason=None, + ) + + def any_needs_fetch(items: list[Freshness]) -> bool: """Any series a fetch could actually help. See `Freshness.needs_fetch`.""" return any(item.needs_fetch for item in items) diff --git a/tests/data/test_freshness.py b/tests/data/test_freshness.py index 4c1f261e..e535e49e 100644 --- a/tests/data/test_freshness.py +++ b/tests/data/test_freshness.py @@ -2,16 +2,20 @@ from __future__ import annotations +from decimal import Decimal + from keel.data.freshness import ( DEFAULT_TOLERANCE_BARS, + BarReadiness, Freshness, any_gaps, any_needs_fetch, assess, + entry_bar_ready, expected_last_ts, ) from keel.data.history import CoverageInfo -from keel.types import Granularity +from keel.types import Candle, Granularity _DAY = 86400 _HOUR = 3600 @@ -32,6 +36,11 @@ def _info(last_ts, *, n=100, gaps=0, granularity=Granularity.ONE_DAY, product="B ) +def _candle(ts: int, price: str = "100") -> Candle: + p = Decimal(price) + return Candle(ts=ts, open=p, high=p, low=p, close=p, volume=Decimal("1")) + + def test_expected_last_ts_is_the_bar_below_the_forming_one(): """At exactly midnight, the day bar stamped today is forming; yesterday's is the newest complete one.""" @@ -131,3 +140,148 @@ def test_any_needs_fetch_and_any_gaps_are_independent(): def test_freshness_is_frozen(): result = assess(_info(_NOW - _DAY), _NOW) assert isinstance(result, Freshness) + + +# -- entry_bar_ready (the real-money entry gate; see keel/agent.py's wiring) ------------------- +# +# This is deliberately a SEPARATE predicate from `assess`/`DEFAULT_TOLERANCE_BARS` -- that +# tolerance exists so an operator-facing staleness ALERT does not fire on the normal +# forming-bar lag. An entry gate on real money needs `bars_behind == 0`: a 1-bar-late hourly +# series is exactly the condition that produces a duplicate order (Finding 1), and the alert +# tolerance would wave it through. +# +# All the "01:20 UTC" scenarios below use `_NOW` as UTC day X's 00:00 -- so `_NOW + _HOUR + +# 20*60` is X's 01:20, matching the live LaunchAgent's first eligible trigger. + +_AT_0120 = _NOW + _HOUR + 20 * 60 # UTC day X, 01:20 -- the first live trigger of the day. +_AT_1420 = _NOW + 14 * _HOUR + 20 * 60 # UTC day X, 14:20 -- well into the trading day. + +# The ts `_completed_days` (turtle_breakout.py) waits for: the 00:00-01:00 UTC hourly bar's +# OPEN ts. At `_AT_0120`, `expected_last_ts(ONE_DAY)` is `_NOW - _DAY` (day X-1's bar) and +# `expected_ts + step` is `_NOW` (day X 00:00) -- exactly this. +_DAY_CLOSE_HOURLY_TS = _NOW + + +def test_entry_bar_ready_missing_when_nothing_stored(): + """No cached bar at all for the gated granularity -- there is nothing to confirm, so this + must never read as "ready". Mirrors `assess`'s `missing`/`bars_behind=-1` convention. + """ + result = entry_bar_ready({}, Granularity.ONE_DAY, _AT_0120) + assert result.ready is False + assert result.reason == "missing" + assert result.bars_behind == -1 + assert result.stored_ts is None + + # An explicitly-empty list reads the same as an absent key. + empty = entry_bar_ready({Granularity.ONE_DAY: []}, Granularity.ONE_DAY, _AT_0120) + assert empty.ready is False + assert empty.reason == "missing" + + +def test_entry_bar_ready_behind_when_the_gated_series_itself_lags(): + """The gated granularity's own bar is stale (bars_behind > 0) -- e.g. the daily fetch + itself hasn't run yet. This must block regardless of any finer series' state; `_completed_days` + would return an empty/short series in the equivalent live scenario. + """ + candles_by_tf = {Granularity.ONE_DAY: [_candle(_NOW - 2 * _DAY)]} # X-2: one bar behind + result = entry_bar_ready(candles_by_tf, Granularity.ONE_DAY, _AT_0120) + assert result.ready is False + assert result.reason == "behind" + assert result.bars_behind == 1 + + +def test_entry_bar_ready_unconfirmed_when_the_finer_series_has_not_crossed_the_close(): + """THE REGRESSION CASE. At 01:20 UTC, `_completed_days` withholds the just-closed daily bar + until the 00:00-01:00 UTC hourly bar has closed -- i.e. until an hourly bar stamped `_NOW` + (day X 00:00) exists. A one-bar-late hourly series (newest stamped `_NOW - _HOUR`, the + PRIOR day's last hour) has not crossed that boundary: `_completed_days` would drop an extra + daily bar and the rule would re-evaluate a bar already traded (Finding 1's duplicate order). + This predicate must call that exact condition "not ready". + """ + candles_by_tf = { + Granularity.ONE_DAY: [_candle(_NOW - _DAY)], # X-1: current, NOT itself behind + Granularity.ONE_HOUR: [_candle(_NOW - _HOUR)], # one hour short of the day close + } + result = entry_bar_ready(candles_by_tf, Granularity.ONE_DAY, _AT_0120) + assert result.ready is False + assert result.reason == "unconfirmed" + assert result.bars_behind == 0 # the daily bar itself is current -- the hourly is what blocks + assert result.blocked_by == Granularity.ONE_HOUR + assert result.blocked_by_ts == _NOW - _HOUR + + +def test_entry_bar_ready_unconfirmed_when_the_finer_series_is_present_but_empty(): + """A configured-but-empty finer series (e.g. the very first poll) must block exactly like a + late one -- there is nothing to confirm the daily bar closed against.""" + candles_by_tf = { + Granularity.ONE_DAY: [_candle(_NOW - _DAY)], + Granularity.ONE_HOUR: [], + } + result = entry_bar_ready(candles_by_tf, Granularity.ONE_DAY, _AT_0120) + assert result.ready is False + assert result.reason == "unconfirmed" + assert result.blocked_by == Granularity.ONE_HOUR + assert result.blocked_by_ts is None + + +def test_entry_bar_ready_when_the_finer_series_has_crossed_the_day_close(): + """The positive case this exists to unblock: the 00:00-01:00 UTC hourly bar (ts == `_NOW`) + has closed, so the daily bar it confirms is genuinely done -- this is `_completed_days`'s own + condition, generalized, and it must pass the instant that condition would.""" + candles_by_tf = { + Granularity.ONE_DAY: [_candle(_NOW - _DAY)], + Granularity.ONE_HOUR: [_candle(_DAY_CLOSE_HOURLY_TS)], + } + result = entry_bar_ready(candles_by_tf, Granularity.ONE_DAY, _AT_0120) + assert result.ready is True + assert result.reason is None + assert result.blocked_by is None + + +def test_entry_bar_ready_with_no_finer_series_configured_is_ready(): + """A config that only ever polls `ONE_DAY` (no hourly key at all) has nothing to confirm + against -- the gate must not invent a requirement the deployment never asked for.""" + candles_by_tf = {Granularity.ONE_DAY: [_candle(_NOW - _DAY)]} + result = entry_bar_ready(candles_by_tf, Granularity.ONE_DAY, _AT_0120) + assert result.ready is True + assert result.blocked_by is None + + +def test_entry_bar_ready_is_not_over_strict_about_how_far_behind_the_finer_series_is(): + """NOT the over-strict version: at 14:20 UTC an hourly series that is FIVE bars behind its + OWN expectation (last stamped 08:00, when 13:00 is expected) still confirms the daily bar, + because it has long since crossed the day-close boundary the daily bar needs. A + `bars_behind == 0` requirement on ONE_HOUR would have been far too strict -- the 01:20 + trigger gives only 5 minutes of margin on a 15-minute bar -- and would block entries + routinely rather than only in the narrow post-midnight window this gate targets. + """ + candles_by_tf = { + Granularity.ONE_DAY: [_candle(_NOW - _DAY)], + Granularity.ONE_HOUR: [_candle(_NOW + 8 * _HOUR)], # 5 bars behind ONE_HOUR's own 13:00 + } + result = entry_bar_ready(candles_by_tf, Granularity.ONE_DAY, _AT_1420) + assert result.ready is True + assert result.reason is None + + +def test_entry_bar_ready_reports_the_coarsest_blocking_series_deterministically(): + """When several finer series are all unconfirmed, the reported `blocked_by` must be + deterministic (same inputs -> same diagnostic) so an operator's alert doesn't flap between + two different "which bar is missing" messages across identical cycles. The COARSEST + offender is reported -- it is the one closest to actually confirming, so it is also the one + likely to clear soonest and is the most actionable to page on.""" + candles_by_tf = { + Granularity.ONE_DAY: [_candle(_NOW - _DAY)], + Granularity.ONE_HOUR: [_candle(_NOW - _HOUR)], + Granularity.FIFTEEN_MINUTE: [_candle(_NOW - 15 * 60)], + } + result = entry_bar_ready(candles_by_tf, Granularity.ONE_DAY, _AT_0120) + assert result.ready is False + assert result.blocked_by == Granularity.ONE_HOUR + + +def test_entry_bar_readiness_is_frozen(): + result = entry_bar_ready( + {Granularity.ONE_DAY: [_candle(_NOW - _DAY)]}, Granularity.ONE_DAY, _AT_0120 + ) + assert isinstance(result, BarReadiness) diff --git a/tests/test_agent.py b/tests/test_agent.py index f21a121c..11bb308a 100644 --- a/tests/test_agent.py +++ b/tests/test_agent.py @@ -2035,3 +2035,309 @@ def _spy_place_bracket(*args, **kwargs): "the second entry's bracket was vetoed -- the duplicate position is riding without an " "exchange-side stop, which is strictly worse than the duplicate entry this test pins" ) + + +# -- entry bar readiness gate (Finding 1, HIGH: duplicate real-money orders) ------------------- +# +# The live LaunchAgent fires at :20 past every UTC hour; the runner gates on UTC hour >= 1, so +# the first eligible trigger of the day is 01:20 UTC. `turtle_breakout.py::_completed_days` +# withholds the just-closed ONE_DAY bar until the 00:00-01:00 UTC ONE_HOUR bar has closed at +# 01:00 UTC -- normally a 20-minute margin. If the ONE_HOUR series is even one bar late (a +# routine publication lag), or the ONE_DAY bar itself hasn't been fetched yet, `_completed_days` +# withholds one MORE daily bar than it should and the rule re-evaluates a bar a PRIOR cycle +# already traded. Nothing else on the live path dedupes an ENTRY (see this module's own +# docstring above), so that re-evaluation is a DUPLICATE REAL-MONEY ORDER, not a delayed one. +# `keel.data.freshness.entry_bar_ready` closes the gap; the tests below pin it at the +# `agent.run_once` level, where the gate is actually wired. + +_DAY = 86_400 +_HOUR = 3_600 + +# `turtle_breakout.py`'s own `_SMALL_PARAMS` (see `tests/strategy/test_turtle_breakout.py`), +# reused so `min_needed` (`max(lookbacks) + 2 == 7`) stays well under the 11-candle series below. +_TURTLE_PARAMS = {"entry_lookback": 5, "exit_lookback": 3, "adx_period": 5, "atr_period": 5} + + +def _turtle_daily_series() -> list[Candle]: + """11 daily candles (epoch days 0-10): the zigzag base from + `tests/strategy/test_engine.py::_uptrend_candles` (days 0-8, verified `regime.detect_condition + == BULLISH` there -- a strictly monotonic series has no interior pivot and reads as CHOPPY, + see `test_two_cycles_in_one_utc_day_reenter_the_same_turtle_breakout`'s docstring above) + followed by TWO INDEPENDENT Donchian breakouts, day 9 and day 10 -- each verified directly + against `TurtleBreakout.detect()` (with `_TURTLE_PARAMS`) to clear every gate on its own + (Donchian high, ADX>threshold, kill-zone rr>=1) when it is the newest bar. + + Two consecutive breakouts model the hazard this section pins: day 9's breakout is one a + correctly-anchored PRIOR cycle already traded (it was "yesterday's" freshly-closed bar + then); day 10's is the genuine fresh one due THIS cycle. `_completed_days`'s over-eager + two-bar drop hands day 9 back to `detect()` a second time -- there is nothing wrong with day + 9 itself, only with re-serving it. + """ + + def _c(ts: int, price: str) -> Candle: + p = Decimal(price) + return Candle( + ts=ts, + open=p - Decimal("0.5"), + high=p + Decimal("0.5"), + low=p - Decimal("0.5"), + close=p, + volume=Decimal("1"), + ) + + base_prices = ["100", "105", "102", "108", "104", "112", "109", "118", "114"] + candles = [_c(i * _DAY, v) for i, v in enumerate(base_prices)] + candles.append(_c(9 * _DAY, "140")) # day 9: the "already traded" breakout + candles.append(_c(10 * _DAY, "160")) # day 10: the genuine fresh breakout + return candles + + +def test_turtle_entry_is_blocked_when_the_hourly_series_has_not_crossed_the_day_close(repo): + """THE REGRESSION, hourly-lag shape. At 01:20 UTC on "day 11", day 10 is the newest COMPLETE + daily bar (`expected_last_ts`); the 00:00-01:00 UTC hourly bar (ts == day 11's 00:00) is + what `_completed_days` needs closed to release it. Here the hourly series is stamped one + bar SHORT of that -- a routine one-hour venue publication lag. + + PRE-FIX: `_completed_days` sees the late hourly series and drops day 10 (correctly) AND day + 9 (incorrectly), so `TurtleBreakout.detect()` fires on day 9's ALREADY-TRADED breakout -- + demonstrated below by `enter_signals` being non-empty, which is this test's load-bearing + assertion; everything after it is the fixed behaviour. + POST-FIX: the entry-readiness gate blocks the rule before `engine.evaluate` ever sees it, + because the confirming hourly bar has not arrived -- independent of whatever + `_completed_days` itself would compute. + """ + candles = _turtle_daily_series() + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, candles) + repo.insert_rule("turtle_breakout", {"product_id": PRODUCT, **_TURTLE_PARAMS}, status="live") + + today_open = 11 * _DAY # "day 11" 00:00 UTC -- the confirming hourly bar's ts if current + late_hourly = [_candle(today_open - _HOUR)] # one bar SHORT of the boundary + repo.upsert_candles(PRODUCT, Granularity.ONE_HOUR, late_hourly) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): candles, + (PRODUCT, Granularity.ONE_HOUR): late_hourly, + } + ) + config = _config( + market_data=MarketDataConfig( + granularities=[Granularity.ONE_DAY, Granularity.ONE_HOUR], history_days=365 + ) + ) + now_ts = today_open + _HOUR + 20 * 60 # 01:20 UTC on day 11 -- the first live trigger + + result = run_once(broker, repo, config, now_ts=now_ts) + + # THE BUG, stated as an assertion: pre-fix, this fires on day 9's already-traded breakout. + assert result.enter_signals == [], ( + f"turtle_breakout fired on a bar this cycle's freshness could not confirm: " + f"{result.enter_signals!r}" + ) + assert all(not r.placed for r in result.enter_results) + assert repo.get_orders(mode="live", product_id=PRODUCT) == [] + + assert len(result.blocked_entries) == 1 + blocked = result.blocked_entries[0] + assert blocked.product == PRODUCT + assert blocked.rule_name == "turtle_breakout" + assert blocked.granularity == Granularity.ONE_DAY + + +def test_turtle_entry_is_blocked_when_the_daily_bar_itself_has_not_been_fetched_yet(repo): + """THE REGRESSION, daily-lag shape. Here the ONE_HOUR confirming series IS current, but the + ONE_DAY series itself lags -- day 10's bar hasn't been fetched into the cache yet, so the + newest stored daily bar (day 9) is one bar behind `expected_last_ts`. `_completed_days` + drops nothing extra in this shape (there's nothing to drop -- day 10 was never there), but + the series' own newest bar is still the already-traded day 9 breakout. + + Distinct failure mode from the hourly-lag test above (`bars_behind > 0` on the gated series + itself, vs. an unconfirmed FINER series) -- both must block, via different `BarReadiness` + reasons. + """ + candles = _turtle_daily_series() + stored_daily = candles[:-1] # day 10 not fetched yet -- only through day 9 + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, stored_daily) + repo.insert_rule("turtle_breakout", {"product_id": PRODUCT, **_TURTLE_PARAMS}, status="live") + + today_open = 11 * _DAY + current_hourly = [_candle(today_open)] # the hourly series IS current this time + repo.upsert_candles(PRODUCT, Granularity.ONE_HOUR, current_hourly) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): stored_daily, + (PRODUCT, Granularity.ONE_HOUR): current_hourly, + } + ) + config = _config( + market_data=MarketDataConfig( + granularities=[Granularity.ONE_DAY, Granularity.ONE_HOUR], history_days=365 + ) + ) + now_ts = today_open + _HOUR + 20 * 60 + + result = run_once(broker, repo, config, now_ts=now_ts) + + # THE BUG: pre-fix, `_completed_days` doesn't drop anything here (the hourly series is + # current), so `detect()` sees day 9 as the newest bar and fires on it -- already traded. + assert result.enter_signals == [], ( + f"turtle_breakout fired on day 9's bar while day 10's had not been fetched yet: " + f"{result.enter_signals!r}" + ) + assert repo.get_orders(mode="live", product_id=PRODUCT) == [] + assert len(result.blocked_entries) == 1 + assert result.blocked_entries[0].granularity == Granularity.ONE_DAY + + +def test_turtle_entry_is_evaluated_and_placed_when_both_series_are_current(repo): + """THE COUNTERWEIGHT to the two regression tests above: this gate must not become a blanket + "never trade". When both series genuinely are current -- the normal case, true for ~23 of + the 24 daily triggers -- the entry must fire and place exactly as it did before this gate + existed. Same day-11 01:20 UTC instant, differing only in that the hourly series HAS crossed + day 11's 00:00 close. + """ + candles = _turtle_daily_series() + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, candles) + repo.insert_rule("turtle_breakout", {"product_id": PRODUCT, **_TURTLE_PARAMS}, status="live") + + today_open = 11 * _DAY + current_hourly = [_candle(today_open)] + repo.upsert_candles(PRODUCT, Granularity.ONE_HOUR, current_hourly) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): candles, + (PRODUCT, Granularity.ONE_HOUR): current_hourly, + } + ) + config = _config( + market_data=MarketDataConfig( + granularities=[Granularity.ONE_DAY, Granularity.ONE_HOUR], history_days=365 + ) + ) + now_ts = today_open + _HOUR + 20 * 60 + + result = run_once(broker, repo, config, now_ts=now_ts) + + assert len(result.enter_signals) == 1 + assert result.enter_signals[0].setup is not None + assert result.enter_signals[0].setup.entry == Decimal("160") # day 10's genuine breakout + assert len(result.enter_results) == 1 + assert result.enter_results[0].placed is True + assert result.blocked_entries == [] + # `get_orders` also carries the bracket's SELL leg (`place_bracket`'s protective stop) -- + # same convention `test_two_cycles_in_one_utc_day_reenter_the_same_turtle_breakout` above + # uses -- so the BUY count, not the raw row count, is what proves exactly one entry placed. + buy_orders = [o for o in repo.get_orders(mode="live", product_id=PRODUCT) if o["side"] == "BUY"] + assert len(buy_orders) == 1 + + +def test_exit_still_runs_while_a_different_rules_entry_is_blocked(repo): + """The exit path must never be held hostage by the entry gate: an open position's rule-driven + channel exit runs IN-PROCESS (unlike the protective stop, which rests at the broker), so it + has to fire on a stale-feed cycle exactly as it would on a fresh one. Staying in a losing + position an extra day because a DIFFERENT rule's confirming series lagged is strictly worse + than a delayed entry. Seeds a held position owned by `fake_exit` (always exits) alongside a + `turtle_breakout` rule blocked by the same late-hourly scenario as the first regression test + above, both for the SAME product, and asserts both effects land in the one cycle. + """ + _seed_open_position(repo, PRODUCT, Decimal("0.1"), Decimal("50000"), ts=1_000) + repo.insert_rule("fake_exit", {"product_id": PRODUCT}, status="live") + repo.set_state(f"position_rule:{PRODUCT}", "fake_exit") + + candles = _turtle_daily_series() + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, candles) + repo.insert_rule("turtle_breakout", {"product_id": PRODUCT, **_TURTLE_PARAMS}, status="live") + + today_open = 11 * _DAY + late_hourly = [_candle(today_open - _HOUR)] + repo.upsert_candles(PRODUCT, Granularity.ONE_HOUR, late_hourly) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): candles, + (PRODUCT, Granularity.ONE_HOUR): late_hourly, + } + ) + config = _config( + market_data=MarketDataConfig( + granularities=[Granularity.ONE_DAY, Granularity.ONE_HOUR], history_days=365 + ) + ) + now_ts = today_open + _HOUR + 20 * 60 + + result = run_once(broker, repo, config, now_ts=now_ts) + + assert len(result.exit_results) == 1 + assert result.exit_results[0].placed is True + # THE BUG: pre-fix, turtle_breakout also fires here (it is blind to the same lag the exit + # correctly ignores) -- this is the load-bearing assertion for the "before" transcript. + assert result.enter_signals == [], ( + f"turtle_breakout should have been blocked but fired anyway: {result.enter_signals!r}" + ) + blocked_names = {b.rule_name for b in result.blocked_entries} + assert "turtle_breakout" in blocked_names + # `fake_exit` declares neither `granularity` nor `timeframe`, so it is ALSO gated on the + # coarsest configured granularity (ONE_DAY) and shows up here too -- harmlessly, since its + # `detect()` always returns `None` and it was never going to enter regardless. This test + # only asserts on turtle_breakout, which IS the hazard being pinned. + + +def test_entry_gate_granularity_falls_back_to_the_coarsest_configured_granularity_for_dca(): + """`Dca` declares neither `granularity` nor `timeframe`, yet `Dca.detect` reads + `candles_by_tf[Granularity.ONE_DAY]` directly and keys its cadence off + `latest.ts // 86400 % cadence_days` -- so a stale DAILY bar re-fires the same cadence hit + and buys twice. `strategy.engine._trading_granularity`'s FINEST fallback (built for CTS + *scoring*) is wrong here: gating DCA on FIFTEEN_MINUTE would miss the hazard entirely -- the + daily bar could be weeks stale while FIFTEEN_MINUTE stayed perfectly fresh. The COARSEST + configured granularity is the fallback that fails in the safe direction for any rule that + does not declare what it reads. + """ + rule = Dca(product_id=PRODUCT) + granularities = [Granularity.ONE_DAY, Granularity.ONE_HOUR, Granularity.FIFTEEN_MINUTE] + + assert agent._entry_gate_granularity(rule, granularities) == Granularity.ONE_DAY + + +def test_run_once_blocks_a_dca_entry_on_a_stale_daily_bar(repo): + """The same gate, applied to a rule that declares no `granularity`/`timeframe` attribute at + all -- `Dca` reads `ONE_DAY` directly (see the `_entry_gate_granularity` test above), so a + stale daily bar must block it exactly like a declared-granularity rule, using the coarsest + fallback. `cadence_days=1` makes every stored bar a cadence hit regardless of its ts, so a + fire here can only be explained by the gate being absent, not by an off-cadence miss. + """ + repo.insert_rule( + "dca", + {"product_id": PRODUCT, "cadence_days": 1}, + status="live", + ) + stale_daily = [_candle(0, "100")] # epoch day 0 -- wildly behind + # Kept fresh so `market_feed.is_fresh`'s STALE-FEED skip (gated on the FINEST configured + # granularity) doesn't pre-empt this test before it ever reaches the entry gate. + fresh_hourly = [_candle(5 * _DAY + 60, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, stale_daily) + repo.upsert_candles(PRODUCT, Granularity.ONE_HOUR, fresh_hourly) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): stale_daily, + (PRODUCT, Granularity.ONE_HOUR): fresh_hourly, + } + ) + config = _config( + market_data=MarketDataConfig( + granularities=[Granularity.ONE_DAY, Granularity.ONE_HOUR], history_days=365 + ) + ) + now_ts = 5 * _DAY + 2 * _HOUR + + result = run_once(broker, repo, config, now_ts=now_ts) + + # THE BUG: pre-fix, DCA's cadence math fires off the stale day-0 bar regardless of how far + # behind it is -- nothing today checks the daily bar's own freshness before `detect()` runs. + assert result.enter_signals == [], f"dca fired on a stale daily bar: {result.enter_signals!r}" + assert repo.get_orders(mode="live", product_id=PRODUCT) == [] + assert len(result.blocked_entries) == 1 + assert result.blocked_entries[0].rule_name == "dca" + assert result.blocked_entries[0].granularity == Granularity.ONE_DAY diff --git a/tests/test_cli.py b/tests/test_cli.py index 8fd8ed54..ee486b22 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -20,6 +20,7 @@ from click.testing import CliRunner import keel.cli as cli_module +from keel import agent from keel.agent import RULE_REGISTRY, _build_rule from keel.cli import cli from keel.commands._common import DISCLAIMER @@ -173,6 +174,110 @@ def test_agent_prints_paper_equity_and_drawdown_line(tmp_path, write_config, mon assert "drawdown 0 total / 0 weekly" in result.output +# -- agent -- blocked entries (Finding 1, HIGH: duplicate real-money orders) ------------------- + + +def _seed_blocked_dca_scenario(db_path: Path, now_ts: int) -> None: + """A `dca` rule whose gating ONE_DAY bar is wildly stale, with a fresh ONE_HOUR bar so + `market_feed.is_fresh`'s STALE-FEED skip (checked against the FINEST configured + granularity) doesn't pre-empt the entry gate before it's ever reached. `cadence_days=1` + makes every stored bar a cadence hit regardless of ts, matching + `tests/test_agent.py::test_run_once_blocks_a_dca_entry_on_a_stale_daily_bar`, whose + reasoning this reuses one layer up, through the real CLI entrypoint. + """ + product = "BTC-USD" + repo = _repo_at(db_path) + repo.set_state("kill_switch", False) + + def _c(ts: int, price: str = "100") -> Candle: + p = Decimal(price) + return Candle(ts=ts, open=p, high=p, low=p, close=p, volume=Decimal("1")) + + repo.upsert_candles(product, Granularity.ONE_DAY, [_c(0)]) + repo.upsert_candles(product, Granularity.ONE_HOUR, [_c(now_ts - 60)]) + repo.insert_rule("dca", {"product_id": product, "cadence_days": 1}, status="paper") + + +def test_agent_exits_data_not_ready_when_an_entry_is_blocked(tmp_path, write_config, monkeypatch): + """CLI surface for Finding 1 (HIGH). A single-cycle `keel agent` must not exit `0` when + `run_once` withheld an entry on an unconfirmed bar -- a green exit code is exactly what lets + a cron/LaunchAgent wrapper stamp the day as done and never retry, turning a transient + publication lag into a silently-skipped trading day forever instead of the intended + `<= 60 minutes of delay` (see `agent.DATA_NOT_READY_EXIT`'s docstring). + """ + from tests.conftest import VALID_CONFIG_YAML + + monkeypatch.setattr(cli_module, "_build_broker", lambda config: FakeBroker()) + # Drop FIFTEEN_MINUTE -- the live config's finest granularity -- so the market-data-wide + # STALE-FEED skip (`market_feed.is_fresh`, checked against the finest configured + # granularity) doesn't need its own fixture and can't mask the entry gate this test is about. + config_path = write_config(VALID_CONFIG_YAML.replace(" - FIFTEEN_MINUTE\n", "")) + db_path = tmp_path / "test.db" + now_ts = 5 * 86_400 + 2 * 3_600 + _seed_blocked_dca_scenario(db_path, now_ts) + monkeypatch.setattr(cli_module.time, "time", lambda: now_ts) + runner = CliRunner() + + result = runner.invoke(cli, ["--db", str(db_path), "--config", str(config_path), "agent"]) + + assert result.exit_code == agent.DATA_NOT_READY_EXIT, result.output + assert "signals=0" in result.output + assert "blocked=1" in result.output + + +def test_agent_exits_zero_and_reports_blocked_zero_when_nothing_is_blocked( + tmp_path, valid_config_path, monkeypatch +): + """The counterweight to the test above: a normal cycle with nothing blocked exits `0`, and + the printed line carries `blocked=0` alongside `signals=` -- `_print_loop_result` must keep + emitting the `signals=[0-9]+` token the live runner greps out of its output (see the runner's + own `keel-live-run.sh`), and `blocked=0` proves the new token is additive, not a replacement. + """ + monkeypatch.setattr(cli_module, "_build_broker", lambda config: FakeBroker()) + db_path = tmp_path / "test.db" + _repo_at(db_path).set_state("kill_switch", False) + runner = CliRunner() + + result = runner.invoke( + cli, ["--db", str(db_path), "--config", str(valid_config_path), "agent"] + ) + + assert result.exit_code == 0, result.output + assert "signals=0" in result.output + assert "blocked=0" in result.output + + +def test_agent_loop_does_not_exit_the_process_when_a_cycle_is_blocked( + tmp_path, write_config, monkeypatch +): + """`--loop` must NEVER terminate the process on a blocked cycle -- a long-running loop is + supposed to skip the cycle and retry next interval, exactly like it does for any other + per-cycle condition (kill-switch, stale feed); dying on a usually-transient publication lag + would take the whole scheduled loop down over what a single-cycle runner recovers from in + one retry. Reuses the same blocked scenario as the single-cycle exit-code test above, but + through `--loop --max-cycles 1`. + """ + from tests.conftest import VALID_CONFIG_YAML + + monkeypatch.setattr(cli_module, "_build_broker", lambda config: FakeBroker()) + config_path = write_config(VALID_CONFIG_YAML.replace(" - FIFTEEN_MINUTE\n", "")) + db_path = tmp_path / "test.db" + now_ts = 5 * 86_400 + 2 * 3_600 + _seed_blocked_dca_scenario(db_path, now_ts) + monkeypatch.setattr(cli_module.time, "time", lambda: now_ts) + runner = CliRunner() + + result = runner.invoke( + cli, + [ + "--db", str(db_path), + "--config", str(config_path), + "agent", "--loop", "--max-cycles", "1", "--interval", "0", + ], + ) + + assert result.exit_code == 0, result.output + assert "blocked=1" in result.output From 25ca168e1e3cc77dcc5c5fb6208c459ee38e9478 Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Thu, 6 Aug 2026 19:03:32 -0400 Subject: [PATCH 2/4] fix(schedule): stop the runner losing a day-stamp, a clock, or a duplicate The day-stamp in keel-live-run.sh is the ONLY thing standing between the live money path and entering the same daily signal twice. With 24 triggers a day, one lost stamp is up to 23 duplicate entries in one UTC day. Four ways it could be lost, all reproduced before fixing: FINDING 2 (HIGH) -- a failed stamp write was swallowed. `printf ... > "$STAMP"` discarded its exit status, there is no `set -e`, and the script exited 0. With a read-only logs directory the cycle RAN, the stamp was ABSENT, rc was 0, and the next trigger ran a SECOND full cycle (reproduced: two cycles, rc=0 both times). Two layers now: * PRE-FLIGHT, before keel is invoked at all: write/read/remove a probe file next to the stamp and refuse to run a cycle if that fails. This is the layer that matters. Exiting nonzero AFTER a cycle has run does not prevent the duplicate -- the order is already placed and the next trigger still re-runs. The only way to turn "duplicate real order" into "no trading plus a loud alert" is to refuse to trade when we cannot record that we traded. Failing closed costs a trading day; a duplicate live entry is not recoverable. * ATOMIC WRITE + read-back afterwards, as belt and braces. `> "$STAMP"` truncates FIRST, so a torn write left an EMPTY stamp, which reads as "never ran" and re-runs the day; a temp file plus `mv -f` cannot leave the stamp truncated or partial. FINDING 3 (MED) -- empty `date -u` output disabled the detector silently and permanently. On this hardware `$((10#$(date -u '+%H')))` on empty input evaluates to 0, not an error, so an empty clock gave TODAY="" and HOUR=0; a MISSING stamp also reads as "", so `[ "" = "" ]` was true -- "already ran" -- forever, with no alert. The raw clock strings are now validated before anything is computed from them (exit 64, nothing run, stamp untouched). FINDING 4 (MED) -- the stamp compare was `=`, so a clock rollback re-evaluated a bar. A Mac booting with a bad RTC before NTP settles (RunAtLoad fires immediately) reads a past date, which `!=` treats as "not today": the cycle runs and stamps the bogus date, and when the clock corrects forward the real date differs from that stamp so it runs AGAIN. The compare is now strictly-less-than, which makes the stamp monotonic -- ISO dates sort lexicographically, so a string compare is a date compare. A malformed stamp is refused (exit 65) rather than compared, because `"garbage" < "2026-08-06"` is false and would read as "already ran" forever. Also: the "N signal(s) PENDING -- run the agent interactively" notification now fires ONLY on a clean cycle. Per this script's own COROLLARY, running the agent by hand BYPASSES the stamp, so prompting for it off a FAILED cycle's partially-parsed output pointed the operator straight at a duplicate entry. An ordinary nonzero keel exit deliberately does NOT notify -- it is expected and self-healing (a retry an hour later), and alerting 23 times a day for it would train the operator to ignore the alerts that do need a human. That policy is written down in the header. FINDING 7 -- "no missed day" was stated flatly in both the header and the plist. It is conditional on the machine being powered on for at least one eligible trigger that UTC day; launchd does not re-run a trigger that passed while the machine was off. Both now say so. FINDING 10 -- the PENDLOG line logged LOCAL, unlabelled time next to lines that are all UTC. FINDING 8 (flock) -- documented, not fixed: flock is not installed on macOS (verified), launchd will not start a job already running, and the race that actually matters is a manual run, which bypasses the stamp regardless of any lock. FINDING 6 (test quality) -- tests/test_schedule.py drove a Python RE-IMPLEMENTATION of the shell gate, so the year-long simulation tested a model, not the artifact; and `_skip_before_sched_hour` made the only two real-shell tests SILENTLY SKIP whenever CI ran between 00:00 and 01:00 UTC -- on the sole barrier to duplicate orders. The skip is gone: every real-script test now shims `date` on PATH and injects its own instant. The model is kept (driving the real script over 9624 triggers would add ~2.5 minutes to a 10-second suite) but is now PINNED to the artifact by test_the_simulated_gate_matches_the_real_script, which replays the real script over a curated adversarial sequence -- normal days, the sub-SCHED_HOUR trigger, both DST transitions including the twice-fired local 01:20, and the boot-after-outage catch-up -- and requires it to agree with the model at every trigger. `_stored_series` also hardcoded instantaneous, never-failing candle publication, which is the assumption that made the late-candle bug class invisible. It now takes `hourly_lag_bars` / `daily_lag_bars`, and a new test pins the premise against the real `_completed_days`: at 01:20 UTC one bar of hourly lag regresses the effective daily bar to X-2 -- the bar yesterday's cycle already traded -- while at the old 13:05 UTC schedule the same lag is harmless. That is the 20-minute margin this schedule now runs on, and why agent.run_once gates entries on it. Co-Authored-By: Claude Opus 5 (1M context) --- com.keel.live.plist | 8 + keel-live-run.sh | 208 ++++++++++++-- tests/test_schedule.py | 613 +++++++++++++++++++++++++++++++++++++---- 3 files changed, 745 insertions(+), 84 deletions(-) diff --git a/com.keel.live.plist b/com.keel.live.plist index 0609d507..2a4d108e 100644 --- a/com.keel.live.plist +++ b/com.keel.live.plist @@ -45,6 +45,14 @@ an entry, so two cycles in one UTC day means two entries off one daily bar. See tests/test_schedule.py, which pins all of this. + "NO MISSED DAY" IS CONDITIONAL, NOT UNCONDITIONAL: it holds only if the machine is + powered ON for at least one eligible trigger during that UTC day. launchd does NOT + re-run a StartCalendarInterval that passed while the machine was OFF (see WHY 24 + TRIGGERS above, which is the exact mechanism the 2026-07-28 incident exposed), so a + machine that is off from just after 01:00 UTC through the rest of a UTC date gets no + eligible trigger at all that day, and nothing catches it up; that UTC date is simply + skipped. Do not read "no missed day" as a guarantee independent of power. + This changes WHEN a cycle runs, never whether it may place an order, which is autonomy's job alone. This comment used to say "the detector still places nothing: confirm mode fails closed with no TTY", which held only with autonomy OFF while the deployment has run diff --git a/keel-live-run.sh b/keel-live-run.sh index 7af36280..7feb1856 100755 --- a/keel-live-run.sh +++ b/keel-live-run.sh @@ -55,13 +55,18 @@ # to gate and stamp on the LOCAL date at 09:00, i.e. 13:00/14:00 UTC, roughly twelve hours of # avoidable lag on every breakout. # -# THE INVARIANT. For any UTC date X the newest VISIBLE daily bar is constant -- it is X-1 -- -# across the whole eligible window [01:00 UTC, 24:00 UTC). So whichever eligible trigger fires -# first on UTC date X evaluates bar X-1 and stamps X, and every later trigger that UTC day is a -# no-op: every daily bar evaluated exactly once, no missed day and no double day. That only holds -# because the stamp and the gate are on the SAME clock. A LOCAL date straddles two UTC dates, so -# the old gate could run twice within one UTC day on the catch-up path (machine off until late in -# the local day) -- see tests/test_schedule.py. +# THE INVARIANT, AND WHAT IT DEPENDS ON. For any UTC date X the newest VISIBLE daily bar is +# constant -- it is X-1 -- across the whole eligible window [01:00 UTC, 24:00 UTC). So whichever +# eligible trigger fires first on UTC date X evaluates bar X-1 and stamps X, and every later +# trigger that UTC day is a no-op: every daily bar evaluated exactly once, no missed day and no +# double day. That only holds because the stamp and the gate are on the SAME clock, AND because +# the machine is powered on for at least one eligible trigger during UTC date X. launchd does NOT +# re-run a StartCalendarInterval that passed while the machine was OFF (see CATCH-UP below), so a +# machine that is off from just after 01:00 UTC through the rest of UTC date X gets no eligible +# trigger at all that day, and nothing catches it up -- that UTC date is simply skipped. "No +# missed day" is conditional on power, not an unconditional guarantee. A LOCAL date straddles two +# UTC dates, so the old gate could run twice within one UTC day on the catch-up path (machine off +# until late in the local day) -- see tests/test_schedule.py. # # CATCH-UP. launchd re-runs a missed StartCalendarInterval on wake from SLEEP but NOT when the # trigger passed while the machine was powered OFF, so a shutdown over the scheduled hour silently @@ -79,6 +84,38 @@ # trigger instead of being recorded as done -- and a detector that failed must not look like a # quiet "no signals today". # +# EXIT CODES this script produces itself (keel's own exit code otherwise passes straight through +# via `exit "$STATUS"` at the very end -- see the COROLLARY above for why that must never be +# masked; a masked exit code would hide the fact that a cycle failed and needs retrying): +# 64 -- `date -u` returned something that is not a well-formed date/hour (empty output counts: +# on this hardware `$((10#$(date -u '+%H')))` on empty input evaluates to 0, not an +# error, so an unvalidated empty clock silently reads as HOUR=0 and can make a missing +# stamp compare equal to an empty TODAY -- "already ran", forever, with no alert). +# 65 -- the on-disk stamp is non-empty but is not a well-formed ISO date. A malformed stamp +# must never be silently COMPARED: string `<`/`=` against garbage can come out either +# way, and the "looks like already ran" direction disables the detector forever, the same +# failure class as 64. +# 66 -- the day-stamp could not be proven persistable before running a cycle (pre-flight), or +# could not be verified written back after one (post-cycle). See the PRE-FLIGHT and +# ATOMIC STAMP WRITE comments below for why there are two layers and which one matters. +# +# NOTIFICATION POLICY. A macOS notification fires ONLY for a condition the machine cannot +# self-heal without a human: exit codes 64/65/66 above. An ordinary NONZERO exit from keel itself +# (e.g. the venue has not yet published the bar this cycle needs) is EXPECTED and SELF-HEALING -- +# one of the remaining hourly triggers retries it, and the OUTLOG line below is enough of a +# record -- so it does NOT notify. Notifying 23 times a day for a condition that resolves itself +# on its own would train the operator to ignore notifications, which defeats the ones that +# actually need a human. +# +# TOCTOU (Finding 8, OPTIONAL, not closed). Between reading $STAMPED and writing $STAMP, two +# CONCURRENT invocations of this script could both pass the gate and both run a cycle -- `flock` +# would close this, but it is NOT installed on this machine (verified: `which flock` fails), so +# this is documented rather than fixed. The realistic exposure is small: launchd will not start a +# job that is already running, so the SCHEDULED path cannot race itself. The actual race is a +# MANUAL `keel agent` run, or a manual invocation of this script, racing the scheduled one -- +# which the COROLLARY paragraph above already warns bypasses the stamp regardless of any lock, so +# a TOCTOU fix here would not have closed the exposure that actually matters. +# # Authored in the dev repo (gitignored). DEPLOY (copy) to ~/keel and schedule via # com.keel.live.plist. Runs from the deployment's own venv + config + db. set -uo pipefail # NOT -e: a nonzero exit from keel/grep must not skip the notify path @@ -90,6 +127,11 @@ DB="keel-live.db" OUTLOG="$DIR/logs/keel-live.out.log" PENDLOG="$DIR/logs/keel-live.pending.log" STAMP="$DIR/logs/.keel-live-last-run" +# The one seam every macOS notification in this script goes through. Same purpose as the `DIR=` +# rewrite tests/test_schedule.py::_sandbox already relies on: it lets the schedule tests swap in a +# recorder and assert BOTH that a machine-is-broken condition alerts and that an ordinary +# self-healing one does NOT -- without ever firing a real notification during a test run. +OSASCRIPT="/usr/bin/osascript" # UTC hour at or after which a cycle is allowed: 01:00 UTC is the instant _completed_days stops # withholding the daily bar that closed at 00:00 UTC. See the header. This is a UTC hour, and it # is only meaningful because TODAY below is a UTC date too -- change one and you must change both. @@ -97,14 +139,68 @@ SCHED_HOUR=1 cd "$DIR" || exit 1 -TODAY="$(date -u '+%Y-%m-%d')" +# Single seam for every macOS alert this script can raise, so the alert-worthy paths (64/65/66) +# all read the same and none of them can forget the `2>/dev/null || true` that keeps a notify +# failure from ever masking the exit code it is reporting on. +notify() { + "$OSASCRIPT" -e "display notification \"$1\" with title \"keel-live\" subtitle \"supervised live\" sound name \"Glass\"" 2>/dev/null || true +} + +TODAY_RAW="$(date -u '+%Y-%m-%d')" +HOUR_RAW="$(date -u '+%H')" + +# A1 (Finding 3, MED). Validate the RAW clock output before computing anything from it. An empty +# `date -u` -- which this hardware can produce -- would otherwise silently give TODAY="" and, via +# `$((10#$(date -u '+%H')))` on empty input evaluating to 0 (not an error), HOUR=0. A MISSING +# stamp file also reads as "" (`cat ... 2>/dev/null || true`), so `[ "" = "" ]` would read as +# "already ran" and the detector would be dead FOREVER with no alert -- the worst failure mode +# available, because it looks like success. Reject anything that is not exactly a 4-digit-hyphen +# date / 2-digit hour BEFORE touching the stamp at all: notify, and exit 64 having run nothing. +if ! [[ "$TODAY_RAW" =~ ^[0-9]{4}-[0-9]{2}-[0-9]{2}$ ]] || ! [[ "$HOUR_RAW" =~ ^[0-9]{2}$ ]]; then + notify "keel-live: date -u returned malformed output (date='${TODAY_RAW}' hour='${HOUR_RAW}') -- refusing to run a cycle. The system clock needs investigating." + printf '%s [keel-live] clock invalid -- date -u gave date=%s hour=%s -- refusing to run, stamp untouched -- exit 64\n' \ + "$(date -u '+%Y-%m-%dT%H:%M:%SZ' 2>/dev/null || printf 'unknown')" "$TODAY_RAW" "$HOUR_RAW" + exit 64 +fi + # 10# forces base 10: `date +%H` yields 08/09, which arithmetic would otherwise read as octal. -HOUR="$((10#$(date -u '+%H')))" +HOUR="$((10#$HOUR_RAW))" +if [ "$HOUR" -gt 23 ]; then + notify "keel-live: date -u returned an out-of-range hour ('${HOUR_RAW}') -- refusing to run a cycle. The system clock needs investigating." + printf '%s [keel-live] clock invalid -- hour %s out of range -- refusing to run, stamp untouched -- exit 64\n' \ + "$(date -u '+%Y-%m-%dT%H:%M:%SZ' 2>/dev/null || printf 'unknown')" "$HOUR_RAW" + exit 64 +fi +TODAY="$TODAY_RAW" + STAMPED="$(cat "$STAMP" 2>/dev/null || true)" -if [ "$STAMPED" = "$TODAY" ]; then - printf '%s [keel-live] detector already ran this UTC day (%s) -- skipping\n' \ - "$(date -u '+%Y-%m-%d %H:%M UTC')" "$TODAY" +# A2 (Finding 4, MED), part one. A non-empty stamp that is not a well-formed ISO date must never +# be silently COMPARED: `"garbage" < "2026-08-06"` is FALSE in a lexicographic string compare, +# which reads exactly like "already ran" and disables the detector forever -- the same failure +# class as A1, just entered from the stamp file instead of the clock. Refuse loudly instead. +if [ -n "$STAMPED" ] && ! [[ "$STAMPED" =~ ^[0-9]{4}-[0-9]{2}-[0-9]{2}$ ]]; then + notify "keel-live: the day-stamp is corrupt ('${STAMPED}') -- refusing to run a cycle. An operator needs to inspect ${STAMP}." + printf '%s [keel-live] stamp malformed -- %s does not read back as a date -- refusing to run, stamp not overwritten -- exit 65\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMP" + exit 65 +fi + +# A2, part two: the compare is STRICTLY LESS THAN, not EQUALS. A Mac that boots with a bad RTC +# before NTP settles (RunAtLoad fires immediately, before the clock is trustworthy) can read a +# date in the PAST. With `=` that reads as "not today", the cycle RUNS and stamps the bogus past +# date; when the clock then corrects forward, the real date differs from that bogus stamp so the +# cycle runs AGAIN -- re-evaluating a bar it already traded, a second entry on the live money +# path. Requiring the stamp to be STRICTLY BEFORE today closes both directions: a stamp equal to +# today (ordinary "already ran") and a stamp AHEAD of today (clock rolled back after a correct +# stamp) both read as "done, do not run" -- neither should trigger a second cycle. +# ISO-8601 dates sort lexicographically, so a plain string comparison gives us date comparison for +# free. `<` inside `[[ ]]` is a bash STRING comparison, which is what we want here; the same `<` +# inside a POSIX `[ ]` is output redirection and would silently truncate a file instead of +# comparing -- `[[ ]]` is not a style choice on this line, it is the only correct spelling. +if [ -n "$STAMPED" ] && ! [[ "$STAMPED" < "$TODAY" ]]; then + printf '%s [keel-live] stamp (%s) is not before today (%s) -- already ran, or the clock moved backward -- skipping\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMPED" "$TODAY" exit 0 fi @@ -114,6 +210,29 @@ if [ "$HOUR" -lt "$SCHED_HOUR" ]; then exit 0 fi +# A3 (Finding 2, HIGH), layer one: PRE-FLIGHT, before invoking keel at all. Prove the stamp is +# PERSISTABLE by writing a throwaway probe file next to $STAMP, reading it back, and removing it. +# Reproduced by the reviewer with a read-only logs dir: the OLD script ran the cycle, the stamp +# write then failed SILENTLY, rc was 0, and the next trigger ran a SECOND full cycle. Exiting +# nonzero AFTER a cycle has already run does not prevent that duplicate -- if autonomy is ON the +# order is already placed, and the next trigger will still re-run because the write already +# failed once and nothing detected it. The only way to turn "duplicate real order" into "no +# trading plus a loud alert" is to refuse to trade when we cannot record that we traded. That is +# failing CLOSED, and it is the correct direction here even though it costs a trading day: a +# missed day is recoverable, a duplicate live entry is not. +PREFLIGHT_PROBE="$STAMP.preflight.$$" +if { printf 'preflight-probe\n' >"$PREFLIGHT_PROBE"; } 2>/dev/null \ + && [ "$(cat "$PREFLIGHT_PROBE" 2>/dev/null || true)" = "preflight-probe" ] \ + && rm -f "$PREFLIGHT_PROBE" 2>/dev/null; then + : # persistable -- proceed +else + rm -f "$PREFLIGHT_PROBE" 2>/dev/null || true + notify "keel-live: cannot persist the day-stamp (logs directory or disk problem near ${STAMP}) -- refusing to run a cycle, because an unstamped success would duplicate on the next trigger." + printf '%s [keel-live] pre-flight FAILED -- could not write/read/remove a probe file next to %s -- refusing to run a cycle -- exit 66\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMP" + exit 66 +fi + # One headless cycle on the live money path. With autonomy ON this PLACES orders unattended; with # it OFF the confirm gate declines for want of a TTY and nothing is placed. Captures the # LoopResult line, which reads e.g.: [ts] mode=confirm polled=.. products=[..] signals=N entered=0 .. @@ -121,25 +240,60 @@ fi # event in keel-live.log, which is where you can see autonomy having taken effect. OUT="$("$KEEL" --config "$CONFIG" --db "$DB" agent 2>&1)" STATUS=$? -printf '%s\n' "$OUT" >> "$OUTLOG" +printf '%s\n' "$OUT" >>"$OUTLOG" -# Parse `signals=N` from the LoopResult (default 0 if the line is absent, e.g. a kill-switch skip). -SIGNALS="$(printf '%s\n' "$OUT" | grep -oE 'signals=[0-9]+' | tail -1 | cut -d= -f2)" -SIGNALS="${SIGNALS:-0}" +# Everything below is gated on a CLEAN cycle. A4 (the PENDING notification) and A3's layer two +# (the stamp write) both used to run unconditionally; both are wrong to run on a failed cycle, +# for related but distinct reasons -- see each comment below. +if [ "$STATUS" -eq 0 ]; then + # Parse `signals=N` from the LoopResult (default 0 if the line is absent, e.g. a kill-switch + # skip). Only trustworthy here, inside the STATUS==0 branch: on a failed cycle the captured + # output may be partial or garbled, so any `signals=N` found in it is not something to act on. + SIGNALS="$(printf '%s\n' "$OUT" | grep -oE 'signals=[0-9]+' | tail -1 | cut -d= -f2)" + SIGNALS="${SIGNALS:-0}" -if [ "${SIGNALS}" -gt 0 ]; then - MSG="${SIGNALS} Turtle signal(s) PENDING -- run the agent interactively to approve (same day)." - # macOS notification (LaunchAgents run in your GUI session, so this shows up + plays a sound). - /usr/bin/osascript -e "display notification \"${MSG}\" with title \"keel-live\" subtitle \"supervised live\" sound name \"Glass\"" 2>/dev/null || true - printf '%s [keel-live] %s\n' "$(date '+%Y-%m-%d %H:%M')" "${MSG}" >> "$PENDLOG" -fi + if [ "$SIGNALS" -gt 0 ]; then + # A4. Reachable ONLY when STATUS -eq 0. Per the COROLLARY at the top of this file, "run the + # agent interactively" BYPASSES this script's stamp entirely, so firing that prompt off a + # FAILED cycle's output would tell the operator to do by hand the exact thing the stamp + # exists to prevent -- a direct path to a duplicate order. The old script parsed `signals=N` + # and notified regardless of exit status; that was the bug. + MSG="${SIGNALS} Turtle signal(s) PENDING -- run the agent interactively to approve (same day)." + notify "$MSG" + # A5 (Finding 10). UTC, and labelled as such, like every other timestamp in this script. + # This used to be `date` (no `-u`) -- LOCAL, unlabelled time next to lines that are all UTC. + printf '%s [keel-live] %s\n' "$(date -u '+%Y-%m-%d %H:%M UTC')" "${MSG}" >>"$PENDLOG" + fi -# Only a clean cycle counts as "this UTC day is done"; anything else leaves the day open for one -# of the remaining hourly triggers to retry. -if [ "$STATUS" -eq 0 ]; then - printf '%s\n' "$TODAY" > "$STAMP" + # A3, layer two: belt-and-braces, NOT the primary defence -- the pre-flight above is. Write to + # a TEMP file and `mv -f` it onto $STAMP: a rename is atomic within one filesystem, so a torn + # write can never leave $STAMP truncated or empty. (Plain `> "$STAMP"` TRUNCATES the target + # FIRST and writes after, so a write that dies partway through -- disk full, a yanked volume -- + # leaves an EMPTY stamp, and an empty stamp reads as "never ran" and re-runs the day: the + # truncation bug this replaces.) Then read $STAMP back and require it to equal $TODAY. This can + # only fail if something changed between the pre-flight probe succeeding and now, but "can only + # fail rarely" is not "cannot fail" -- and by this point a cycle has ALREADY RUN. If autonomy is + # ON, an order may already be placed, so the notification here is not optional: failing to + # record the stamp will not by itself stop a second cycle, only a human acting on this alert + # before the next trigger will. + STAMP_TMP="$STAMP.tmp.$$" + if { printf '%s\n' "$TODAY" >"$STAMP_TMP"; } 2>/dev/null \ + && mv -f "$STAMP_TMP" "$STAMP" 2>/dev/null \ + && [ "$(cat "$STAMP" 2>/dev/null || true)" = "$TODAY" ]; then + : # stamped and verified + else + rm -f "$STAMP_TMP" 2>/dev/null || true + notify "keel-live: the day-stamp write FAILED after a cycle already ran -- an order may already be placed. INVESTIGATE ${STAMP} IMMEDIATELY before the next trigger." + printf '%s [keel-live] stamp write FAILED after a clean cycle -- %s does not read back as %s -- exit 66\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMP" "$TODAY" >>"$OUTLOG" + exit 66 + fi else + # Only a clean cycle counts as "this UTC day is done"; anything else leaves the day open for + # one of the remaining hourly triggers to retry. Deliberately NOT a notification -- see + # NOTIFICATION POLICY at the top: a nonzero keel exit is an expected, self-healing condition + # (e.g. the venue has not published the bar yet), and the OUTLOG line is enough of a record. printf '%s [keel-live] cycle exited %d -- not stamping, will retry\n' \ - "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STATUS" >> "$OUTLOG" + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STATUS" >>"$OUTLOG" fi exit "$STATUS" diff --git a/tests/test_schedule.py b/tests/test_schedule.py index 4fa199d1..eb9cf1c6 100644 --- a/tests/test_schedule.py +++ b/tests/test_schedule.py @@ -31,6 +31,30 @@ StartCalendarInterval on wake from sleep but NOT when the trigger passed while the machine was powered off, so the only defence against a shutdown eating a day is having another trigger later -- and the catch-up window grew from 12h to 23h. + +**Publication lag (the premise nothing tested before this file).** All of the above assumes +instantaneous, never-failing candle publication. `_stored_series` used to hard-code that +assumption; it no longer does (`hourly_lag_bars`/`daily_lag_bars`), and +`test_publication_lag_can_regress_the_effective_bar_except_at_the_old_late_schedule` proves the +premise of the whole late-candle bug class: a one-bar-late feed at 01:20 UTC REGRESSES the +effective daily bar by a full day (re-entering a bar yesterday's cycle already traded), while the +same lag at the OLD 13:05 UTC schedule does not, because that schedule traded ~13h of publication +margin for the ~20 minutes this one runs on. + +**Pinning the model to the shipped script (Finding 6).** The gate-simulation tests below +(`_run_gate` and everything built on it) are a PURE PYTHON MODEL of `keel-live-run.sh`'s two +guards -- deliberately, so a 13-month/9600-trigger simulation costs milliseconds instead of +minutes. That is only trustworthy to the extent the model and the shipped script actually agree, +which nothing enforced until `test_the_simulated_gate_matches_the_real_script`: it drives the REAL +script, under a shimmed clock, over a curated adversarial sequence (normal days, the sub-threshold +trigger, both DST transitions, and the boot-after-outage catch-up path) and asserts the model's +prediction matches the script's actual behaviour at every single trigger. Everything else in this +file that exercises the real script (`_sandbox`/`_run`) also runs it VERBATIM -- never a +reimplementation -- through a harness that shims `date` (so tests do not depend on, or wait on, +the wall clock) and records rather than fires macOS notifications (`$OSASCRIPT` is redirected to a +recorder, and every invocation additionally runs under `sandbox-exec` denying the real binary +outright, so a test run can never pop a real notification on a machine that also trades real +money). """ from __future__ import annotations @@ -40,6 +64,7 @@ import re import stat import subprocess +from dataclasses import dataclass from datetime import UTC, date, datetime, timedelta from pathlib import Path from zoneinfo import ZoneInfo @@ -135,17 +160,26 @@ def _candle(ts: int) -> Candle: return Candle(ts=ts, open=price, high=price, low=price, close=price, volume=1) -def _stored_series(now_utc: datetime) -> dict[Granularity, list[Candle]]: +def _stored_series( + now_utc: datetime, *, hourly_lag_bars: int = 0, daily_lag_bars: int = 0 +) -> dict[Granularity, list[Candle]]: """The candle series `data.market_feed` would have persisted as of `now_utc`. market_feed stores only CLOSED candles, so a bar with timestamp `t` and width `w` is present exactly once `now >= t + w`. Deriving both series from that one rule -- rather than hand- writing a series per parametrised time -- is what makes this test about the CLOCK and not about my arithmetic. + + `hourly_lag_bars`/`daily_lag_bars` model a feed that is N bars BEHIND what instantaneous + publication would have produced -- e.g. Coinbase, or `data.market_feed` itself, running late. + Zero (the default, and today's assumption everywhere this was called before) reproduces + instantaneous, never-failing publication. That assumption is exactly what made the whole + late-candle bug class invisible: see + `test_publication_lag_can_regress_the_effective_bar_except_at_the_old_late_schedule`. """ now = int(now_utc.timestamp()) - last_hour = (now // _HOUR - 1) * _HOUR - last_day = (now // _DAY - 1) * _DAY + last_hour = (now // _HOUR - 1 - hourly_lag_bars) * _HOUR + last_day = (now // _DAY - 1 - daily_lag_bars) * _DAY return { Granularity.ONE_DAY: [_candle(last_day - n * _DAY) for n in reversed(range(5))], Granularity.ONE_HOUR: [_candle(last_hour - n * _HOUR) for n in reversed(range(5))], @@ -177,7 +211,9 @@ def test_effective_bar_does_not_advance_until_0100_utc( `SCHED_HOUR=1` in `keel-live-run.sh` is exactly this boundary. If this test ever fails, the schedule's premise has moved and `SCHED_HOUR` must move with it -- do not just re-baseline - the expectations here. + the expectations here. Uses instantaneous publication (`_stored_series`'s default of zero + lag); the effect of LATE publication on this same boundary is + `test_publication_lag_can_regress_the_effective_bar_except_at_the_old_late_schedule`. """ now = datetime(2026, 6, 15, hour, minute, tzinfo=UTC) series = _stored_series(now) @@ -191,11 +227,64 @@ def test_effective_bar_does_not_advance_until_0100_utc( assert effective == newest_stored_day - _DAY +def test_publication_lag_can_regress_the_effective_bar_except_at_the_old_late_schedule() -> None: + """The premise of the WHOLE late-candle problem, against the REAL `_completed_days`. + + Everything above this test assumes `data.market_feed` publishes instantly. It does not always: + Coinbase can be slow, or the feed job can lag. This test proves what happens when it does, at + the two schedules that matter: + + - At 01:20 UTC with both series CURRENT, the effective newest daily bar is X-1 (pinned by + `test_effective_bar_does_not_advance_until_0100_utc` already). + - At 01:20 UTC with the HOURLY series one bar behind, it REGRESSES to X-2. + - At 01:20 UTC with the DAILY series one bar behind, it ALSO regresses to X-2. + - At 13:05 UTC -- where the OLD local-anchored schedule sat -- the SAME one-bar hourly lag + does NOT regress it; there is enough margin (~13h) to absorb it. + + That last case is the point of this test existing: the PR that moved the schedule to 01:20 UTC + traded roughly thirteen hours of publication margin for twenty minutes of it. A regression to + X-2 is not a cosmetic staleness issue -- re-evaluating bar X-2 means re-entering the SAME + breakout that YESTERDAY's 01:20 UTC cycle already evaluated and (if it broke out) already + traded, on the live money path, where nothing downstream dedupes an entry (see the module + docstring). `keel/agent.py::run_once` is gaining a gate (by another worker, on this same + branch) that refuses to re-enter while a position from that same bar is already open -- + referenced here by BEHAVIOUR, not by import, since that file is not owned by this change -- + and that gate is exactly the backstop this test's regression case would otherwise defeat. + """ + at_0120 = datetime(2026, 6, 15, 1, 20, tzinfo=UTC) + at_1305 = datetime(2026, 6, 15, 13, 5, tzinfo=UTC) + + current_at_0120 = _completed_days(_stored_series(at_0120))[-1].ts + + hourly_lagged_at_0120 = _completed_days(_stored_series(at_0120, hourly_lag_bars=1))[-1].ts + assert hourly_lagged_at_0120 == current_at_0120 - _DAY, ( + "a one-bar-late HOURLY feed at 01:20 UTC must regress the effective daily bar by a full " + "day -- that is the entry point of the whole late-candle bug" + ) + + daily_lagged_at_0120 = _completed_days(_stored_series(at_0120, daily_lag_bars=1))[-1].ts + assert daily_lagged_at_0120 == current_at_0120 - _DAY, ( + "a one-bar-late DAILY feed at 01:20 UTC must regress the effective daily bar too" + ) + + current_at_1305 = _completed_days(_stored_series(at_1305))[-1].ts + hourly_lagged_at_1305 = _completed_days(_stored_series(at_1305, hourly_lag_bars=1))[-1].ts + assert hourly_lagged_at_1305 == current_at_1305, ( + "the SAME one-bar hourly lag at 13:05 UTC -- the old schedule's hour -- must NOT regress " + "the effective bar: ~13h of margin absorbs it. This is the margin the 01:20 UTC schedule " + "gave up in exchange for evaluating breakouts ~13h sooner every day it is NOT late." + ) + + # -- the schedule gate, simulated over a full year -------------------------------------------- # # Deliberately PURE: no keel imports, no database, no clock. The gate is four lines of shell and # the only interesting thing about it is how it behaves across thousands of triggers and two DST -# transitions, which is a property you can only see by simulating it. +# transitions, which is a property you can only see by simulating it. It is a MODEL, not the +# shipped script -- trustworthy only because `test_the_simulated_gate_matches_the_real_script`, +# below, pins it to the real `keel-live-run.sh` over a curated adversarial sequence. If you change +# the gate's shape, that is the test that must keep passing; do not "fix" a mismatch by editing +# the model in isolation. def _utc_instants(local_naive: datetime, tz: ZoneInfo) -> list[datetime]: @@ -244,21 +333,25 @@ def _run_gate( ) -> list[datetime]: """Replay `keel-live-run.sh`'s two guards over `triggers`; return the UTC instants that RAN. - The shell, verbatim in Python: + The shell, in Python, as of the hardened script: - if [ "$STAMPED" = "$TODAY" ]; then exit 0; fi # already ran for this date + if [ -n "$STAMPED" ] && ! [[ "$STAMPED" < "$TODAY" ]]; then exit 0; fi # already ran/behind if [ "$HOUR" -lt "$SCHED_HOUR" ]; then exit 0; fi # too early in the day - `utc_anchored=False` reproduces the OLD behaviour (both `TODAY` and `HOUR` from LOCAL time), - so the two can be compared on identical trigger lists. Every cycle here is assumed to succeed - -- a failed cycle writes no stamp and is retried, which only ever ADDS a later run on the - same date, never removes one. + `utc_anchored=False` reproduces the OLD (pre-UTC-anchoring) behaviour (both `TODAY` and `HOUR` + from LOCAL time), so the two can be compared on identical trigger lists. Every cycle here is + assumed to succeed -- a failed cycle writes no stamp and is retried, which only ever ADDS a + later run on the same date, never removes one. The strict `<` compare and `stamp < clock.date()` + below behave identically to the old `==` compare for any MONOTONICALLY forward-moving trigger + sequence (which every trigger list built by `_triggers` is) -- the two diverge only under a + clock rollback, which is covered separately by the real-script test + `test_clock_rollback_does_not_rerun_or_move_the_stamp_backwards`, not by this pure model. """ ran: list[datetime] = [] stamp: date | None = None for utc_instant, local_instant in triggers: clock = utc_instant if utc_anchored else local_instant - if clock.date() == stamp: + if stamp is not None and not (stamp < clock.date()): continue if clock.hour < sched_hour: continue @@ -278,8 +371,14 @@ def _run_gate( def test_exactly_one_run_per_utc_day_over_a_full_year(tz_name: str) -> None: """Over 13 months of real triggers, every UTC date gets exactly one cycle -- no more, no less. - This is the invariant the whole change rests on, stated as a property rather than as prose: - combined with `test_effective_bar_does_not_advance_until_0100_utc` (the newest visible daily + THIS TESTS A MODEL, not the shipped script (see the section banner above and the module + docstring) -- driving the real script over 13 months/~9600 triggers was measured to add + minutes to a sub-second suite. Trusting this test's result as a statement about + `keel-live-run.sh` is only valid because `test_the_simulated_gate_matches_the_real_script` + pins `_run_gate` to the real script over a curated adversarial sequence; if that test and this + one ever disagree in spirit, believe the real-script test. + + Combined with `test_effective_bar_does_not_advance_until_0100_utc` (the newest visible daily bar is constant across the entire eligible window), "exactly one run per UTC date" means "every daily bar evaluated exactly once". Two runs on one UTC date would be a DUPLICATE ENTRY on the live money path, because nothing downstream dedupes one. Zero runs would be a silently @@ -425,33 +524,144 @@ def test_run_script_gate_constants_match_the_simulated_gate() -> None: def test_run_script_reads_the_clock_in_utc() -> None: - """`TODAY` and `HOUR` are both derived with `date -u`. + """The RAW clock reads (`TODAY_RAW`, `HOUR_RAW`) -- and therefore `TODAY`/`HOUR` -- come from + `date -u`, never local time. The stamp and the hour gate MUST agree on which clock they are on. A UTC hour compared against a locally-stamped date would gate on one calendar and dedupe on another -- the worst of both, and it would not show up in the pure simulation above because that simulation gets its clock - from a parameter rather than from the script. + from a parameter rather than from the script. `TODAY`/`HOUR` are validated derivatives of + `TODAY_RAW`/`HOUR_RAW` (see A1 in the script's header), not independent `date` calls, so + pinning the two RAW reads is what actually pins the clock source. """ source = RUN_SCRIPT.read_text() - assert re.search(r"^TODAY=\"\$\(date -u '\+%Y-%m-%d'\)\"$", source, re.MULTILINE) - assert re.search(r"^HOUR=\"\$\(\(10#\$\(date -u '\+%H'\)\)\)\"$", source, re.MULTILINE) + assert re.search(r"^TODAY_RAW=\"\$\(date -u '\+%Y-%m-%d'\)\"$", source, re.MULTILINE) + assert re.search(r"^HOUR_RAW=\"\$\(date -u '\+%H'\)\"$", source, re.MULTILINE) + # 10# forces base 10: `date +%H` yields 08/09, which arithmetic would otherwise read as octal. + assert re.search(r'^HOUR="\$\(\(10#\$HOUR_RAW\)\)"$', source, re.MULTILINE) + +# -- harness: run the REAL script under a shimmed clock, with notifications recorded ----------- +# +# Every test below this point executes `keel-live-run.sh` VERBATIM (only `DIR=` and the literal +# osascript path are rewritten) so nothing here can drift from what actually ships. `_sandbox` +# builds the sandbox; `_run` fires one invocation of it at a chosen UTC instant. + + +@dataclass(frozen=True) +class Sandbox: + """Everything one `_sandbox(...)` call sets up, handed to `_run` for each invocation.""" + + script: Path + stamp: Path + outlog: Path + pendlog: Path + calls_log: Path # every argument string any "notification" call made, one per line + invocations_log: Path # one line per time the $KEEL stub actually ran, OUTSIDE logs/ on + # purpose -- the pre-flight test makes logs/ unwritable, and "was + # keel invoked at all" must stay observable even then. + env: dict[str, str] + + +#: Denies exec of the REAL notification binary at the OS level, independent of whatever the +#: script calls it by. This is defense IN DEPTH on top of the `/usr/bin/osascript` rewrite in +#: `_sandbox`: even if that rewrite ever fails to match (as it briefly must while TDD-red-testing +#: a not-yet-fixed script that does not use the `$OSASCRIPT` seam at all), this is what stands +#: between a test run and a real notification popping up on a machine that also trades real money. +_SANDBOX_EXEC = "/usr/bin/sandbox-exec" +_DENY_OSASCRIPT_PROFILE = ( + '(version 1)(allow default)(deny process-exec (literal "/usr/bin/osascript"))' +) -def _sandbox(tmp_path: Path, keel_exit_code: int) -> tuple[Path, Path]: - """Copy `keel-live-run.sh` into `tmp_path` with its deployment root repointed at the sandbox. - Only the `DIR=` assignment is rewritten; the gate, the stamp and the exit handling all run - VERBATIM, which is the point -- a test that reimplemented them would prove nothing about the - script that actually ships. `KEEL` is derived from `DIR` inside the script, so repointing - `DIR` also repoints the binary at our stub. +def _run_script(script: Path, *, env: dict[str, str]) -> subprocess.CompletedProcess[str]: + """Run `script` the way launchd would, except sandboxed against ever notifying for real. - Returns `(script, stamp)`. + Every real-script invocation in this file goes through here (via `_run`) rather than calling + `subprocess.run` directly, so there is exactly one place that could forget the sandbox. + """ + return subprocess.run( + [_SANDBOX_EXEC, "-p", _DENY_OSASCRIPT_PROFILE, "/bin/bash", str(script)], + capture_output=True, + text=True, + env=env, + ) + + +def _install_date_shim(bin_dir: Path) -> None: + """Install a `date` on `PATH` that reads its instant from `$KEEL_TEST_NOW` (epoch seconds) + instead of the wall clock, plus two failure modes A1 needs: `KEEL_TEST_DATE_MODE=empty` + (produces no output -- the empty-`date -u` case this hardware can produce) and `=garbage` + (produces non-date text). + + Honours ONLY the invocation forms `keel-live-run.sh` actually uses (`date -u '+FORMAT'`) -- + this is deliberately not a general `date(1)` replacement. + """ + bin_dir.mkdir(parents=True, exist_ok=True) + shim = bin_dir / "date" + shim.write_text( + "#!/bin/bash\n" + 'case "${KEEL_TEST_DATE_MODE:-fixed}" in\n' + " empty) exit 0 ;;\n" + ' garbage) printf "%s\\n" "${KEEL_TEST_DATE_GARBAGE:-not-a-date}"; exit 0 ;;\n' + ' *) exec /bin/date -u -r "$KEEL_TEST_NOW" "$@" ;;\n' + "esac\n" + ) + shim.chmod(shim.stat().st_mode | stat.S_IEXEC) + + +def _redirect_osascript(source: str, recorder: Path) -> str: + """Point the script's ONE reference to the real notification binary at a recorder instead. + + A plain string substitution rather than a regex on an `OSASCRIPT=` assignment, deliberately: + it works identically whether the script hardcodes the literal path inline (the pre-fix shape) + or holds it in the `$OSASCRIPT` constant (the fixed shape, A6) -- so the SAME harness code + runs the TDD-red captures against the unmodified script and the green checks against the + fixed one, with no separate code path to trust. + """ + count = source.count("/usr/bin/osascript") + assert count == 1, ( + "expected exactly one literal reference to /usr/bin/osascript -- if this drifted, a new " + "notification path may call the real binary unrewritten, which must never happen in a test" + ) + return source.replace("/usr/bin/osascript", str(recorder)) + + +def _sandbox( + tmp_path: Path, + keel_exit_code: int, + *, + signals: int = 0, + keel_stub_extra: str = "", +) -> Sandbox: + """Copy `keel-live-run.sh` into `tmp_path`, repointed at the sandbox and wired for testing. + + Two rewrites, both load-bearing for safety, not just convenience: + - `DIR="..."` -> `tmp_path`: the gate, the stamp and the exit handling all run VERBATIM, + which is the point -- a test that reimplemented them would prove nothing about the script + that actually ships. + - the literal `/usr/bin/osascript` -> a recorder script (see `_redirect_osascript`), so + tests can assert BOTH that a machine-is-broken condition alerts and that an ordinary + self-healing one does not, without ever risking a real notification. + + `signals`/`keel_stub_extra` customise the `$KEEL` stub: `signals` controls the `signals=N` the + stub's fake LoopResult line reports, and `keel_stub_extra` is shell text spliced in right + before the stub exits, so a test can make "a cycle ran" also DO something observable -- the + atomic-stamp tests use it to `chflags uchg` the stamp mid-cycle, simulating a write that fails + only after the pre-flight probe (a differently-named file) already passed. """ source = RUN_SCRIPT.read_text() patched, count = re.subn( r'^DIR="[^"]*"$', f'DIR="{tmp_path}"', source, count=1, flags=re.MULTILINE ) assert count == 1, "could not repoint DIR -- refusing to run a script aimed at the deployment" + + calls_log = tmp_path / "osascript-calls.log" + recorder = tmp_path / "osascript-recorder.sh" + recorder.write_text(f'#!/bin/bash\nprintf "%s\\n" "$*" >> "{calls_log}"\nexit 0\n') + recorder.chmod(recorder.stat().st_mode | stat.S_IEXEC) + patched = _redirect_osascript(patched, recorder) + # Belt and braces. This test executes a shell script that, unmodified, drives REAL MONEY # against ~/keel. If any reference to that path survives the rewrite, do not run it. assert "/Users/elmehdiaitbrahim/keel" not in patched @@ -460,42 +670,152 @@ def _sandbox(tmp_path: Path, keel_exit_code: int) -> tuple[Path, Path]: stub_dir = tmp_path / ".venv" / "bin" stub_dir.mkdir(parents=True, exist_ok=True) stub = stub_dir / "keel" - # Emits a LoopResult-shaped line with signals=0, so the notification path stays untaken and - # no osascript runs during the test. - stub.write_text(f"#!/bin/bash\nprintf 'mode=confirm signals=0\\n'\nexit {keel_exit_code}\n") + invocations_log = stub_dir / "keel.invocations" + stub.write_text( + "#!/bin/bash\n" + f'printf "%s\\n" "$*" >> "{invocations_log}"\n' + f"printf 'mode=confirm signals={signals}\\n'\n" + f"{keel_stub_extra}\n" + f"exit {keel_exit_code}\n" + ) stub.chmod(stub.stat().st_mode | stat.S_IEXEC) script = tmp_path / "keel-live-run.sh" script.write_text(patched) - return script, tmp_path / "logs" / ".keel-live-last-run" + date_bin = tmp_path / "shim-bin" + _install_date_shim(date_bin) -def _skip_before_sched_hour() -> None: - """Skip when the wall clock would make the script take its early-exit branch. + env = dict(os.environ) + env["PATH"] = f"{date_bin}:{env.get('PATH', '')}" + + return Sandbox( + script=script, + stamp=tmp_path / "logs" / ".keel-live-last-run", + outlog=tmp_path / "logs" / "keel-live.out.log", + pendlog=tmp_path / "logs" / "keel-live.pending.log", + calls_log=calls_log, + invocations_log=invocations_log, + env=env, + ) - These tests are about the STAMP, and the script legitimately refuses to do anything before - 01:00 UTC. Rather than override `SCHED_HOUR` in the sandbox -- which would test a script we do - not ship -- the one UTC hour a day where the two conflict is skipped. The hour gate itself is - covered by the pure simulation above, which does not depend on the clock. + +def _run( + sb: Sandbox, now_utc: datetime, *, date_mode: str = "fixed" +) -> subprocess.CompletedProcess[str]: + """Fire one invocation of the sandboxed script as though the clock read `now_utc`.""" + env = dict(sb.env) + env["KEEL_TEST_DATE_MODE"] = date_mode + env["KEEL_TEST_NOW"] = str(int(now_utc.timestamp())) + return _run_script(sb.script, env=env) + + +def _count_lines(path: Path) -> int: + """0 for a file that does not exist yet -- most of these logs start out absent.""" + if not path.exists(): + return 0 + return len(path.read_text().splitlines()) + + +def test_the_sandbox_never_points_at_the_live_deployment(tmp_path: Path) -> None: + """Guard on the guard: prove `_sandbox`'s rewrites really do relocate everything. + + Covers both rewrites every test in this file depends on for safety: `DIR=` (the money path) + and the literal `/usr/bin/osascript` (the notification path). If either survives, the tests + below are executing the live runner against real money, or could pop a real notification. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + body = sb.script.read_text() + assert "/Users/elmehdiaitbrahim/keel" not in body + assert f'DIR="{tmp_path}"' in body + assert "/usr/bin/osascript" not in body + assert os.path.commonpath([str(tmp_path), str(sb.script)]) == str(tmp_path) + + +# -- B2: pin the pure-Python model to the shipped script --------------------------------------- + + +def test_the_simulated_gate_matches_the_real_script(tmp_path: Path) -> None: + """Pins `_run_gate` (the pure-Python model) to the REAL `keel-live-run.sh`. + + `test_exactly_one_run_per_utc_day_over_a_full_year` only proves a property of the MODEL; this + is the test that makes trusting the model for that job legitimate. It replays a curated, + adversarial trigger sequence through the ACTUAL shipped script (via the `_sandbox`/`_run` + clock harness) and asserts, at EVERY trigger, that "did the real script run a cycle" equals + "did the model say it runs". + + A full 13-month/~9600-trigger real-script run was measured at roughly +2.5 minutes on a + ~10s suite (bash invocation ~3.3ms, the shimmed `date` ~5ms per call, several `date` calls per + invocation) -- not acceptable, so this sequence is curated rather than exhaustive. It covers: + three consecutive normal UTC days; the 00:20 UTC trigger below `SCHED_HOUR`; the full + spring-forward day (2026-03-08, 23 triggers, the hour-lost case); the full fall-back day + (2026-11-01, 25 triggers, including BOTH firings of the repeated local hour); and the + boot-after-outage catch-up sequence from + `test_the_old_local_date_gate_could_double_run_within_one_utc_day`. All of it runs through ONE + sandbox, replayed as a single sequence sorted by UTC instant (the order a real machine would + execute them in), so the stamp evolves exactly as it would across all these cases back to + back -- one continuous timeline is cheaper than one sandbox per scenario and just as faithful, + since the gate only ever compares ISO-date strings, never wall-clock elapsed time. """ - if datetime.now(UTC).hour < SCHED_HOUR: - pytest.skip("inside the 00:00-01:00 UTC window the script deliberately declines to run") + sb = _sandbox(tmp_path, keel_exit_code=0) + tz = ZoneInfo(DEPLOYMENT_TZ) + schedule = _plist_triggers() + + pairs: list[tuple[datetime, datetime]] = [] + + # The 00:20 UTC trigger, below SCHED_HOUR, then three consecutive normal UTC days at 01:20. + below_threshold = datetime(2026, 6, 15, 0, 20, tzinfo=UTC) + pairs.append((below_threshold, below_threshold)) + for day in (15, 16, 17): + t = datetime(2026, 6, day, 1, 20, tzinfo=UTC) + pairs.append((t, t)) + + # Spring-forward: local 02:00-02:59 does not exist -- 23 triggers. + pairs.extend(_triggers(SPRING_FORWARD, SPRING_FORWARD, tz, schedule)) + + # Fall-back: local 01:00-01:59 happens TWICE -- 25 triggers, both firings included. + pairs.extend(_triggers(FALL_BACK, FALL_BACK, tz, schedule)) + + # Boot-after-outage catch-up: identical to the dedicated regression test above. + all_triggers = _triggers(date(2026, 1, 15), date(2026, 1, 16), tz, schedule) + boot = datetime(2026, 1, 16, 1, 20, tzinfo=UTC) + pairs.extend(pair for pair in all_triggers if pair[0] >= boot) + + pairs.sort(key=lambda pair: pair[0]) + + model_ran = set(_run_gate(pairs, SCHED_HOUR, utc_anchored=True)) + + for utc_instant, _local in pairs: + before = _count_lines(sb.invocations_log) + _run(sb, utc_instant) + script_ran = _count_lines(sb.invocations_log) > before + model_says_ran = utc_instant in model_ran + assert script_ran == model_says_ran, ( + f"model/script disagreement at {utc_instant.isoformat()}: " + f"script ran={script_ran}, model said ran={model_says_ran}" + ) + + +# -- B4: the real script's failure-handling behaviour ------------------------------------------- def test_a_clean_cycle_stamps_the_utc_date_and_the_next_run_is_a_no_op(tmp_path: Path) -> None: """A successful cycle stamps today's UTC date; a second invocation does nothing. This is the dedupe, end to end, in the real shell -- the mechanism every characterization test - in `tests/test_agent.py` shows the consequences of losing. + in `tests/test_agent.py` shows the consequences of losing. Clock-shimmed rather than relying + on the wall clock (previously this test SILENTLY SKIPPED whenever CI happened to run inside + the 00:00-01:00 UTC window -- on the exact mechanism that is the sole barrier to duplicate + orders -- which is exactly backwards for a test this important). """ - _skip_before_sched_hour() - script, stamp = _sandbox(tmp_path, keel_exit_code=0) + sb = _sandbox(tmp_path, keel_exit_code=0) + now = datetime(2026, 6, 15, 1, 20, tzinfo=UTC) - first = subprocess.run(["/bin/bash", str(script)], capture_output=True, text=True) + first = _run(sb, now) assert first.returncode == 0 - assert stamp.read_text().strip() == datetime.now(UTC).strftime("%Y-%m-%d") + assert sb.stamp.read_text().strip() == "2026-06-15" - second = subprocess.run(["/bin/bash", str(script)], capture_output=True, text=True) + second = _run(sb, now) assert second.returncode == 0 assert "already ran" in second.stdout assert "UTC" in second.stdout, "the skip message must say which calendar it is talking about" @@ -508,26 +828,205 @@ def test_a_failed_cycle_writes_no_stamp_so_the_next_trigger_retries(tmp_path: Pa recorded as a quiet "no signals today", and the next of the day's 23 remaining triggers must pick it up. The cost of getting this backwards is a silently skipped trading day. """ - _skip_before_sched_hour() - script, stamp = _sandbox(tmp_path, keel_exit_code=3) - - result = subprocess.run(["/bin/bash", str(script)], capture_output=True, text=True) + sb = _sandbox(tmp_path, keel_exit_code=3) + now = datetime(2026, 6, 15, 1, 20, tzinfo=UTC) + result = _run(sb, now) assert result.returncode == 3, "the script must surface the cycle's exit code, not mask it" - assert not stamp.exists(), "a failed cycle must leave the day unstamped so it is retried" + assert not sb.stamp.exists(), "a failed cycle must leave the day unstamped so it is retried" - retried = subprocess.run(["/bin/bash", str(script)], capture_output=True, text=True) + retried = _run(sb, now) assert retried.returncode == 3 assert "already ran" not in retried.stdout -def test_the_sandbox_never_points_at_the_live_deployment(tmp_path: Path) -> None: - """Guard on the guard: prove the rewrite in `_sandbox` really does relocate everything. +def test_unwritable_logs_dir_means_the_cycle_never_runs(tmp_path: Path) -> None: + """Finding 2 (HIGH), the reviewer's exact reproduction, inverted. - If this ever fails, the two tests above are executing the live runner against real money. + With a read-only logs dir the OLD script ran the cycle anyway, left the stamp ABSENT, exited + 0, and the next trigger ran a SECOND full cycle -- a duplicate real-money order, since nothing + downstream dedupes an entry (see the module docstring). The pre-flight probe must catch this + BEFORE `$KEEL` is ever invoked: a lost stamp then costs a missed trading day (recoverable), not + a duplicate order (not recoverable). """ - script, _ = _sandbox(tmp_path, keel_exit_code=0) - body = script.read_text() - assert "/Users/elmehdiaitbrahim/keel" not in body - assert f'DIR="{tmp_path}"' in body - assert os.path.commonpath([str(tmp_path), str(script)]) == str(tmp_path) + sb = _sandbox(tmp_path, keel_exit_code=0) + logs_dir = tmp_path / "logs" + original_mode = logs_dir.stat().st_mode + logs_dir.chmod(0o555) + try: + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode != 0, "an unpersistable stamp must not exit 0" + assert _count_lines(sb.invocations_log) == 0, "keel must never be invoked pre-flight" + assert sb.calls_log.exists() and sb.calls_log.read_text().strip(), ( + "a condition the machine cannot self-heal must alert a human" + ) + finally: + logs_dir.chmod(original_mode) + + +def test_atomic_stamp_write_leaves_yesterdays_stamp_intact_on_failure(tmp_path: Path) -> None: + """Finding 2 (HIGH): a torn/failed post-cycle write must never leave the stamp EMPTY or PARTIAL. + + Plain `> "$STAMP"` truncates before it writes, so a write that dies partway leaves an EMPTY + stamp -- and an empty stamp reads as "never ran", re-running a UTC day that already traded. + Here the write is forced to fail AFTER the pre-flight probe (a differently-named file) has + already passed, by making the stamp file itself immutable partway through the "cycle" -- and + the pre-existing YESTERDAY stamp must survive completely unchanged: not empty, not today, not + partial. That is what the temp-file-then-`mv -f` design buys: a rename either fully happens or + fully does not. + """ + stamp_path = tmp_path / "logs" / ".keel-live-last-run" + yesterday = "2026-06-14" + sb = _sandbox(tmp_path, keel_exit_code=0, keel_stub_extra=f'chflags uchg "{stamp_path}"') + stamp_path.write_text(yesterday + "\n") + try: + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode != 0 + assert stamp_path.read_text().strip() == yesterday, ( + "the stamp must never be corrupted by a failed write -- it must read exactly what it " + "read before the cycle ran" + ) + finally: + subprocess.run(["chflags", "nouchg", str(stamp_path)], check=False) + + +def test_stamp_write_failure_is_not_swallowed(tmp_path: Path) -> None: + """Finding 2 (HIGH): a failed stamp write must be LOUD, not swallowed. + + The old script discarded `> "$STAMP"`'s exit status entirely and always `exit`ed with keel's + own (successful) status, so a write failure looked identical to a normal, correctly-stamped + day. The only way an operator finds out is a notification and a nonzero exit; without both, + the next trigger runs a second cycle believing today needs (re-)trading, when an order from + today's first cycle may already be sitting on the exchange. + """ + stamp_path = tmp_path / "logs" / ".keel-live-last-run" + sb = _sandbox(tmp_path, keel_exit_code=0, keel_stub_extra=f'chflags uchg "{stamp_path}"') + stamp_path.write_text("2026-06-14\n") + try: + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode != 0, "a stamp write failure must not exit 0" + assert sb.calls_log.exists() and sb.calls_log.read_text().strip(), ( + "a stamp write failure must alert a human -- silence here IS the Finding-2 bug" + ) + finally: + subprocess.run(["chflags", "nouchg", str(stamp_path)], check=False) + + +def test_empty_clock_output_refuses_to_run(tmp_path: Path) -> None: + """Finding 3 (MED): `date -u` returning EMPTY must not silently read as "already ran, forever". + + On this hardware `$((10#$(date -u '+%H')))` on empty input evaluates to 0, not an error, so an + unvalidated empty clock gives `TODAY=""`/`HOUR=0` -- and a missing stamp file ALSO reads as "" + (`cat ... 2>/dev/null || true`), so `[ "" = "" ]` (or the new `[[ "" < "" ]]` -> false, same + effect) reads as "already ran". That makes the detector dead FOREVER, silently, because the + failure mode looks exactly like success. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC), date_mode="empty") + assert result.returncode != 0 + assert _count_lines(sb.invocations_log) == 0, "a broken clock must never reach a cycle" + assert not sb.stamp.exists(), "a broken clock must not be recorded as a completed day" + assert "already ran" not in result.stdout, ( + "the empty-clock bug makes this claim true BY ACCIDENT -- it must never be printed here" + ) + assert sb.calls_log.exists() and sb.calls_log.read_text().strip() + + +def test_garbage_clock_output_refuses_to_run(tmp_path: Path) -> None: + """Finding 3 (MED): `date -u` returning GARBAGE must be rejected the same way EMPTY is. + + Not every clock failure produces empty output -- a broken locale, a corrupted `/etc/localtime`, + or a flaky `date` binary could just as easily produce text that is not a date at all. Anything + that is not exactly `^[0-9]{4}-[0-9]{2}-[0-9]{2}$` / `^[0-9]{2}$` must be rejected, not just + the empty case. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC), date_mode="garbage") + assert result.returncode != 0 + assert _count_lines(sb.invocations_log) == 0 + assert not sb.stamp.exists() + assert "already ran" not in result.stdout + assert sb.calls_log.exists() and sb.calls_log.read_text().strip() + + +def test_malformed_stamp_content_refuses_to_run(tmp_path: Path) -> None: + """Finding 4 (MED): a corrupt on-disk stamp must never be silently COMPARED against today. + + `"garbage" < "2026-06-15"` is FALSE in a plain string compare, which reads exactly like + "already ran" and disables the detector forever -- the same failure class as an unvalidated + empty clock, just entered from the stamp file instead of `date`. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + sb.stamp.write_text("not-a-date\n") + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode != 0 + assert _count_lines(sb.invocations_log) == 0 + assert sb.stamp.read_text().strip() == "not-a-date", "a malformed stamp must not be overwritten" + assert sb.calls_log.exists() and sb.calls_log.read_text().strip() + + +def test_clock_rollback_does_not_rerun_or_move_the_stamp_backwards(tmp_path: Path) -> None: + """Finding 4 (MED): a clock reading a PAST date (bad RTC before NTP settles) must not re-run. + + `RunAtLoad` fires immediately on boot, potentially before NTP has corrected a bad real-time + clock. With the OLD `=` compare, a bogus past date is "not today", so the cycle RUNS and + stamps the bogus date; when the clock then corrects forward, the real date no longer matches + that bogus stamp, so the cycle runs AGAIN -- re-evaluating, and potentially re-entering, a bar + it already traded. The fix requires the stamp to be STRICTLY BEFORE today, so a stamp equal to + OR ahead of today both read as "done" -- and the stamp itself must never move backwards. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + x = datetime(2026, 6, 15, 1, 20, tzinfo=UTC) + months_in_the_past = datetime(2026, 1, 10, 1, 20, tzinfo=UTC) + x_plus_1 = datetime(2026, 6, 16, 1, 20, tzinfo=UTC) + + first = _run(sb, x) + assert first.returncode == 0 + assert sb.stamp.read_text().strip() == "2026-06-15" + ran_once = _count_lines(sb.invocations_log) + + _run(sb, months_in_the_past) + assert _count_lines(sb.invocations_log) == ran_once, "a clock in the past must not run a cycle" + assert sb.stamp.read_text().strip() == "2026-06-15", "the stamp must never move backwards" + + _run(sb, x) + assert _count_lines(sb.invocations_log) == ran_once, ( + "the stamp's own date, re-seen, must not re-run either" + ) + assert sb.stamp.read_text().strip() == "2026-06-15" + + _run(sb, x_plus_1) + assert _count_lines(sb.invocations_log) == ran_once + 1, "the day after must run exactly once" + assert sb.stamp.read_text().strip() == "2026-06-16" + + +def test_pendlog_is_utc_labelled(tmp_path: Path) -> None: + """Finding 10: PENDLOG's timestamp must say UTC, like every other line in this script. + + It used to be plain `date` (LOCAL, unlabelled) next to lines that are otherwise all `date -u` + -- a trap for an operator reading logs at 2am, unsure which midnight a PENDING signal is even + relative to. + """ + sb = _sandbox(tmp_path, keel_exit_code=0, signals=2) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode == 0 + pending = sb.pendlog.read_text() + assert "UTC" in pending + assert re.search(r"\d{4}-\d{2}-\d{2} \d{2}:\d{2} UTC", pending) + + +def test_no_pending_notification_on_a_failed_cycle(tmp_path: Path) -> None: + """A4: acting on a PENDING prompt from a FAILED cycle bypasses the stamp and duplicates entry. + + Per the header's COROLLARY, "run the agent interactively to approve" tells the operator to do + the one thing that skips this script's stamp entirely. Firing that prompt off a cycle that did + not even complete -- whose `signals=N` may be parsed from partial or garbled output -- is a + direct path to a duplicate live order. The fix only takes the PENDING-notification path when + the cycle's own exit status is clean; an ordinary nonzero keel exit still gets an OUTLOG line + (see `test_a_failed_cycle_writes_no_stamp_so_the_next_trigger_retries`), just not this prompt. + """ + sb = _sandbox(tmp_path, keel_exit_code=3, signals=2) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode == 3 + calls = sb.calls_log.read_text() if sb.calls_log.exists() else "" + assert "run the agent interactively" not in calls From bdef825b2d4b381921aff16f2471903c0008a64d Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Thu, 6 Aug 2026 19:40:07 -0400 Subject: [PATCH 3/4] fix(agent): withhold ALL entries when any bar is unconfirmed, and alert a stuck detector Three defects found by an adversarial review of this PR. The first is critical and was mine. CRITICAL -- the entry gate placed orders and THEN failed the cycle, so the retry duplicated them. The gate was a per-RULE filter inside the per-PRODUCT loop, and `engine.evaluate` + `executor.execute` ran inside that same iteration. `blocked_entries` was only RECORDED, never consulted before execution. So a product examined earlier had already placed real orders by the time a later product's rule was found not ready. The cycle then exited 4, the runner correctly declined to stamp, and the next hourly trigger re-ran the WHOLE cycle against the same daily bar -- re-placing everything that had already traded: 01:20 blocked=1 (XLM turtle) -> exit 4 -> no stamp BTC BUY orders: 1 ($50 DCA) 02:20 blocked=0 BTC BUY orders: 2 <-- DUPLICATE 03:20 vetoed by per_asset_concentration_cap (the rails catch only the THIRD) This is the modal shape, not an edge case: `poll_once` fetches per `(product, granularity)` and `candles_by_tf` is per-product, so "P has published, Q has not" is exactly the condition at :20 past the hour, and the BTC DCA fires deterministically every 7 days. keel-live-run.sh's own header states the principle this violated -- "Exiting nonzero AFTER a cycle has already run does not prevent that duplicate ... refuse to trade when we cannot record that we traded". `run_once` is now two passes. A PRE-PASS over every (product, rule) pair computes readiness and `entries_allowed = not blocked_entries` BEFORE any execution; the MAIN PASS runs exits for every non-stale product unconditionally, and evaluates entries only when `entries_allowed`. Entry admission has to be atomic with respect to the cycle's exit status, because that status is a single bit the runner uses to decide whether to stamp the UTC day -- a partially-executed cycle plus a nonzero exit is the worst of both. The cost, stated plainly: one lagging product now delays EVERY entry that cycle, including entries whose own data was fresh. That is the intended trade -- a delayed entry is recoverable within <= 60 minutes by the next trigger, a duplicate live entry is not -- and it is what makes the retry IDEMPOTENT, which is what gives "<= 60 minutes of delay" its meaning. The stale-product skip deliberately still runs FIRST, so a dead venue or a delisted product is skipped as stale before the freshness gate sees it and cannot halt the whole cycle's entries. MED, a regression this PR introduced -- the monotonic compare turned a FORWARD clock excursion into a permanent silent outage. Making the compare `<` fixed rollback and broke roll-forward: 2026-08-06 01:20 runs, stamps 2026-08-06 2035-01-01 03:20 (bad RTC before NTP, RunAtLoad) runs, stamps 2035-01-01 2026-08-07..11 "stamp is not before today -- skipping" rc=0, no alert, until 2035 Under the old `=` compare this self-healed the next day. A stamp strictly AHEAD of today is corrupt state, not an ordinary "already ran", so it now notifies and exits 67 -- distinct from 65 (not a date at all) so an operator can tell them apart. A stamp EQUAL to today stays a silent exit 0, so the common path does not start over-alerting. Rollback protection survives: the cycle still does not re-run, it now alerts instead of skipping silently. `tests/test_schedule.py` asserted in prose that `<` and `=` "diverge only under a clock rollback". That claim was false -- they also diverge on a forward excursion -- and the false claim is exactly why no test covered this. Corrected, and the differential test's curated sequence now includes a forward jump. MED -- nothing ever escalated a stuck detector. A nonzero keel exit deliberately does not notify (it is normally a self-healing publication lag), but that meant 23 consecutive failing triggers produced ZERO notifications, and a stuck detector was indistinguishable from a quiet day with no signals. That matters more now that ANY unconfirmed product withholds the whole cycle. A consecutive-failure counter next to the stamp now alerts at 3 in a row and every 3 after, resetting on a verified clean stamp. It is guarded so a bug in it degrades to "stops escalating", never to "stops trading" or "hides that a cycle failed". Also: trimmed an overstated claim in tests/test_rule_manifest.py. It asserts the COMMITTED manifest, not a deployment DB, so it catches a reseeded box's state being COMMITTED, not the reseed itself. `rule_manifest.py apply` is what catches that live. Co-Authored-By: Claude Opus 5 (1M context) --- keel-live-run.sh | 167 ++++++++++++++++++---- keel/agent.py | 136 +++++++++++++----- tests/test_agent.py | 276 ++++++++++++++++++++++++++++++++++++ tests/test_rule_manifest.py | 10 ++ tests/test_schedule.py | 268 +++++++++++++++++++++++++++++++--- 5 files changed, 773 insertions(+), 84 deletions(-) diff --git a/keel-live-run.sh b/keel-live-run.sh index 7feb1856..f099fefa 100755 --- a/keel-live-run.sh +++ b/keel-live-run.sh @@ -98,14 +98,28 @@ # 66 -- the day-stamp could not be proven persistable before running a cycle (pre-flight), or # could not be verified written back after one (post-cycle). See the PRE-FLIGHT and # ATOMIC STAMP WRITE comments below for why there are two layers and which one matters. +# 67 -- the on-disk stamp is a well-formed date but is STRICTLY AHEAD of today. That is not the +# ordinary "already ran" case (stamp equal to today) -- it means either the clock read +# forward before NTP settled, or the stamp file is otherwise corrupt, and treating it as +# "already ran" would silently disable the detector until the real clock catches up to the +# bogus stamp, which could be years. Distinct from 65 (stamp is not a date at all) so an +# operator can tell the two apart at a glance -- see A2, part two, below. # -# NOTIFICATION POLICY. A macOS notification fires ONLY for a condition the machine cannot -# self-heal without a human: exit codes 64/65/66 above. An ordinary NONZERO exit from keel itself -# (e.g. the venue has not yet published the bar this cycle needs) is EXPECTED and SELF-HEALING -- -# one of the remaining hourly triggers retries it, and the OUTLOG line below is enough of a -# record -- so it does NOT notify. Notifying 23 times a day for a condition that resolves itself -# on its own would train the operator to ignore notifications, which defeats the ones that -# actually need a human. +# NOTIFICATION POLICY. A macOS notification fires for two kinds of thing: +# (a) a condition the machine cannot self-heal without a human touching it -- exit codes +# 64/65/66/67 above; and +# (b) a detector that has been failing an ORDINARY nonzero exit from keel itself for +# $ESCALATE_EVERY consecutive triggers or more, and on every further multiple of +# $ESCALATE_EVERY after that (see the consecutive-failure counter near the bottom of this +# script). A SINGLE ordinary nonzero exit (e.g. the venue has not yet published the bar this +# cycle needs) is EXPECTED and SELF-HEALING -- one of the remaining hourly triggers retries +# it, and the OUTLOG line below is enough of a record -- so it does NOT notify by itself. +# Notifying on every one of 23 triggers a day for a condition that usually resolves itself +# would train the operator to ignore notifications, which defeats the ones that actually +# need a human. But a detector still failing after that many tries in a row is no longer +# "usual publication lag", and a chronically stuck detector that never notifies is +# indistinguishable from a quiet day with no signals -- which is its own silent-failure mode, +# the same class as 64/65/66/67, just reached by a different door. # # TOCTOU (Finding 8, OPTIONAL, not closed). Between reading $STAMPED and writing $STAMP, two # CONCURRENT invocations of this script could both pass the gate and both run a cycle -- `flock` @@ -127,6 +141,11 @@ DB="keel-live.db" OUTLOG="$DIR/logs/keel-live.out.log" PENDLOG="$DIR/logs/keel-live.pending.log" STAMP="$DIR/logs/.keel-live-last-run" +# A8 (Defect 2, MED). Consecutive-failure counter, next to $STAMP rather than inside it, so the +# stamp's own format -- a single ISO date, load-bearing for the A2 compare below -- never has to +# also carry an integer. See the increment/reset sites near the bottom of this script and the +# NOTIFICATION POLICY paragraph above. +FAILCOUNT="$STAMP.failures" # The one seam every macOS notification in this script goes through. Same purpose as the `DIR=` # rewrite tests/test_schedule.py::_sandbox already relies on: it lets the schedule tests swap in a # recorder and assert BOTH that a machine-is-broken condition alerts and that an ordinary @@ -136,16 +155,38 @@ OSASCRIPT="/usr/bin/osascript" # withholding the daily bar that closed at 00:00 UTC. See the header. This is a UTC hour, and it # is only meaningful because TODAY below is a UTC date too -- change one and you must change both. SCHED_HOUR=1 +# A8 threshold: notify once a stuck detector has failed this many triggers IN A ROW, and again on +# every further multiple (6, 9, ...). See the increment site near the bottom of this script for why +# a repeating multiple, not a single one-shot alert. +ESCALATE_EVERY=3 cd "$DIR" || exit 1 -# Single seam for every macOS alert this script can raise, so the alert-worthy paths (64/65/66) -# all read the same and none of them can forget the `2>/dev/null || true` that keeps a notify -# failure from ever masking the exit code it is reporting on. +# Single seam for every macOS alert this script can raise, so the alert-worthy paths +# (64/65/66/67, plus the A8 escalation below) all read the same and none of them can forget the +# `2>/dev/null || true` that keeps a notify failure from ever masking the exit code it is +# reporting on. notify() { "$OSASCRIPT" -e "display notification \"$1\" with title \"keel-live\" subtitle \"supervised live\" sound name \"Glass\"" 2>/dev/null || true } +# A8. Read the consecutive-failure counter, guarded so ANY problem reading it -- the common case +# of the file not existing yet (a healthy detector has none), a permissions problem, or someone +# having hand-edited it to non-numeric junk -- reads as 0 rather than aborting the script or +# corrupting the retry path this file exists to support. This function, and both call sites below, +# must never be able to change $STATUS or block a retry: the failure counter is an ALERTING +# convenience, not a second correctness mechanism, and a bug in it must degrade to "stops +# escalating" rather than "stops trading" or "hides that a cycle failed". +read_failcount() { + local n + n="$(cat "$FAILCOUNT" 2>/dev/null || true)" + if [[ "$n" =~ ^[0-9]+$ ]]; then + printf '%s' "$n" + else + printf '0' + fi +} + TODAY_RAW="$(date -u '+%Y-%m-%d')" HOUR_RAW="$(date -u '+%H')" @@ -186,20 +227,49 @@ if [ -n "$STAMPED" ] && ! [[ "$STAMPED" =~ ^[0-9]{4}-[0-9]{2}-[0-9]{2}$ ]]; then exit 65 fi -# A2, part two: the compare is STRICTLY LESS THAN, not EQUALS. A Mac that boots with a bad RTC -# before NTP settles (RunAtLoad fires immediately, before the clock is trustworthy) can read a -# date in the PAST. With `=` that reads as "not today", the cycle RUNS and stamps the bogus past -# date; when the clock then corrects forward, the real date differs from that bogus stamp so the -# cycle runs AGAIN -- re-evaluating a bar it already traded, a second entry on the live money -# path. Requiring the stamp to be STRICTLY BEFORE today closes both directions: a stamp equal to -# today (ordinary "already ran") and a stamp AHEAD of today (clock rolled back after a correct -# stamp) both read as "done, do not run" -- neither should trigger a second cycle. +# A2, part two: a stamp that is not BEFORE today splits into two outcomes, not one. A Mac that +# boots with a bad RTC before NTP settles (RunAtLoad fires immediately, before the clock is +# trustworthy) can read a date in the PAST. With the OLD `=` compare that read as "not today", the +# cycle RAN and stamped the bogus past date; when the clock then corrected forward, the real date +# differed from that bogus stamp so the cycle ran AGAIN -- re-evaluating a bar it already traded, a +# second entry on the live money path. Requiring the stamp to be STRICTLY BEFORE today (`<`, not +# `=`) closed that: a stamp AHEAD of today (clock rolled back after a correct stamp) now reads as +# "done, do not run", same as a stamp equal to today. +# +# But collapsing "ahead" and "equal" into a single silent skip is itself a regression this same fix +# must not repeat, because a bad RTC is not only ever wrong in the PAST direction. RunAtLoad firing +# before NTP settles can just as easily read the clock FORWARD -- e.g. a default/garbage RTC date +# of 2035. That runs a cycle and stamps a date years ahead of real time; every real trigger +# afterwards then has a correctly-read TODAY that is, and stays, BEHIND that bogus stamp, so +# `! [[ "$STAMPED" < "$TODAY" ]]` is true FOREVER -- a silent, self-perpetuating outage that looks +# exactly like "already ran today", every single trigger, until the real clock catches up to the +# bogus stamp years later. Under the OLD `=` compare this self-healed the very next real day +# (STAMPED != TODAY, so the cycle ran and re-stamped the correct date); the `<` compare above traded +# that self-healing away for the rollback fix, and nothing caught the trade until now. +# +# So: a stamp STRICTLY AHEAD of today is no longer treated as "already ran". It is corrupt state, +# the same family as a stamp that is not a date at all (A2 part one, exit 65) -- something is wrong +# with the clock or the stamp file, and it needs a human, not a silent skip. A distinct exit code +# (67, not a reuse of 65) lets an operator tell the two apart at a glance: 65 says "go inspect the +# stamp file", 67 says "go check the clock (and, only if that is sane, then the stamp file)" -- +# collapsing them into one code would cost that distinction for free. The rollback protection is +# unaffected: the stamp still never moves backwards and a rolled-back clock still never re-runs the +# cycle -- it now ALERTS instead of skipping silently, which is strictly better for the identical +# behaviour. +# # ISO-8601 dates sort lexicographically, so a plain string comparison gives us date comparison for -# free. `<` inside `[[ ]]` is a bash STRING comparison, which is what we want here; the same `<` -# inside a POSIX `[ ]` is output redirection and would silently truncate a file instead of -# comparing -- `[[ ]]` is not a style choice on this line, it is the only correct spelling. -if [ -n "$STAMPED" ] && ! [[ "$STAMPED" < "$TODAY" ]]; then - printf '%s [keel-live] stamp (%s) is not before today (%s) -- already ran, or the clock moved backward -- skipping\n' \ +# free. `<`/`>`/`=` inside `[[ ]]` are bash STRING comparisons, which is what we want here; `<`/`>` +# inside a POSIX `[ ]` are output/input redirection and would silently mangle a file instead of +# comparing -- `[[ ]]` is not a style choice on these lines, it is the only correct spelling. +if [ -n "$STAMPED" ] && [[ "$STAMPED" > "$TODAY" ]]; then + notify "keel-live: the day-stamp (${STAMPED}) is AHEAD of today (${TODAY}) -- refusing to run a cycle. This means either the clock read forward before NTP settled, or the stamp file is corrupt; investigate ${STAMP} and the system clock before the next trigger. Nothing has been run and the stamp has not been touched." + printf '%s [keel-live] stamp (%s) is AHEAD of today (%s) -- refusing to run, stamp not overwritten -- exit 67\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMPED" "$TODAY" + exit 67 +fi + +if [ -n "$STAMPED" ] && [ "$STAMPED" = "$TODAY" ]; then + printf '%s [keel-live] stamp (%s) equals today (%s) -- already ran this UTC day -- skipping\n' \ "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMPED" "$TODAY" exit 0 fi @@ -280,7 +350,14 @@ if [ "$STATUS" -eq 0 ]; then if { printf '%s\n' "$TODAY" >"$STAMP_TMP"; } 2>/dev/null \ && mv -f "$STAMP_TMP" "$STAMP" 2>/dev/null \ && [ "$(cat "$STAMP" 2>/dev/null || true)" = "$TODAY" ]; then - : # stamped and verified + # A8, reset. A clean, VERIFIED stamp write means the detector is healthy again -- zero the + # consecutive-failure counter so a later, unrelated single failure starts counting from zero + # rather than continuing from wherever a much earlier, already-resolved outage left off. A + # missing counter file reads as 0 (see read_failcount), so `rm -f` IS the reset; guarded the + # same way as everything else touching $FAILCOUNT -- if the remove itself fails, the next + # escalation check simply starts from a stale (higher) count, which only means "alerts a little + # sooner than strictly necessary next time", never "misses" or "blocks" anything. + rm -f "$FAILCOUNT" 2>/dev/null || true else rm -f "$STAMP_TMP" 2>/dev/null || true notify "keel-live: the day-stamp write FAILED after a cycle already ran -- an order may already be placed. INVESTIGATE ${STAMP} IMMEDIATELY before the next trigger." @@ -290,10 +367,46 @@ if [ "$STATUS" -eq 0 ]; then fi else # Only a clean cycle counts as "this UTC day is done"; anything else leaves the day open for - # one of the remaining hourly triggers to retry. Deliberately NOT a notification -- see - # NOTIFICATION POLICY at the top: a nonzero keel exit is an expected, self-healing condition - # (e.g. the venue has not published the bar yet), and the OUTLOG line is enough of a record. + # one of the remaining hourly triggers to retry. Deliberately NOT a notification by itself -- see + # NOTIFICATION POLICY at the top: a single nonzero keel exit is an expected, self-healing + # condition (e.g. the venue has not published the bar yet), and the OUTLOG line is enough of a + # record for that case. printf '%s [keel-live] cycle exited %d -- not stamping, will retry\n' \ "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STATUS" >>"$OUTLOG" + + # A8, increment (Defect 2, MED). A single failed trigger is expected and self-healing, but + # NOTHING ELSE in this script ever escalates a detector that keeps failing -- 23 consecutive + # nonzero exits in one UTC day would otherwise produce zero notifications, indistinguishable from + # a quiet day with no signals. Count consecutive failures and alert once the run is long enough + # that "publication lag" stops being a plausible explanation. + # + # The read-modify-write below is guarded end to end: `read_failcount` cannot return anything but + # a plain non-negative integer, and the write goes through the same temp-file-then-`mv -f` pattern + # as the day-stamp itself so a torn write can never leave $FAILCOUNT truncated into something + # read_failcount would misparse as a smaller number and under-count. If the write fails outright, + # this cycle's failure simply goes uncounted -- the counter under-reports rather than corrupts, + # and, critically, NONE of this can reach `exit`: a bug here must degrade to "the escalation alert + # is late or missing", never to "the retry did not happen" or "the exit status changed". + FAILS="$(($(read_failcount) + 1))" + FAILCOUNT_TMP="$FAILCOUNT.tmp.$$" + if { printf '%s\n' "$FAILS" >"$FAILCOUNT_TMP"; } 2>/dev/null \ + && mv -f "$FAILCOUNT_TMP" "$FAILCOUNT" 2>/dev/null; then + : # counter persisted + else + rm -f "$FAILCOUNT_TMP" 2>/dev/null || true + fi + + # Escalate on the Nth consecutive failure, and again on every FURTHER multiple of N (2N, 3N, ...) + # -- deliberately not once-and-done. A one-shot alert that then goes quiet forever would let a + # detector stuck for a week look, after the first night, exactly like one that self-healed after + # three tries: the operator has no way to tell "resolved" from "still broken, already told you" + # without going and checking. Repeating on a multiple keeps a genuinely stuck detector shouting + # for as long as it stays stuck, while the modulo means it still only fires once per N tries, not + # once per trigger -- 23 failures a day still produces a handful of alerts, not 23. + if [ "$((FAILS % ESCALATE_EVERY))" -eq 0 ]; then + notify "keel-live: ${FAILS} consecutive cycles have failed (latest exit ${STATUS}) -- this is no longer ordinary publication lag. Check ${OUTLOG}." + printf '%s [keel-live] escalation: %d consecutive failures -- notified\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$FAILS" >>"$OUTLOG" + fi fi exit "$STATUS" diff --git a/keel/agent.py b/keel/agent.py index fca661eb..8e5d9d82 100644 --- a/keel/agent.py +++ b/keel/agent.py @@ -821,6 +821,9 @@ def run_once( exit_results: list[ExecutionResult] = [] stale_products: list[str] = [] blocked_entries: list[BlockedEntry] = [] + # Built once per product in the pre-pass below and reused by the main pass, so a + # product's series is read from the DB exactly once per cycle rather than twice. + candles_by_tf_by_product: dict[str, dict[Granularity, list[Any]]] = {} # Reconcile FIRST, before equity and before any entry. A bracket that filled since the # last cycle has already changed the position and the cash balance; reading equity or @@ -912,10 +915,51 @@ def run_once( # not trading, so paper entries are skipped this cycle instead, below. paper_equity = equity_now if paper_trader is not None else None + # == PRE-PASS: decide entry admission for the WHOLE CYCLE, before any order goes out ==== + # + # Finding 1 (HIGH) was closed at the wrong GRANULARITY: `entry_bar_ready` was correct, + # but it used to gate `ready_rules` PER PRODUCT, inside the very loop that also called + # `executor.execute` for that product's signals. A cycle could place a real order for + # product A and only THEN discover, a few iterations later, that product B's confirming + # bar hadn't arrived -- `blocked_entries` ended up correctly non-empty, but nothing had + # consulted it before A's order was already live. + # + # WHY this has to be whole-cycle, not per-product: `keel-live-run.sh` reads this cycle's + # exit status as a SINGLE bit and decides off that alone whether to stamp the UTC day -- + # it has no way to ask "which orders, if any, did that cycle place". A's order placed + # plus a nonzero exit (because B was blocked) is the worst of both worlds: an order is + # live AND the day is left unstamped, so the next hourly trigger retries the WHOLE cycle + # against the SAME daily bar and re-enters everything that already traded, A included. + # Entry admission therefore has to be ATOMIC with the exit status that gates the + # day-stamp -- decided once, for every product, before `executor.execute`/`_paper_enter` + # runs for any of them, not resolved product-by-product as each reaches the front of the + # loop. + # + # THE COST, stated plainly: one lagging product now delays EVERY entry this cycle, + # including ones whose own data was perfectly fresh. That trade is deliberate -- a + # withheld entry is recovered by the very next hourly trigger, at most ~60 minutes + # later; a duplicate live entry is not recoverable at all. Paying a bounded, known delay + # to avoid an unbounded, unrecoverable duplication is the trade this whole module exists + # to make. + # + # This is also what makes the runner's retry IDEMPOTENT, which is the property that + # gives "<= 60 minutes of delay" its meaning: a blocked cycle places nothing and (via + # `keel-live-run.sh`'s exit-4 contract) leaves the day unstamped, so the retry an hour + # later starts from "nothing happened yet", not "something happened and needs to happen + # again". Without that idempotence, "delay" is just a duplicate that hasn't landed yet. + # + # EXITS are deliberately exempt from all of this -- see the main pass below. for product_id in products: if finest is not None and not market_feed.is_fresh( repo, product_id, finest, now_ts, max_age_sec ): + # Stale-product skip stays FIRST and still `continue`s past the product + # entirely, exactly as before this pre-pass existed -- load-bearing ordering, + # independently validated: a dead venue or a delisted product reads as stale + # here and is skipped WITHOUT ever reaching the readiness gate below, so it can + # never block the whole cycle's entries just by being permanently absent from + # the feed. Only a product that IS being polled, and is merely a bar or two + # behind, can withhold the cycle. stale_products.append(product_id) log_event( logger, @@ -929,46 +973,14 @@ def run_once( product_rules = [r for r in rules if getattr(r, "product_id", None) == product_id] candles_by_tf = {g: repo.get_candles(product_id, g) for g in granularities} + candles_by_tf_by_product[product_id] = candles_by_tf - if paper_trader is not None: - _paper_resolve_bars(paper_trader, product_id, candles_by_tf, granularities) - - product_exit_results = _handle_exits( - product_id, product_rules, candles_by_tf, repo, broker, config, mode, now_ts, - confirm_fn=confirm_fn, - ) - for exit_result in product_exit_results: - log_event( - logger, - logging.INFO, - "agent.exit_evaluated", - product=product_id, - placed=exit_result.placed, - reason=exit_result.reason, - ) - exit_results.extend(product_exit_results) - - # Finding 1 (HIGH), ENTRIES ONLY. EXITS above already ran for every rule regardless - # of this gate: an open position's rule-driven channel exit runs IN-PROCESS (the - # protective stop rests at the broker, but the channel exit does not), so it must - # never be held hostage by a stale feed -- staying in a losing position an extra - # cycle is strictly worse than a delayed entry. ENTRIES are different: nothing else - # on the live path dedupes one (see this module's docstring), so re-evaluating a bar - # already traded is a DUPLICATE REAL-MONEY ORDER, not a delayed one. Applied in - # EVERY mode, live and paper alike -- paper is the rehearsal for live (`candidate -> - # paper -> live`), and paper's own dedupe (`PaperTrader`) only refuses a second entry - # while the product is ALREADY OPEN; it does not stop a re-evaluated bar re-entering - # after a flat close. `strategy/backtest.py` and `sim/portfolio_sim.py` never call - # `run_once` at all, so neither is affected by this gate. - ready_rules: list[Rule] = [] for rule in product_rules: gate_gran = _entry_gate_granularity(rule, granularities) if gate_gran is None: - ready_rules.append(rule) continue readiness = freshness.entry_bar_ready(candles_by_tf, gate_gran, now_ts) if readiness.ready: - ready_rules.append(rule) continue log_event( logger, @@ -995,7 +1007,63 @@ def run_once( ) ) - product_signals = engine.evaluate(ready_rules, candles_by_tf, repo=repo) + # The whole-cycle admission bit: ANY blocked rule, on ANY product, withholds EVERY entry + # this cycle -- see the pre-pass comment above for why this cannot be decided per-rule + # or per-product. `blocked_entries` is still recorded per-rule (for the operator log + # line and `LoopResult`), but what it GATES is binary. + entries_allowed = not blocked_entries + if not entries_allowed: + log_event( + logger, + logging.WARNING, + "agent.entries_withheld", + blocked_count=len(blocked_entries), + products=sorted({b.product for b in blocked_entries}), + rules=sorted({b.rule_name for b in blocked_entries}), + ) + + # == MAIN PASS: exits ALWAYS run; entries run ONLY when `entries_allowed` ================ + for product_id in products: + if product_id in stale_products: + continue # already recorded + logged in the pre-pass above -- not logged twice. + + candles_by_tf = candles_by_tf_by_product[product_id] + product_rules = [r for r in rules if getattr(r, "product_id", None) == product_id] + + if paper_trader is not None: + _paper_resolve_bars(paper_trader, product_id, candles_by_tf, granularities) + + # EXITS are exempt from `entries_allowed` and always run, for every non-stale + # product, regardless of which (if any) product is withholding this cycle's + # entries. An open position's rule-driven channel exit runs IN-PROCESS (the + # protective stop rests at the broker, but the channel exit does not), so it must + # never be held hostage by a DIFFERENT product's lagging feed -- staying in a losing + # position an extra cycle is strictly worse than a delayed entry, and nothing about + # the duplicate-order hazard this gate exists for applies to a SELL that closes an + # existing position. + product_exit_results = _handle_exits( + product_id, product_rules, candles_by_tf, repo, broker, config, mode, now_ts, + confirm_fn=confirm_fn, + ) + for exit_result in product_exit_results: + log_event( + logger, + logging.INFO, + "agent.exit_evaluated", + product=product_id, + placed=exit_result.placed, + reason=exit_result.reason, + ) + exit_results.extend(product_exit_results) + + if not entries_allowed: + # Whole-cycle withholding (see the pre-pass comment above): evaluate NOTHING for + # entries on this product, even though its own rules may individually have been + # ready -- `engine.evaluate` is not even called, so no signal is scored, + # persisted, or logged, and `enter_signals` stays empty for the whole cycle. + continue + + product_signals = engine.evaluate(product_rules, candles_by_tf, repo=repo) log_event( logger, logging.INFO, diff --git a/tests/test_agent.py b/tests/test_agent.py index 11bb308a..6f324b45 100644 --- a/tests/test_agent.py +++ b/tests/test_agent.py @@ -2341,3 +2341,279 @@ def test_run_once_blocks_a_dca_entry_on_a_stale_daily_bar(repo): assert len(result.blocked_entries) == 1 assert result.blocked_entries[0].rule_name == "dca" assert result.blocked_entries[0].granularity == Granularity.ONE_DAY + + +# -- entry admission is WHOLE-CYCLE, not per-rule (adversarial review of PR #174) --------------- +# +# The gate pinned above closed the "which BAR" half of Finding 1 but was wired at the wrong +# GRANULARITY: `ready_rules` was filtered PER PRODUCT, inside the very loop that also calls +# `executor.execute` for that product's signals. `blocked_entries` was populated correctly, but +# nothing consulted it before an order went out for an EARLIER, unrelated product in the same +# `products` loop -- and the cycle could still finish with `blocked_entries` non-empty, which is +# what the CLI's exit code is keyed off. `keel-live-run.sh` reads that exit code alone to decide +# whether to stamp the UTC day; a nonzero exit after orders already placed makes it decline to +# stamp and retry the WHOLE cycle next hour, re-entering whatever already placed. The tests below +# pin the fix: entry admission is now decided ONCE, for the WHOLE cycle, before any +# `executor.execute`/`_paper_enter` runs -- see the pre-pass comment in `agent.run_once`. + +_XLM = "XLM-USD" # sorts AFTER "BTC-USD" (`products = sorted(...)`) -- see the regression test. + + +def _blocked_cycle_config(**overrides: Any) -> Config: + """`interval_sec=100_000` -> `max_age_sec = 300_000`s (`FEED_STALENESS_CYCLES == 3`). Wide + enough that a daily series exactly ONE bar behind its own `expected_last_ts` -- which costs + close to TWO calendar days of `now_ts - stored_ts`, since both "one bar behind" and "now + sitting right at the top of its own day" each contribute a step -- still reads as FRESH to + `market_feed.is_fresh`. That is deliberate: every test below wants the product gated by the + stricter `freshness.entry_bar_ready` (blocked), never pre-empted by the looser staleness + skip (which would prove nothing about this section's hazard). Shared so the arithmetic is + worked out once. + """ + return _config(auto_trade=AutoTradeConfig(mode="confirm", interval_sec=100_000), **overrides) + + +def test_a_ready_products_order_placed_before_a_blocked_products_own_check_is_the_regression( + repo, +): + """THE REGRESSION. Two products, one cycle: `BTC-USD` sorts before `XLM-USD` + (`products = sorted(...)`), so the OLD per-product loop reached BTC-USD FIRST, found its DCA + rule ready, and placed a REAL order via `executor.execute` -- ONLY THEN did the loop reach + XLM-USD and discover its own DCA rule was blocked. `blocked_entries` ended up non-empty, but + nothing before this fix ever consulted it before BTC-USD's order went out. + + PRE-FIX: this must fail by showing BTC-USD's order placed anyway, alongside a non-empty + `blocked_entries` -- captured verbatim in the PR transcript before the fix landed. + POST-FIX: a blocked rule ANYWHERE in the cycle withholds EVERY entry that cycle, so + BTC-USD's otherwise-ready order never places either, and `enter_signals` stays empty -- + nothing was ever handed to `engine.evaluate` at all. + """ + config = _blocked_cycle_config() + now_ts = 11 * _DAY # start of day 11 -- `expected_last_ts(ONE_DAY)` resolves to day 10. + + # BTC-USD: READY. Daily bar stored exactly at day 10 (== expected); `cadence_days=1` makes + # every stored bar an unconditional cadence hit (`day % 1 == 0` always). + repo.insert_rule("dca", {"product_id": PRODUCT, "cadence_days": 1}, status="live") + ready_daily = [_candle(10 * _DAY, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, ready_daily) + + # XLM-USD: BLOCKED. Daily bar stored at day 9 -- one bar SHORT of day 10 -- so + # `entry_bar_ready` reports `bars_behind == 1`, reason "behind". + repo.insert_rule("dca", {"product_id": _XLM, "cadence_days": 1}, status="live") + blocked_daily = [_candle(9 * _DAY, "100")] + repo.upsert_candles(_XLM, Granularity.ONE_DAY, blocked_daily) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): ready_daily, + (_XLM, Granularity.ONE_DAY): blocked_daily, + } + ) + + result = run_once(broker, repo, config, now_ts=now_ts) + + assert len(result.blocked_entries) == 1 + assert result.blocked_entries[0].product == _XLM + + assert result.enter_signals == [], ( + f"BTC-USD's DCA entry was evaluated even though XLM-USD's was blocked this cycle: " + f"{result.enter_signals!r}" + ) + assert all(not r.placed for r in result.enter_results) + assert repo.get_orders(mode="live", product_id=PRODUCT) == [], ( + "BTC-USD's order placed before XLM-USD's block was ever accounted for -- this IS the bug" + ) + + +def test_retry_after_the_late_series_catches_up_places_exactly_one_order(repo): + """THE END-TO-END STATEMENT OF THE FIX -- the property that actually matters is not merely + "a blocked cycle places nothing" but that a RETRY of the same cycle, once the late series has + caught up, is IDEMPOTENT: it must not somehow end up placing what the first, blocked attempt + already would have, on top of what it places now. Two `run_once` calls at the SAME `now_ts` + -- the runner's own retry shape, an hourly trigger re-running the identical cycle against the + identical bar after a missed day-stamp (see `keel-live-run.sh`'s header) -- first with + XLM-USD's daily bar one bar behind (blocked, zero orders anywhere), second with it caught up + (nothing blocked, BTC-USD's ready DCA finally places, exactly once). + + XLM-USD's own DCA uses `cadence_days=3` (`10 % 3 != 0`) so that even once its data is fresh + and it stops being blocked, it still does not itself fire -- isolating this test to the ONE + order the fix is actually responsible for, rather than also depending on a second rule + firing correctly. + """ + config = _blocked_cycle_config() + now_ts = 11 * _DAY + + repo.insert_rule("dca", {"product_id": PRODUCT, "cadence_days": 1}, status="live") + ready_daily = [_candle(10 * _DAY, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, ready_daily) + + repo.insert_rule("dca", {"product_id": _XLM, "cadence_days": 3}, status="live") + blocked_daily = [_candle(9 * _DAY, "100")] + repo.upsert_candles(_XLM, Granularity.ONE_DAY, blocked_daily) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): ready_daily, + (_XLM, Granularity.ONE_DAY): blocked_daily, + } + ) + + first = run_once(broker, repo, config, now_ts=now_ts) + assert first.blocked_entries != [] + assert first.enter_signals == [] + assert repo.get_orders(mode="live") == [] + + # The late series catches up -- both in the repo (what `run_once` reads) and the fake broker + # (what a subsequent `market_feed.poll_once` would re-serve, so the retry is realistic). + caught_up_daily = [_candle(9 * _DAY, "100"), _candle(10 * _DAY, "100")] + repo.upsert_candles(_XLM, Granularity.ONE_DAY, caught_up_daily) + broker._series[(_XLM, Granularity.ONE_DAY)] = caught_up_daily + + second = run_once(broker, repo, config, now_ts=now_ts) + assert second.blocked_entries == [] + + orders = repo.get_orders(mode="live") + assert len(orders) == 1, ( + f"expected exactly one order across BOTH cycles -- the blocked first cycle must not " + f"have left BTC-USD's entry half-placed for the second cycle to duplicate: {orders!r}" + ) + assert orders[0]["product_id"] == PRODUCT + assert orders[0]["side"] == "BUY" + + +def test_same_product_two_rules_one_ready_one_blocked_neither_places(repo): + """Same product, two rules that gate on DIFFERENT granularities: `dca` falls back to the + coarsest configured granularity (`ONE_DAY`), `pullback_continuation` is given an explicit + `granularity=ONE_HOUR`. Constructed so the ONE_HOUR series is current with respect to ITS + OWN expectation (ready, on its own) while the ONE_DAY series' CONFIRMING hourly bar has not + yet crossed into the new day (blocked) -- i.e. right after midnight, before the first hourly + bar of the new day has closed. + + Neither rule needs to actually detect a tradeable setup: readiness is a property of the + CANDLE TIMESTAMPS alone (`freshness.entry_bar_ready` never calls `rule.detect()`), and post- + fix `engine.evaluate()` is never even invoked while any rule anywhere is blocked -- so this + only has to pin that ONE blocked rule on a product is enough to withhold that SAME product's + OTHER, individually-ready rule too. + """ + config = _blocked_cycle_config( + market_data=MarketDataConfig( + granularities=[Granularity.ONE_DAY, Granularity.ONE_HOUR], history_days=365 + ) + ) + midnight = 11 * _DAY + now_ts = midnight + 300 # 00:05 UTC on day 11 -- just past midnight. + + # ONE_DAY series: yesterday's (day 10) bar, exactly `expected_last_ts(ONE_DAY)` -- current on + # its own terms. + daily = [_candle(10 * _DAY, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, daily) + repo.insert_rule("dca", {"product_id": PRODUCT, "cadence_days": 1}, status="live") + + # ONE_HOUR series: yesterday 23:00's bar -- current w.r.t. ONE_HOUR's OWN expectation (the + # 00:00-01:00 bar is still forming), but it has NOT crossed today's 00:00 boundary, so it + # cannot confirm the daily bar above. + hourly = [_candle(midnight - _HOUR, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_HOUR, hourly) + repo.insert_rule( + "pullback_continuation", {"product_id": PRODUCT, "granularity": "ONE_HOUR"}, status="live" + ) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): daily, + (PRODUCT, Granularity.ONE_HOUR): hourly, + } + ) + + result = run_once(broker, repo, config, now_ts=now_ts) + + blocked_names = {b.rule_name for b in result.blocked_entries} + assert blocked_names == {"dca"}, ( + f"expected only the ONE_DAY-gated dca rule blocked, not pullback_continuation " + f"(ONE_HOUR-gated, current on its own terms): {result.blocked_entries!r}" + ) + assert result.enter_signals == [], ( + "pullback_continuation must not have been evaluated either -- one blocked rule on this " + f"product withholds the WHOLE product's entries, not just the rule that was itself " + f"blocked: {result.enter_signals!r}" + ) + assert repo.get_orders(mode="live", product_id=PRODUCT) == [] + + +def test_exit_still_runs_when_a_different_products_blocked_entry_withholds_the_whole_cycle(repo): + """Complements `test_exit_still_runs_while_a_different_rules_entry_is_blocked` above (same + product, two rules) with the shape that matters post-fix: a DIFFERENT PRODUCT's block now + withholds the whole cycle's entries, not just its own. BTC-USD holds a position owned by + `fake_exit` (always exits); XLM-USD's `dca` entry is blocked. Exits are exempt from + `entries_allowed` entirely (see the pre-pass comment in `run_once`) -- protective stops rest + at the broker, but the channel exit here runs IN-PROCESS, and holding a losing position an + extra cycle is strictly worse than a delayed entry -- so BTC-USD's exit must still fire while + `enter_signals` stays empty for the whole cycle. + """ + config = _blocked_cycle_config() + now_ts = 11 * _DAY + + _seed_open_position( + repo, PRODUCT, Decimal("0.1"), Decimal("50000"), ts=1_000, rule_name="fake_exit" + ) + repo.insert_rule("fake_exit", {"product_id": PRODUCT}, status="live") + repo.set_state(f"position_rule:{PRODUCT}", "fake_exit") + fresh_daily = [_candle(10 * _DAY, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, fresh_daily) + + repo.insert_rule("dca", {"product_id": _XLM, "cadence_days": 1}, status="live") + blocked_daily = [_candle(9 * _DAY, "100")] + repo.upsert_candles(_XLM, Granularity.ONE_DAY, blocked_daily) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): fresh_daily, + (_XLM, Granularity.ONE_DAY): blocked_daily, + } + ) + + result = run_once(broker, repo, config, now_ts=now_ts) + + assert len(result.exit_results) == 1 + assert result.exit_results[0].placed is True + assert result.enter_signals == [], ( + f"entries should have been withheld for the whole cycle: {result.enter_signals!r}" + ) + blocked_products = {b.product for b in result.blocked_entries} + assert blocked_products == {_XLM} + + +def test_a_stale_products_missing_feed_does_not_withhold_a_different_products_entry(repo): + """Pins the ORDERING the pre-pass in `run_once` must preserve: the stale-feed check + (`market_feed.is_fresh`) runs BEFORE the entry-readiness gate and `continue`s past a stale + product entirely -- it never reaches `freshness.entry_bar_ready` and so never contributes to + `blocked_entries`. A dead venue or a delisted product must not be able to silently halt every + OTHER product's trading merely by having no feed at all; only a product that IS being polled, + and is merely a bar or two behind, can withhold the whole cycle's entries (see the pre-pass + comment in `run_once`). + """ + config = _blocked_cycle_config() + now_ts = 11 * _DAY + + # XLM-USD: no candles ever recorded -- `market_feed.is_fresh` -> False, "no stored candle at + # all" -- skipped as STALE, exactly like `test_stale_feed_skips_trading_for_that_product`. + repo.insert_rule("dca", {"product_id": _XLM, "cadence_days": 1}, status="live") + + # BTC-USD: healthy and ready -- an ordinary cadence-hit DCA entry. + repo.insert_rule("dca", {"product_id": PRODUCT, "cadence_days": 1}, status="live") + ready_daily = [_candle(10 * _DAY, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, ready_daily) + + broker = FakeBroker(series={(PRODUCT, Granularity.ONE_DAY): ready_daily}) + + result = run_once(broker, repo, config, now_ts=now_ts) + + assert result.stale_products == [_XLM] + assert result.blocked_entries == [], ( + f"a stale product must not surface as a BLOCKED entry -- it never reached the readiness " + f"gate at all: {result.blocked_entries!r}" + ) + assert len(result.enter_signals) == 1 + assert result.enter_signals[0].product_id == PRODUCT + orders = repo.get_orders(mode="live", product_id=PRODUCT) + assert len(orders) == 1 + assert orders[0]["side"] == "BUY" diff --git a/tests/test_rule_manifest.py b/tests/test_rule_manifest.py index 0f9646d9..a16292e6 100644 --- a/tests/test_rule_manifest.py +++ b/tests/test_rule_manifest.py @@ -168,6 +168,16 @@ def test_committed_manifest_is_valid(tmp_path: Path) -> None: # for that: (2) status, which is the only thing that still can, and (3) a pinned check on # the coincidence itself, so that if the operator ever moves the budget off the default, the # value check regains its old power and (3) is what tells them so. + # + # SCOPE, so nobody reads more assurance into this than it gives. Everything below asserts + # against the COMMITTED FILE, `deploy/live-rules.json` -- not against any deployment's + # database. So it does NOT detect a box that has been reseeded; it detects a reseeded box's + # state being COMMITTED, i.e. someone re-running `rule_manifest.py export` against a + # reseeded DB and committing the diff. That is the reviewable choke point this manifest + # exists to create, and it is worth guarding -- but the reseed itself is silent on the box + # until an export happens, and nothing here changes that. Catching it live would take a + # check against a real DB (`rule_manifest.py apply` already reports exactly that drift and + # exits 1), which is a deploy-time step, not a unit test. # (1) AGREEMENT -- the manifest's budget must match config.dca.budget_usd, the value the live # executor actually spends. diff --git a/tests/test_schedule.py b/tests/test_schedule.py index eb9cf1c6..356c22ba 100644 --- a/tests/test_schedule.py +++ b/tests/test_schedule.py @@ -331,21 +331,40 @@ def _triggers( def _run_gate( triggers: list[tuple[datetime, datetime]], sched_hour: int, *, utc_anchored: bool ) -> list[datetime]: - """Replay `keel-live-run.sh`'s two guards over `triggers`; return the UTC instants that RAN. + """Replay `keel-live-run.sh`'s two guards over `triggers`; return the UTC instants that RAN a + cycle (i.e. invoked keel) -- NOT whether the script exited 0, 67, or anything else; see the + note below on why that distinction is deliberately outside what this model represents. - The shell, in Python, as of the hardened script: + The shell's gate, in Python, as of the hardened script: - if [ -n "$STAMPED" ] && ! [[ "$STAMPED" < "$TODAY" ]]; then exit 0; fi # already ran/behind - if [ "$HOUR" -lt "$SCHED_HOUR" ]; then exit 0; fi # too early in the day + if [ -n "$STAMPED" ] && [[ "$STAMPED" > "$TODAY" ]]; then exit 67; fi # ahead: alert + if [ -n "$STAMPED" ] && [ "$STAMPED" = "$TODAY" ]; then exit 0; fi # already ran + if [ "$HOUR" -lt "$SCHED_HOUR" ]; then exit 0; fi # too early + + Both `STAMPED > TODAY` (Defect 1's forward-excursion alert, exit 67) and `STAMPED == TODAY` + (the ordinary already-ran case, exit 0) leave the stamp untouched and never invoke keel, so + both collapse into the same `not (stamp < clock.date())` test below for the purpose of "did a + cycle run" -- this model is deliberately blind to WHICH of the two no-run outcomes fired, since + only the shipped script's exit code and notifications (not this pure model) distinguish them. + That distinction is covered against the REAL script by + `test_forward_clock_excursion_escalates_instead_of_silently_skipping` and + `test_clock_rollback_does_not_rerun_or_move_the_stamp_backwards`. `utc_anchored=False` reproduces the OLD (pre-UTC-anchoring) behaviour (both `TODAY` and `HOUR` from LOCAL time), so the two can be compared on identical trigger lists. Every cycle here is assumed to succeed -- a failed cycle writes no stamp and is retried, which only ever ADDS a - later run on the same date, never removes one. The strict `<` compare and `stamp < clock.date()` - below behave identically to the old `==` compare for any MONOTONICALLY forward-moving trigger - sequence (which every trigger list built by `_triggers` is) -- the two diverge only under a - clock rollback, which is covered separately by the real-script test - `test_clock_rollback_does_not_rerun_or_move_the_stamp_backwards`, not by this pure model. + later run on the same date, never removes one. + + CORRECTION: an earlier version of this docstring claimed the strict `<` compare (this PR) and + the pre-PR-174 `==` compare "diverge only under a clock rollback". That was FALSE, and the + false claim is precisely why nothing here covered the other direction before now: a FORWARD + clock excursion (a bad RTC reading a bogus future date before NTP settles) also makes the two + diverge, and in the more dangerous direction -- `==` self-heals the very next real day (the + bogus stamp no longer equals today, so the cycle runs and re-stamps correctly), `<` does not + self-heal at all, ever, until the real clock catches up to the bogus future stamp, which could + be years. See `test_forward_clock_excursion_escalates_instead_of_silently_skipping` for that + case driven against the real script; both directions of divergence (rollback and forward + excursion) are covered now. """ ran: list[datetime] = [] stamp: date | None = None @@ -749,13 +768,28 @@ def test_the_simulated_gate_matches_the_real_script(tmp_path: Path) -> None: invocation) -- not acceptable, so this sequence is curated rather than exhaustive. It covers: three consecutive normal UTC days; the 00:20 UTC trigger below `SCHED_HOUR`; the full spring-forward day (2026-03-08, 23 triggers, the hour-lost case); the full fall-back day - (2026-11-01, 25 triggers, including BOTH firings of the repeated local hour); and the + (2026-11-01, 25 triggers, including BOTH firings of the repeated local hour); the boot-after-outage catch-up sequence from - `test_the_old_local_date_gate_could_double_run_within_one_utc_day`. All of it runs through ONE - sandbox, replayed as a single sequence sorted by UTC instant (the order a real machine would - execute them in), so the stamp evolves exactly as it would across all these cases back to - back -- one continuous timeline is cheaper than one sandbox per scenario and just as faithful, - since the gate only ever compares ISO-date strings, never wall-clock elapsed time. + `test_the_old_local_date_gate_could_double_run_within_one_utc_day`; and (Defect 1) a forward + clock excursion followed by a return to real dates. Before Defect 1 was found, NEITHER this + differential test NOR the pure model covered a forward excursion at all -- which is precisely + how the regression got through review: nothing here would have caught "the script now returns + the wrong exit code and stays silent forever", because this test only ever asserted whether a + cycle ran, and a forward excursion never runs one, on the buggy script OR the fixed one (see + `_run_gate`'s docstring). The excursion is added for completeness and to guard the "did a cycle + run" property specifically, not to catch Defect 1 itself -- + `test_forward_clock_excursion_escalates_instead_of_silently_skipping` is what proves the exit + code and notification, which this coarser differential test cannot see. + + Most of it runs through ONE sandbox, replayed as a single sequence sorted by UTC instant (the + order a real machine would execute them in), so the stamp evolves exactly as it would across + all these cases back to back -- one continuous timeline is cheaper than one sandbox per + scenario and just as faithful, since the gate only ever compares ISO-date strings, never + wall-clock elapsed time. The forward-excursion mini-sequence is the one exception: it is + APPENDED after the sort, in its own literal firing order, rather than sorted in with the rest, + because "jump forward then return to real dates" is deliberately NOT monotonic in the clock's + own reading -- sorting it back into chronological order would erase the exact anomaly under + test. It is kept small (4 extra triggers) to keep the added wall-clock cost tiny. """ sb = _sandbox(tmp_path, keel_exit_code=0) tz = ZoneInfo(DEPLOYMENT_TZ) @@ -783,6 +817,18 @@ def test_the_simulated_gate_matches_the_real_script(tmp_path: Path) -> None: pairs.sort(key=lambda pair: pair[0]) + # Defect 1: a forward clock excursion, then a return to real dates -- appended AFTER the sort, + # in this exact order, deliberately not re-sorted with the rest (see the docstring above). The + # last chronological trigger sorted in above is the fall-back day, 2026-11-01, so this segment + # starts a month later to land on an ordinary already-stamped day first. + forward_excursion_and_return = [ + (datetime(2026, 12, 1, 1, 20, tzinfo=UTC), datetime(2026, 12, 1, 1, 20, tzinfo=UTC)), + (datetime(2035, 1, 1, 3, 20, tzinfo=UTC), datetime(2035, 1, 1, 3, 20, tzinfo=UTC)), + (datetime(2026, 12, 2, 1, 20, tzinfo=UTC), datetime(2026, 12, 2, 1, 20, tzinfo=UTC)), + (datetime(2026, 12, 3, 1, 20, tzinfo=UTC), datetime(2026, 12, 3, 1, 20, tzinfo=UTC)), + ] + pairs.extend(forward_excursion_and_return) + model_ran = set(_run_gate(pairs, SCHED_HOUR, utc_anchored=True)) for utc_instant, _local in pairs: @@ -966,14 +1012,22 @@ def test_malformed_stamp_content_refuses_to_run(tmp_path: Path) -> None: def test_clock_rollback_does_not_rerun_or_move_the_stamp_backwards(tmp_path: Path) -> None: - """Finding 4 (MED): a clock reading a PAST date (bad RTC before NTP settles) must not re-run. + """Finding 4 (MED) / Defect 1 (MED): a clock reading a PAST date must not re-run -- and now + alerts instead of skipping silently. `RunAtLoad` fires immediately on boot, potentially before NTP has corrected a bad real-time - clock. With the OLD `=` compare, a bogus past date is "not today", so the cycle RUNS and - stamps the bogus date; when the clock then corrects forward, the real date no longer matches - that bogus stamp, so the cycle runs AGAIN -- re-evaluating, and potentially re-entering, a bar - it already traded. The fix requires the stamp to be STRICTLY BEFORE today, so a stamp equal to - OR ahead of today both read as "done" -- and the stamp itself must never move backwards. + clock. With the OLD `=` compare, a bogus past date was "not today", so the cycle RAN and + stamped the bogus date; when the clock then corrected forward, the real date no longer matched + that bogus stamp, so the cycle ran AGAIN -- re-evaluating, and potentially re-entering, a bar + it already traded. Requiring the stamp to be STRICTLY BEFORE today closes that: a stamp equal + to OR ahead of today both read as "done, do not run" -- and the stamp itself must never move + backwards. + + What changed under Defect 1: a rolled-back clock makes today's stamp read as AHEAD of "today", + which is now exit 67 (notify, refuse) rather than the old silent exit 0 -- the two no-run + outcomes used to be one path and are now two, see `_run_gate`'s docstring. The behaviour this + test exists to pin -- never re-run, never move the stamp backwards -- is unchanged; only the + exit code and the fact that a human now hears about it are new. """ sb = _sandbox(tmp_path, keel_exit_code=0) x = datetime(2026, 6, 15, 1, 20, tzinfo=UTC) @@ -985,21 +1039,189 @@ def test_clock_rollback_does_not_rerun_or_move_the_stamp_backwards(tmp_path: Pat assert sb.stamp.read_text().strip() == "2026-06-15" ran_once = _count_lines(sb.invocations_log) - _run(sb, months_in_the_past) + rolled_back = _run(sb, months_in_the_past) + assert rolled_back.returncode == 67, "a stamp ahead of today must exit 67, not exit 0" assert _count_lines(sb.invocations_log) == ran_once, "a clock in the past must not run a cycle" assert sb.stamp.read_text().strip() == "2026-06-15", "the stamp must never move backwards" + assert sb.calls_log.exists() and sb.calls_log.read_text().strip(), ( + "a rolled-back clock must alert a human now, not skip silently forever" + ) - _run(sb, x) + calls_after_rollback = _count_lines(sb.calls_log) + same_day = _run(sb, x) + assert same_day.returncode == 0, ( + "the stamp's own date, re-seen, is the ORDINARY already-ran case" + ) assert _count_lines(sb.invocations_log) == ran_once, ( "the stamp's own date, re-seen, must not re-run either" ) assert sb.stamp.read_text().strip() == "2026-06-15" + assert _count_lines(sb.calls_log) == calls_after_rollback, ( + "re-seeing the stamp's own date is the ordinary already-ran path -- it must stay silent, " + "not alert again" + ) _run(sb, x_plus_1) assert _count_lines(sb.invocations_log) == ran_once + 1, "the day after must run exactly once" assert sb.stamp.read_text().strip() == "2026-06-16" +def test_forward_clock_excursion_escalates_instead_of_silently_skipping(tmp_path: Path) -> None: + """Defect 1 (MED), a REGRESSION PR #174 itself introduced: a forward clock excursion must not + become a permanent silent outage. + + Reproduces the reviewer's exact sequence through this PR's own sandbox harness: the detector + runs normally and stamps a real UTC date; a bad RTC before NTP settles then reads YEARS into + the future (`RunAtLoad` firing on a not-yet-corrected boot clock), the cycle runs and stamps + that bogus future date; every real trigger afterwards then reads a correctly-dated TODAY that + is, and stays, behind the bogus stamp. + + Under the OLD `=` compare (pre-PR-174) this SELF-HEALED the very next real day: the bogus + stamp no longer equalled today, so the cycle ran again and re-stamped the correct date. PR + #174's `<` compare fixed clock ROLLBACK but broke this direction instead: `! [[ "$STAMPED" < + "$TODAY" ]]` stays true for every subsequent real day until the real clock catches up to the + bogus stamp -- which could be years -- so this is a SILENT outage, rc=0 throughout, zero + notifications. This test is therefore a regression test for THIS FIX, not a test of the + original Finding 4: the monotonic `<` compare did not exist before PR #174, so there is no + "before PR #174" behaviour to regress against here. + + The fix: a stamp strictly AHEAD of today is corrupt state, not "already ran" -- exit 67, + notify, and never overwrite the stamp. Checked over SEVERAL consecutive real days, not just + one, to prove the alert keeps firing rather than notifying once and then going quiet again + exactly like the bug it replaces. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + + real_run = datetime(2026, 8, 6, 1, 20, tzinfo=UTC) + first = _run(sb, real_run) + assert first.returncode == 0 + assert sb.stamp.read_text().strip() == "2026-08-06" + ran_once = _count_lines(sb.invocations_log) + + # Bad RTC before NTP settles: RunAtLoad fires with a clock reading years in the future. + bad_rtc = datetime(2035, 1, 1, 3, 20, tzinfo=UTC) + jumped = _run(sb, bad_rtc) + assert jumped.returncode == 0, ( + "the bogus future date is, from the stamp's point of view, just another unstamped day -- " + "it runs normally, which is exactly how the bogus stamp gets written in the first place" + ) + assert sb.stamp.read_text().strip() == "2035-01-01" + assert _count_lines(sb.invocations_log) == ran_once + 1 + + calls_before_return = _count_lines(sb.calls_log) + for day in (7, 8, 9, 10, 11): + back_to_real = datetime(2026, 8, day, 1, 20, tzinfo=UTC) + result = _run(sb, back_to_real) + assert result.returncode == 67, ( + f"2026-08-{day:02d} must exit 67 (stamp ahead of today) -- the OLD `=` compare would " + "have exited 0 and RUN a (duplicate) cycle here instead; the regression this PR " + "introduced exited 0 and skipped SILENTLY instead of either" + ) + assert _count_lines(sb.invocations_log) == ran_once + 1, ( + "a stamp ahead of today must never run a cycle, on any of these days" + ) + assert sb.stamp.read_text().strip() == "2035-01-01", ( + "the bogus future stamp must not move just because more real days went by" + ) + + assert _count_lines(sb.calls_log) == calls_before_return + 5, ( + "all 5 subsequent real days must alert -- one notification and then silence would be no " + "better than the regression this fix closes, just with a one-day grace period" + ) + + +def test_ordinary_already_ran_stays_silent(tmp_path: Path) -> None: + """The control for Defect 1's fix: an ordinary same-UTC-day second trigger must still exit 0 + with NO notification. + + Splitting "stamp ahead of today" (exit 67, alert) out from "stamp equal to today" (exit 0, + silent) is only a correct fix if the ordinary, overwhelmingly common case -- one of the day's + 23 remaining triggers finding the day already done -- does not start alerting too. A version of + the fix that over-eagerly notified on every non-run, not just the forward-excursion one, would + defeat the NOTIFICATION POLICY this script depends on (see its header): training the operator + to expect routine noise on the ordinary path is exactly what makes the operator ignore the + alerts that matter. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + now = datetime(2026, 6, 15, 1, 20, tzinfo=UTC) + + first = _run(sb, now) + assert first.returncode == 0 + assert sb.stamp.read_text().strip() == "2026-06-15" + assert _count_lines(sb.calls_log) == 0, "a normal first-of-the-day run must not alert either" + + second = _run(sb, now) + assert second.returncode == 0 + assert "already ran" in second.stdout + assert _count_lines(sb.calls_log) == 0, ( + "the ordinary already-ran path must stay exactly as silent as before this fix" + ) + + +def test_stuck_detector_escalates_after_consecutive_failures(tmp_path: Path) -> None: + """Defect 2 (MED): nothing previously escalated a detector that keeps failing every trigger. + + A nonzero exit from keel is deliberately NOT notified on its own (NOTIFICATION POLICY: it is + normally an expected, self-healing publication lag that the next hourly trigger retries). But + that means 23 consecutive failing triggers in one UTC day produced ZERO notifications, and a + persistently stuck detector was indistinguishable from a quiet day with no signals -- which + matters more now that another change on this branch (the entry gate in `keel/agent.py`) makes + ANY one chronically-lagging product withhold the WHOLE cycle's entries, so a single stuck + product could keep the day permanently unstamped with nothing ever shouting about it. + + Proves all four pieces of the fix: N-1 consecutive failures stay silent, the Nth (N=3) alerts, + the stamp is never written on any of the failing cycles, and a subsequent CLEAN cycle resets + the counter so a later isolated failure is silent again rather than continuing to count from a + long-resolved outage. + """ + now = datetime(2026, 6, 15, 1, 20, tzinfo=UTC) + failcount = tmp_path / "logs" / ".keel-live-last-run.failures" + + failing = _sandbox(tmp_path, keel_exit_code=3) + + first = _run(failing, now) + assert first.returncode == 3 + assert not failing.stamp.exists(), "a failing cycle must never fabricate a stamp" + assert _count_lines(failing.calls_log) == 0, "one failure is ordinary publication lag -- silent" + + second = _run(failing, now) + assert second.returncode == 3 + assert not failing.stamp.exists() + assert _count_lines(failing.calls_log) == 0, ( + "two failures in a row is still not 'stuck' -- silent" + ) + + third = _run(failing, now) + assert third.returncode == 3 + assert not failing.stamp.exists(), ( + "escalating must never fabricate a stamp -- the day stays open" + ) + assert _count_lines(failing.calls_log) == 1, "the third consecutive failure must escalate" + assert "3 consecutive" in failing.calls_log.read_text() + + # A clean, verified cycle heals the detector -- the counter must reset, not just pause. + clean = _sandbox(tmp_path, keel_exit_code=0) + healed = _run(clean, now) + assert healed.returncode == 0 + assert clean.stamp.read_text().strip() == "2026-06-15" + assert not failcount.exists(), ( + "a clean, verified stamp write must reset the consecutive-failure counter, not merely " + "pause it -- a missing counter file reads as 0" + ) + + # One more failure, on a later day so the fresh stamp does not itself block it: must be silent, + # proving the counter actually reset rather than continuing on from 3. + calls_before_next_failure = _count_lines(clean.calls_log) + failing_again = _sandbox(tmp_path, keel_exit_code=5) + later = datetime(2026, 6, 16, 1, 20, tzinfo=UTC) + single_failure = _run(failing_again, later) + assert single_failure.returncode == 5 + assert _count_lines(failing_again.calls_log) == calls_before_next_failure, ( + "the counter reset means a single later failure is silent again, not counted onward from " + "the earlier, already-resolved outage" + ) + + def test_pendlog_is_utc_labelled(tmp_path: Path) -> None: """Finding 10: PENDLOG's timestamp must say UTC, like every other line in this script. From 68c2db625d1bd2d0f3ecc03177f34930d05acbdb Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Thu, 6 Aug 2026 20:48:32 -0400 Subject: [PATCH 4/4] fix(schedule): prove the stamp is REPLACEABLE, halt on an unrecordable cycle, kill the mutants Round-3 review. One MEDIUM with a money consequence, one test that asserted a discrimination it did not make, and four fixes no test could kill. MEDIUM -- the pre-flight proved the DIRECTORY was writable, not that $STAMP was REPLACEABLE. It probed `$STAMP.preflight.$$`, a DIFFERENT path. With $STAMP made a DIRECTORY (a botched restore, a `mkdir` typo) or marked immutable, the probe PASSED, keel RAN AND PLACED ORDERS, and only the post-cycle `mv -f`/readback -- which actually targets $STAMP -- then failed. Reproduced over five triggers in one UTC day: exit codes: 66 66 66 66 66 CYCLES RUN: 5 <- each one places real orders That is the exact "exiting nonzero AFTER a cycle has already run does not prevent the duplicate" pattern the pre-flight's own comment rejects, and the prose claim "prove the stamp is PERSISTABLE" was simply false. Two layers now: * the pre-flight ROUND-TRIPS through $STAMP itself -- write a temp file, `mv -f` it ONTO $STAMP, read $STAMP back -- using the stamp's own validated contents as the payload so a pass is a semantic no-op, and removing the stamp afterwards when there was none. Same reproduction now gives 66 x5 with ZERO cycles run. A stamp at mode 000 deliberately still works: a rename needs directory permission, not permission on the target inode. * a HALT SENTINEL for the residual window, where the stamp becomes unreplaceable BETWEEN a passing pre-flight and the post-cycle write. In that case a cycle has already run and may have placed orders, so the script drops a sentinel and every subsequent trigger refuses with exit 68 until a human clears it. That bounds the damage to the ONE cycle that already ran instead of 23. A lost trading day is recoverable; a duplicate live entry is not. MEDIUM -- the atomic-write test did not test atomicity, and its docstring said it did. It forced failure with `chflags uchg`, which fails at open(2) BEFORE truncation, so a plain `>` preserved yesterday's stamp identically. Verified: replacing the whole temp+mv+readback block with a single truncating `printf > "$STAMP"` left ALL 34 tests green. This is the same class of miss that let the previous round's regression through -- a docstring asserting a discrimination the test does not make -- so it is fixed on both sides: the behavioural test's docstring now states only what it proves and explains why a behavioural test CANNOT discriminate here, and a new source-level test pins the design (no bare truncating redirect onto $STAMP anywhere; temp path; `mv -f` onto $STAMP; readback against $TODAY). Every fix in this PR that a test could not kill is now pinned, each verified by performing the mutation and watching a test go red: * plain `>` instead of temp+mv -> red * readback verification dropped -> red * `mv -f` replaced with `cp -f` -> red * hour-range check (`-gt 23`) -> `if false` -> red * read_failcount numeric validation removed -> red (5 of 6 parametrised cases) * exit-65 malformed-stamp branch removed -> red, via a stamp that sorts BELOW today (`1999-1-1`); the previous test used one that sorts ABOVE and so fell into the 67 branch, which also refuses -- so the branch was load-bearing but the test was not * pre-flight round-trip removed -> red, via an IMMUTABLE regular-file stamp * halt sentinel gate removed -> red Every `returncode != 0` assertion is now an exact code, so the operator-facing 64/65/66/67/68 distinctions the header argues for are actually pinned rather than merely asserted in prose. Deliberately left redundant: the pre-flight's "exists but is not a regular file" check is not individually killable, because the round-trip alone already detects a directory (verified: exit 66, zero cycles). It is kept for a clearer operator message and to stop `mv` littering a probe file inside that directory, and is documented as belt-and-braces rather than as a sole detector. Also, from the same review: `agent.run_once`'s comment claimed a blocked cycle places nothing. It does not -- exits are exempt and can place a real SELL in the very cycle that withheld every entry. Comment corrected, and the retry's exit-idempotence is now pinned by a test. That test corrected the review's stated mechanism rather than confirming it. The claim was that `_handle_exits` clearing `position_rule:` is what stops a retry duplicating an exit. Mutation says otherwise: removing that clear alone leaves the suite GREEN. An exit is a market order, so its SELL is recorded `filled` immediately, and the audit-log qty netting in `_held_position` -- implemented independently in BOTH `agent.py` and `execution/executor.py` -- already reads the position as closed on the retry, before `position_rule` is consulted. Only breaking all three at once produces the duplicate SELL. The mechanism is triple-redundant; `position_rule` clearing is load-bearing for something else entirely (stale bracket state poisoning the NEXT position on that product), which is documented at its own call site. Co-Authored-By: Claude Opus 5 (1M context) --- keel-live-run.sh | 122 +++++++++-- keel/agent.py | 19 +- tests/test_agent.py | 81 ++++++++ tests/test_rule_manifest.py | 12 +- tests/test_schedule.py | 403 ++++++++++++++++++++++++++++++++++-- 5 files changed, 587 insertions(+), 50 deletions(-) diff --git a/keel-live-run.sh b/keel-live-run.sh index f099fefa..bb0aa108 100755 --- a/keel-live-run.sh +++ b/keel-live-run.sh @@ -104,6 +104,13 @@ # "already ran" would silently disable the detector until the real clock catches up to the # bogus stamp, which could be years. Distinct from 65 (stamp is not a date at all) so an # operator can tell the two apart at a glance -- see A2, part two, below. +# 68 -- the HALT SENTINEL ($STAMP.halt) is present: a PREVIOUS trigger's post-cycle stamp write +# failed AFTER that trigger's cycle had already run (see A3 layer two and A9 below). This +# is a deliberate DEAD STOP, not a retry -- a cycle may have placed an order and the script +# has no way to know whether it did, so it refuses on EVERY trigger, not just the one that +# hit the failure, until a human inspects and clears the sentinel. Distinct from 66 so an +# operator can tell "a stamp write just failed, this one trigger" (66) apart from "a +# previous failure is still blocking every trigger since" (68) at a glance. # # NOTIFICATION POLICY. A macOS notification fires for two kinds of thing: # (a) a condition the machine cannot self-heal without a human touching it -- exit codes @@ -146,6 +153,11 @@ STAMP="$DIR/logs/.keel-live-last-run" # also carry an integer. See the increment/reset sites near the bottom of this script and the # NOTIFICATION POLICY paragraph above. FAILCOUNT="$STAMP.failures" +# A9 (Finding 1, MEDIUM). The HALT SENTINEL, next to $STAMP for the same reason $FAILCOUNT is: +# dropped when the post-cycle stamp write fails AFTER a cycle has already run, and checked at the +# very top of the script on every subsequent trigger. See A9 below (the top-of-script check) and +# the write site near the bottom of this script for why this exists and what it bounds. +HALT="$STAMP.halt" # The one seam every macOS notification in this script goes through. Same purpose as the `DIR=` # rewrite tests/test_schedule.py::_sandbox already relies on: it lets the schedule tests swap in a # recorder and assert BOTH that a machine-is-broken condition alerts and that an ordinary @@ -214,6 +226,28 @@ if [ "$HOUR" -gt 23 ]; then fi TODAY="$TODAY_RAW" +# A9 (Finding 1, MEDIUM), the HALT SENTINEL check. Deliberately the FIRST thing after the clock is +# validated and BEFORE the stamp is even read: layers one and two below (the pre-flight probe and +# the post-cycle readback) each close a window at a different point in the cycle, but $STAMP can +# still become unreplaceable in the gap BETWEEN a passing pre-flight and the post-cycle write -- +# e.g. the volume drops to read-only mid-cycle, or something else starts holding $STAMP open. When +# that happens a cycle has ALREADY RUN -- and, with autonomy ON, may have placed an order -- and +# the day is left unstamped, so without this check the very next trigger would see "not yet done" +# and run ANOTHER cycle, compounding the exact duplicate this whole file exists to prevent. The +# write site near the bottom of this script drops $HALT the moment that residual-window failure is +# detected; this is the other half, checked on every trigger from then on. +# +# This is a DEAD STOP, not a retry: only a human removing $HALT -- after confirming what actually +# happened on the exchange -- clears it. That is the correct default because it bounds the damage +# to the ONE cycle that already ran instead of up to 23 more that UTC day, and because a lost +# trading day is recoverable where a duplicate live entry is not. +if [ -e "$HALT" ]; then + notify "keel-live: HALTED by ${HALT} -- a previous trigger's day-stamp write failed AFTER its cycle already ran, and an order may already be placed. An operator must confirm what happened on the exchange, then remove ${HALT}, before this will run again." + printf '%s [keel-live] halt sentinel present (%s) -- refusing to run, every trigger, until a human clears it -- exit 68\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$HALT" + exit 68 +fi + STAMPED="$(cat "$STAMP" 2>/dev/null || true)" # A2 (Finding 4, MED), part one. A non-empty stamp that is not a well-formed ISO date must never @@ -281,24 +315,70 @@ if [ "$HOUR" -lt "$SCHED_HOUR" ]; then fi # A3 (Finding 2, HIGH), layer one: PRE-FLIGHT, before invoking keel at all. Prove the stamp is -# PERSISTABLE by writing a throwaway probe file next to $STAMP, reading it back, and removing it. -# Reproduced by the reviewer with a read-only logs dir: the OLD script ran the cycle, the stamp -# write then failed SILENTLY, rc was 0, and the next trigger ran a SECOND full cycle. Exiting -# nonzero AFTER a cycle has already run does not prevent that duplicate -- if autonomy is ON the -# order is already placed, and the next trigger will still re-run because the write already -# failed once and nothing detected it. The only way to turn "duplicate real order" into "no -# trading plus a loud alert" is to refuse to trade when we cannot record that we traded. That is -# failing CLOSED, and it is the correct direction here even though it costs a trading day: a -# missed day is recoverable, a duplicate live entry is not. +# REPLACEABLE by round-tripping through the EXACT path the real post-cycle write uses. +# +# An EARLIER version of this pre-flight wrote its probe to a DIFFERENT path ($STAMP.preflight.$$), +# read that back, and removed it. That only proves the DIRECTORY is writable -- it says nothing +# about whether $STAMP ITSELF can be replaced. The gap between those two is exactly how the +# reviewer reproduced a live duplicate: with $STAMP made a DIRECTORY (a botched restore, or a +# `mkdir` typo) or with `uchg` set on it, the directory-probe pre-flight passed every single time +# -- it never touched $STAMP -- keel ran and PLACED ORDERS, and only the real post-cycle write, +# which actually targets $STAMP, then failed. Five triggers in one UTC day reproduced as exit 66 +# five times over with FIVE cycles having already run, each placing real orders -- precisely the +# "exiting nonzero AFTER a cycle already ran does not prevent the duplicate" pattern this +# pre-flight exists to reject, just never closed for this particular case before now. Probing the +# real path closes that gap by construction: if $STAMP cannot be replaced, this probe fails for +# the identical reason the real write would have, before any cycle runs. +# +# First, reject outright a stamp that EXISTS but is not a REGULAR FILE. This is not just a cheap +# shortcut for the directory case (though it is that): `mv -f` onto a directory does not replace +# it, it silently MOVES the temp file INSIDE the directory, which could make the round-trip below +# spuriously "succeed" (the readback could even find stale content left over from some earlier +# probe) while never proving $STAMP itself is replaceable at all. Catching the wrong file TYPE +# here, before ever attempting the round-trip, avoids that trap entirely. +if [ -e "$STAMP" ] && [ ! -f "$STAMP" ]; then + notify "keel-live: the day-stamp path (${STAMP}) exists but is not a regular file -- refusing to run a cycle. An operator needs to inspect and fix ${STAMP} (e.g. a botched restore left a directory there, or clear an immutable flag)." + printf '%s [keel-live] pre-flight FAILED -- %s exists and is not a regular file -- refusing to run a cycle -- exit 66\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMP" + exit 66 +fi +# +# Then round-trip through $STAMP itself: write a temp file, `mv -f` it ONTO $STAMP (the identical +# two steps the real post-cycle write below performs), and read $STAMP back. When a stamp already +# exists, the probe payload is that stamp's OWN current contents ($STAMPED, already read and +# validated above, before this point $STAMPED is either empty or a real ISO date strictly before +# today) -- so a successful probe is a semantic NO-OP: $STAMP ends this block holding exactly what +# it held going in. When there is no stamp yet, the probe payload is a throwaway marker, and a +# successful probe removes it again so the day is left correctly UNSTAMPED, exactly as if this +# pre-flight had never run. +# +# A crash between the `mv -f` and the cleanup/notify below is possible, but it is SAFE, not silent: +# it would leave $STAMP holding the literal marker text, which is not an ISO date, so the very next +# trigger hits the A2 malformed-stamp check above and refuses LOUDLY (exit 65) instead of treating +# the marker as a real stamp. A rare failure turning into a loud, correctly-classified refusal on +# the next trigger is the pattern this whole script is built around -- see the EXIT CODES header. +# +# (Note for anyone tempted to "simplify" this: a stamp with mode 000 must keep working, and does -- +# `mv -f` is a rename, which only needs WRITE permission on the containing directory, never on the +# target file itself, so it replaces a mode-000 $STAMP exactly as readily as a normal one.) +if [ -n "$STAMPED" ]; then + PREFLIGHT_PAYLOAD="$STAMPED" + PREFLIGHT_HAD_STAMP=1 +else + PREFLIGHT_PAYLOAD="preflight-probe-$$" + PREFLIGHT_HAD_STAMP=0 +fi PREFLIGHT_PROBE="$STAMP.preflight.$$" -if { printf 'preflight-probe\n' >"$PREFLIGHT_PROBE"; } 2>/dev/null \ - && [ "$(cat "$PREFLIGHT_PROBE" 2>/dev/null || true)" = "preflight-probe" ] \ - && rm -f "$PREFLIGHT_PROBE" 2>/dev/null; then - : # persistable -- proceed +if { printf '%s\n' "$PREFLIGHT_PAYLOAD" >"$PREFLIGHT_PROBE"; } 2>/dev/null \ + && mv -f "$PREFLIGHT_PROBE" "$STAMP" 2>/dev/null \ + && [ "$(cat "$STAMP" 2>/dev/null || true)" = "$PREFLIGHT_PAYLOAD" ]; then + if [ "$PREFLIGHT_HAD_STAMP" -eq 0 ]; then + rm -f "$STAMP" 2>/dev/null || true + fi else rm -f "$PREFLIGHT_PROBE" 2>/dev/null || true - notify "keel-live: cannot persist the day-stamp (logs directory or disk problem near ${STAMP}) -- refusing to run a cycle, because an unstamped success would duplicate on the next trigger." - printf '%s [keel-live] pre-flight FAILED -- could not write/read/remove a probe file next to %s -- refusing to run a cycle -- exit 66\n' \ + notify "keel-live: cannot persist the day-stamp (${STAMP} could not be replaced via the real write path) -- refusing to run a cycle, because an unstamped success would duplicate on the next trigger." + printf '%s [keel-live] pre-flight FAILED -- could not replace %s via the real write path -- refusing to run a cycle -- exit 66\n' \ "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMP" exit 66 fi @@ -360,9 +440,15 @@ if [ "$STATUS" -eq 0 ]; then rm -f "$FAILCOUNT" 2>/dev/null || true else rm -f "$STAMP_TMP" 2>/dev/null || true - notify "keel-live: the day-stamp write FAILED after a cycle already ran -- an order may already be placed. INVESTIGATE ${STAMP} IMMEDIATELY before the next trigger." - printf '%s [keel-live] stamp write FAILED after a clean cycle -- %s does not read back as %s -- exit 66\n' \ - "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMP" "$TODAY" >>"$OUTLOG" + # A9. The pre-flight above proved $STAMP replaceable BEFORE this cycle ran; something changed + # in the window between that check and this write, and a cycle has now run without us being + # able to record it. Dropping $HALT here, in the directory the pre-flight just proved is + # writable, is what stops every trigger from here on rather than just this one -- see the + # top-of-script check for what that buys. + : >"$HALT" 2>/dev/null || true + notify "keel-live: the day-stamp write FAILED after a cycle already ran -- an order may already be placed. INVESTIGATE ${STAMP} IMMEDIATELY before the next trigger. The detector is now HALTED (${HALT}) until a human clears it." + printf '%s [keel-live] stamp write FAILED after a clean cycle -- %s does not read back as %s -- HALT sentinel written to %s -- exit 66\n' \ + "$(date -u '+%Y-%m-%d %H:%M UTC')" "$STAMP" "$TODAY" "$HALT" >>"$OUTLOG" exit 66 fi else diff --git a/keel/agent.py b/keel/agent.py index 8e5d9d82..972d9805 100644 --- a/keel/agent.py +++ b/keel/agent.py @@ -942,13 +942,20 @@ def run_once( # to avoid an unbounded, unrecoverable duplication is the trade this whole module exists # to make. # - # This is also what makes the runner's retry IDEMPOTENT, which is the property that - # gives "<= 60 minutes of delay" its meaning: a blocked cycle places nothing and (via - # `keel-live-run.sh`'s exit-4 contract) leaves the day unstamped, so the retry an hour - # later starts from "nothing happened yet", not "something happened and needs to happen - # again". Without that idempotence, "delay" is just a duplicate that hasn't landed yet. + # This is also what makes the runner's retry IDEMPOTENT FOR ENTRIES, which is the + # property that gives "<= 60 minutes of delay" its meaning: a blocked cycle places NO + # entries and (via `keel-live-run.sh`'s exit-4 contract) leaves the day unstamped, so the + # retry an hour later starts from "no entry happened yet", not "an entry happened and + # needs to happen again". Without that idempotence, "delay" is just a duplicate entry + # that hasn't landed yet. # - # EXITS are deliberately exempt from all of this -- see the main pass below. + # A blocked cycle is NOT inert, though: EXITS are deliberately exempt from all of this -- + # see the main pass below -- and still run for every non-stale product regardless of + # `entries_allowed`, so THIS SAME cycle can place a real SELL even while every entry was + # withheld. That exemption is correct on its own terms (the protective stop rests at the + # broker, but the rule-driven channel exit runs IN-PROCESS, and trapping a losing + # position an extra cycle is strictly worse than a delayed entry) -- the point here is + # only that "entries withheld" must never be misread as "this cycle placed nothing". for product_id in products: if finest is not None and not market_feed.is_fresh( repo, product_id, finest, now_ts, max_age_sec diff --git a/tests/test_agent.py b/tests/test_agent.py index 6f324b45..6546f90d 100644 --- a/tests/test_agent.py +++ b/tests/test_agent.py @@ -2617,3 +2617,84 @@ def test_a_stale_products_missing_feed_does_not_withhold_a_different_products_en orders = repo.get_orders(mode="live", product_id=PRODUCT) assert len(orders) == 1 assert orders[0]["side"] == "BUY" + + +def test_retry_after_a_blocked_cycle_does_not_duplicate_an_already_placed_exit(repo): + """THE PROPERTY THAT MAKES "the runner declines to stamp and retries" SAFE FOR EXITS. #174 + turned "a nonzero exit runs after exits have already run this UTC day" from a rare, + exception-only path into a ROUTINE one: every blocked cycle now takes it, because a blocked + cycle still runs `_handle_exits` for every non-stale product (see the pre-pass comment in + `run_once`) and then exits 4, which makes `keel-live-run.sh` decline to stamp the day, and + one of the remaining hourly triggers re-runs the SAME cycle an hour later. If that retry + re-placed an already-placed exit, it would SELL a position that was already sold -- + dumping it a second time into whatever the market happens to be doing an hour on. + + Seeds a position on BTC-USD owned by `fake_exit` (`exit_signal` always fires) alongside a + blocked XLM-USD `dca` entry, so the FIRST cycle both places the exit AND reports + `blocked_entries` non-empty -- the exact shape #174 makes routine. It then re-runs `run_once` + at the SAME `now_ts` against the SAME repo/broker state, exactly as the retried hourly + trigger would, and asserts exactly ONE SELL order exists across both cycles. + + CORRECTING THE STATED PREMISE, by mutation, not by inspection alone: this test was + commissioned to pin `_handle_exits` clearing `agent_state["position_rule:"]` on + placement (~line 631) as THE mechanism that stops the duplicate. That is not what a mutation + test can honestly show. Un-clearing `position_rule:` ALONE does NOT turn this test + red -- `_handle_exits`'s own `if qty <= 0: return []` (`_held_position`, the filled-orders + audit log) already reads the position as closed on the retry: an exit is always a market + order, so its own SELL is recorded `status="filled"` the instant it places, and net qty + (buys minus sells) is what BOTH `agent._handle_exits` AND, independently, + `execution.executor._build_intent`'s own separate `_held_position` check before either one + ever consults `position_rule` at all. The system is triple-redundant: that qty check in + `agent.py`, the same qty check (separately implemented) in `executor.py`, and the + `position_rule` clear each independently block the duplicate -- breaking any ONE OR TWO of + the three still leaves this test green, and only breaking all three at once produces a + second SELL. `position_rule` clearing is real and matters, but for a DIFFERENT reason (see + its own comment at the clear site: stale bracket state poisoning the NEXT position opened on + this product, not this retry) -- not for the property this test pins. The primary mechanism + for THIS property is the audit-log qty netting in `_held_position`: a placed exit is itself + a filled SELL, so the very next read of "what do we hold" already reflects it. + """ + config = _blocked_cycle_config() + now_ts = 11 * _DAY + + # BTC-USD holds a position owned by `fake_exit` (always exits). + _seed_open_position( + repo, PRODUCT, Decimal("0.1"), Decimal("50000"), ts=1_000, rule_name="fake_exit" + ) + repo.insert_rule("fake_exit", {"product_id": PRODUCT}, status="live") + repo.set_state(f"position_rule:{PRODUCT}", "fake_exit") + fresh_daily = [_candle(10 * _DAY, "100")] + repo.upsert_candles(PRODUCT, Granularity.ONE_DAY, fresh_daily) + + # XLM-USD's dca entry is blocked -- withholds the WHOLE cycle's entries, exactly the + # scenario a real blocked cycle exits #174 makes ROUTINE. + repo.insert_rule("dca", {"product_id": _XLM, "cadence_days": 1}, status="live") + blocked_daily = [_candle(9 * _DAY, "100")] + repo.upsert_candles(_XLM, Granularity.ONE_DAY, blocked_daily) + + broker = FakeBroker( + series={ + (PRODUCT, Granularity.ONE_DAY): fresh_daily, + (_XLM, Granularity.ONE_DAY): blocked_daily, + } + ) + + first = run_once(broker, repo, config, now_ts=now_ts) + assert first.blocked_entries != [] + assert len(first.exit_results) == 1 + assert first.exit_results[0].placed is True + + # The retry: SAME `now_ts`, SAME repo/broker state -- exactly what the next hourly trigger + # runs, because the blocked cycle's exit-4 left the UTC day unstamped (`keel-live-run.sh`). + second = run_once(broker, repo, config, now_ts=now_ts) + # XLM-USD's data hasn't caught up between cycles (nothing in this test advances it), so the + # retry is blocked again too -- confirms this really is the SAME cycle re-running against + # the SAME unconfirmed bar, not a coincidentally-unblocked second attempt. + assert second.blocked_entries != [] + + orders = repo.get_orders(mode="live", product_id=PRODUCT) + sells = [o for o in orders if o["side"] == "SELL"] + assert len(sells) == 1, ( + f"the retry duplicated the exit -- expected exactly one SELL across both cycles, " + f"got {len(sells)}: {sells!r}" + ) diff --git a/tests/test_rule_manifest.py b/tests/test_rule_manifest.py index a16292e6..be569413 100644 --- a/tests/test_rule_manifest.py +++ b/tests/test_rule_manifest.py @@ -169,15 +169,9 @@ def test_committed_manifest_is_valid(tmp_path: Path) -> None: # the coincidence itself, so that if the operator ever moves the budget off the default, the # value check regains its old power and (3) is what tells them so. # - # SCOPE, so nobody reads more assurance into this than it gives. Everything below asserts - # against the COMMITTED FILE, `deploy/live-rules.json` -- not against any deployment's - # database. So it does NOT detect a box that has been reseeded; it detects a reseeded box's - # state being COMMITTED, i.e. someone re-running `rule_manifest.py export` against a - # reseeded DB and committing the diff. That is the reviewable choke point this manifest - # exists to create, and it is worth guarding -- but the reseed itself is silent on the box - # until an export happens, and nothing here changes that. Catching it live would take a - # check against a real DB (`rule_manifest.py apply` already reports exactly that drift and - # exits 1), which is a deploy-time step, not a unit test. + # SCOPE: this asserts the COMMITTED FILE, not a deployment's database, so it catches a + # reseeded box's state being COMMITTED -- not the reseed itself. `rule_manifest.py apply` + # is what reports that drift against a live DB. # (1) AGREEMENT -- the manifest's budget must match config.dca.budget_usd, the value the live # executor actually spends. diff --git a/tests/test_schedule.py b/tests/test_schedule.py index 356c22ba..701e2a0c 100644 --- a/tests/test_schedule.py +++ b/tests/test_schedule.py @@ -560,6 +560,70 @@ def test_run_script_reads_the_clock_in_utc() -> None: assert re.search(r'^HOUR="\$\(\(10#\$HOUR_RAW\)\)"$', source, re.MULTILINE) +def test_stamp_write_uses_atomic_temp_file_then_mv_with_readback() -> None: + """Finding 2 (HIGH), the SOURCE-level pin for the post-cycle stamp write's design. + + Follows the precedent of `test_run_script_reads_the_clock_in_utc` above (which greps the + script rather than executing it): atomicity is a property of the SHAPE of the write, not of + any one outcome a behavioural test can force. The BEHAVIOURAL test right below, + `test_atomic_stamp_write_leaves_yesterdays_stamp_intact_on_failure`, demonstrates the stamp + survives a failed write, but its docstring now explains -- and this test exists precisely + because -- the only failure mode available on this hardware (`chflags + uchg`) fails at `open(2)` BEFORE any truncation would happen, so a plain truncating + `>"$STAMP"` passes that behavioural test identically. This is the same class of miss that let + an earlier regression through: a docstring asserting a discrimination the test did not + actually make. This test makes the discrimination the OTHER way -- by pinning the source shape + directly -- so nothing here can drift back into that tautology unnoticed. + + Only lines of actual bash are searched (comment lines are stripped first): the header prose + a few lines above this design uses the literal text `> "$STAMP"` as a worked example of the + exact bug this design avoids, and a naive full-text search would flag that prose as a + violation of the very thing it is explaining. + + Must kill all three of the mutations called out when this test was authored -- each was + performed against the shipped script, confirmed to turn this test red, then reverted and + confirmed green again: + 1. reverting to a plain `printf ... >"$STAMP"` (no temp file, no `mv`, no readback); + 2. keeping the temp file and `mv -f` but dropping the readback verification; + 3. keeping the temp file and readback but replacing `mv -f` with something non-atomic + (e.g. `cp -f`), which drops the atomicity while looking superficially similar. + """ + source = RUN_SCRIPT.read_text() + code_only = "\n".join( + line for line in source.splitlines() if not line.lstrip().startswith("#") + ) + + # Mutation 1's signature: no bare truncating redirect onto $STAMP anywhere in the actual code. + # This is the exact gap `chflags uchg` cannot probe (it fails at open(2), before truncation), + # so this is the ONLY thing in this file that actually rules a plain `>"$STAMP"` out. + assert not re.search(r'>\s*"\$STAMP"', code_only), ( + 'found a bare truncating redirect onto "$STAMP" in the script -- the stamp must only ever ' + "be written via a temp file + `mv -f`, never opened directly, or a torn write can leave it " + "empty" + ) + + # The write goes to a $STAMP-derived temp path... + assert re.search(r'STAMP_TMP="\$STAMP\.tmp\.\$\$"', code_only), ( + "the post-cycle stamp write must go to a $STAMP-derived temp path first, not $STAMP itself" + ) + assert re.search(r"printf '%s\\n' \"\$TODAY\" >\"\$STAMP_TMP\"", code_only), ( + "the temp file must be written with $TODAY as its payload" + ) + + # ...which is then mv -f'd ONTO $STAMP -- the atomic step itself (mutation 3's target)... + assert re.search(r'mv -f "\$STAMP_TMP" "\$STAMP"', code_only), ( + "the temp file must be renamed onto $STAMP with `mv -f`, not copied or otherwise written " + "in a way that is not atomic within one filesystem" + ) + + # ...and the RESULT is read back and compared to $TODAY (mutation 2's target), not merely + # trusted because `mv` exited 0. + assert re.search(r'\[ "\$\(cat "\$STAMP" 2>/dev/null \|\| true\)" = "\$TODAY" \]', code_only), ( + "the write must be verified by reading $STAMP back and comparing it to $TODAY -- a `mv` " + "that exits 0 is necessary but not sufficient evidence the stamp actually reads correctly" + ) + + # -- harness: run the REAL script under a shimmed clock, with notifications recorded ----------- # # Every test below this point executes `keel-live-run.sh` VERBATIM (only `DIR=` and the literal @@ -609,9 +673,11 @@ def _run_script(script: Path, *, env: dict[str, str]) -> subprocess.CompletedPro def _install_date_shim(bin_dir: Path) -> None: """Install a `date` on `PATH` that reads its instant from `$KEEL_TEST_NOW` (epoch seconds) - instead of the wall clock, plus two failure modes A1 needs: `KEEL_TEST_DATE_MODE=empty` - (produces no output -- the empty-`date -u` case this hardware can produce) and `=garbage` - (produces non-date text). + instead of the wall clock, plus three failure modes: `KEEL_TEST_DATE_MODE=empty` (produces no + output -- the empty-`date -u` case this hardware can produce, needed for A1), `=garbage` + (produces non-date text, also A1), and `=bad_hour` (a well-formed DATE but an out-of-range + HOUR -- needed to reach the `-gt 23` check at all, since that line is only reachable once the + two-digit-shape regex in A1 has already passed). Honours ONLY the invocation forms `keel-live-run.sh` actually uses (`date -u '+FORMAT'`) -- this is deliberately not a general `date(1)` replacement. @@ -623,6 +689,10 @@ def _install_date_shim(bin_dir: Path) -> None: 'case "${KEEL_TEST_DATE_MODE:-fixed}" in\n' " empty) exit 0 ;;\n" ' garbage) printf "%s\\n" "${KEEL_TEST_DATE_GARBAGE:-not-a-date}"; exit 0 ;;\n' + ' bad_hour) case "$*" in\n' + ' *%H*) printf "%s\\n" "${KEEL_TEST_HOUR_GARBAGE:-99}" ;;\n' + ' *) exec /bin/date -u -r "$KEEL_TEST_NOW" "$@" ;;\n' + " esac ;;\n" ' *) exec /bin/date -u -r "$KEEL_TEST_NOW" "$@" ;;\n' "esac\n" ) @@ -901,7 +971,7 @@ def test_unwritable_logs_dir_means_the_cycle_never_runs(tmp_path: Path) -> None: logs_dir.chmod(0o555) try: result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) - assert result.returncode != 0, "an unpersistable stamp must not exit 0" + assert result.returncode == 66, "an unpersistable stamp must exit exactly 66 (pre-flight)" assert _count_lines(sb.invocations_log) == 0, "keel must never be invoked pre-flight" assert sb.calls_log.exists() and sb.calls_log.read_text().strip(), ( "a condition the machine cannot self-heal must alert a human" @@ -910,16 +980,137 @@ def test_unwritable_logs_dir_means_the_cycle_never_runs(tmp_path: Path) -> None: logs_dir.chmod(original_mode) +def test_unreplaceable_stamp_directory_blocks_every_trigger_before_any_cycle_runs( + tmp_path: Path, +) -> None: + """Finding 1 (MEDIUM), the reviewer's exact reproduction: the OLD pre-flight wrote its probe + to a DIFFERENT path (`$STAMP.preflight.$$`), which proves only that the DIRECTORY is writable + -- never that $STAMP ITSELF can be replaced. With $STAMP made a DIRECTORY (a botched restore, + or a `mkdir` typo), that pre-flight passed every single time, keel ran and PLACED ORDERS, and + only the unrelated post-cycle write -- which actually targets $STAMP -- then failed, five + triggers in a row: + + exit codes: 66 66 66 66 66 + CYCLES RUN: 5 <- each one places real orders + notifications: 5 + + That is precisely the "exiting nonzero AFTER a cycle already ran does not prevent the + duplicate" pattern the pre-flight's own comment already rejects for the read-only-directory + case (see `test_unwritable_logs_dir_means_the_cycle_never_runs` above) -- it just was never + true for THIS case before now. The fix makes the pre-flight round-trip through $STAMP itself + (write a temp file, `mv -f` it ONTO $STAMP, read $STAMP back), so it now fails BEFORE keel is + ever invoked, on every one of the five triggers, not just eventually. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + sb.stamp.mkdir(parents=True) + + for day in (15, 16, 17, 18, 19): + result = _run(sb, datetime(2026, 6, day, 1, 20, tzinfo=UTC)) + assert result.returncode == 66, f"day {day}: expected exit 66 (pre-flight failure)" + + assert _count_lines(sb.invocations_log) == 0, ( + "keel must NEVER be invoked while $STAMP cannot be replaced -- the old defect let all 5 " + "cycles run and place orders before the (unrelated) post-cycle write ever failed" + ) + assert _count_lines(sb.calls_log) == 5, "every one of the 5 triggers must alert a human" + + +def test_stamp_with_mode_000_is_still_replaceable_via_rename(tmp_path: Path) -> None: + """Finding 1 (MEDIUM), the explicit case the fix must NOT break: `mv -f` is a rename, and a + rename only ever needs WRITE permission on the containing DIRECTORY, never on the target file + itself. So a stamp with mode 000 -- unreadable and unwritable by its own permission bits -- + must still be perfectly replaceable, and the pre-flight (which now round-trips through $STAMP + itself rather than a same-named probe) must not mistake "I cannot read/write this inode + directly" for "this path cannot be replaced". `cat` on a mode-000 file fails, so $STAMPED + reads as empty here (the same as "no stamp yet") -- which is a pre-existing, unrelated + property of how $STAMPED is read at the top of the script, not something this fix changes. + """ + stamp_path = tmp_path / "logs" / ".keel-live-last-run" + (tmp_path / "logs").mkdir(parents=True, exist_ok=True) + stamp_path.write_text("2026-06-14\n") + stamp_path.chmod(0o000) + try: + sb = _sandbox(tmp_path, keel_exit_code=0) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode == 0, "a mode-000 stamp must not block the pre-flight or the cycle" + assert _count_lines(sb.invocations_log) == 1, "the cycle must have actually run" + assert sb.stamp.read_text().strip() == "2026-06-15", ( + "the real post-cycle write must succeed too, via the same rename mechanism" + ) + finally: + stamp_path.chmod(0o644) + + +def test_immutable_regular_file_stamp_is_caught_by_the_preflight_round_trip( + tmp_path: Path, +) -> None: + """Finding 1 (MEDIUM): the case that pins the ROUND-TRIP specifically, rather than the + is-it-a-regular-file check that sits next to it. + + Those two pre-flight guards are mutually redundant for the DIRECTORY case + (`test_unreplaceable_stamp_directory_blocks_every_trigger_before_any_cycle_runs`): remove + either one alone and the other still catches a directory, so neither is individually killed + by that test. Verified by mutation -- neutering the regular-file check alone, or the + round-trip alone, left the whole suite green; only neutering BOTH went red. A guard no test + can kill on its own is a guard that can be deleted by a future refactor without anything + noticing, which is exactly how the defect this fix closes got in. + + An IMMUTABLE (`chflags uchg`) stamp is the discriminating case: it IS a regular file, so the + `[ ! -f ]` check passes it straight through, and only the round-trip -- which actually + attempts `mv -f` ONTO $STAMP -- discovers that the path cannot be replaced. Without the + round-trip the pre-flight would wave this through, keel would run and PLACE ORDERS, and only + the post-cycle write would fail, leaving the day unstamped for the next trigger to repeat -- + the duplicate-order shape this whole fix exists to prevent. + + Note this is the pre-flight's own detection, distinct from + `test_atomic_stamp_write_leaves_yesterdays_stamp_intact_on_failure` below, which sets `uchg` + MID-CYCLE to force the post-cycle write to fail after a legitimately passing pre-flight. + """ + logs = tmp_path / "logs" + logs.mkdir(parents=True, exist_ok=True) + stamp_path = logs / ".keel-live-last-run" + stamp_path.write_text("2026-06-14\n") + subprocess.run(["chflags", "uchg", str(stamp_path)], check=False) + try: + sb = _sandbox(tmp_path, keel_exit_code=0) + for day in (15, 16, 17): + result = _run(sb, datetime(2026, 6, day, 1, 20, tzinfo=UTC)) + assert result.returncode == 66, ( + f"day {day}: an immutable stamp must fail the pre-flight with exit 66, not be " + "waved through to a cycle that places orders it cannot then record" + ) + assert _count_lines(sb.invocations_log) == 0, ( + "keel must NEVER be invoked while $STAMP cannot be replaced -- an immutable stamp is " + "a regular file, so ONLY the pre-flight's round-trip onto $STAMP can detect it" + ) + assert _count_lines(sb.calls_log) == 3, "every trigger must alert a human" + assert stamp_path.read_text().strip() == "2026-06-14", ( + "the pre-flight must not have altered the stamp it could not replace" + ) + finally: + subprocess.run(["chflags", "nouchg", str(stamp_path)], check=False) + + def test_atomic_stamp_write_leaves_yesterdays_stamp_intact_on_failure(tmp_path: Path) -> None: """Finding 2 (HIGH): a torn/failed post-cycle write must never leave the stamp EMPTY or PARTIAL. - Plain `> "$STAMP"` truncates before it writes, so a write that dies partway leaves an EMPTY - stamp -- and an empty stamp reads as "never ran", re-running a UTC day that already traded. - Here the write is forced to fail AFTER the pre-flight probe (a differently-named file) has - already passed, by making the stamp file itself immutable partway through the "cycle" -- and - the pre-existing YESTERDAY stamp must survive completely unchanged: not empty, not today, not - partial. That is what the temp-file-then-`mv -f` design buys: a rename either fully happens or - fully does not. + Forces the write to fail AFTER the pre-flight probe has already passed, by making the stamp + file itself immutable partway through the "cycle" -- and asserts the pre-existing YESTERDAY + stamp survives completely unchanged: not empty, not today, not partial. + + This is a BEHAVIOURAL test, and that is ALL it proves. An earlier version of this docstring + additionally claimed it demonstrated the temp-file-then-`mv -f` design's ATOMICITY ("that is + what the ... design buys"). That claim was FALSE: the only failure mode available on this + hardware, `chflags uchg`, makes the write fail at `open(2)` -- BEFORE any truncation would ever + happen -- so a plain truncating `printf '%s\\n' "$TODAY" >"$STAMP"` preserves yesterday's stamp + here exactly as well as the real design does (verified: swapping the whole `STAMP_TMP` + + `mv -f` + readback block for that one line left this test, and all of this file's other + tests, green). A behavioural test cannot discriminate a design property from a coincidence of + its one available failure mode, no matter how the docstring reads -- do not "fix" this by + trying to force a different failure mode; on this hardware there isn't one. The actual pin for + the temp-file/`mv -f`/readback SHAPE is the source-level + `test_stamp_write_uses_atomic_temp_file_then_mv_with_readback` above, which greps the script's + source instead of trying to observe atomicity behaviourally. """ stamp_path = tmp_path / "logs" / ".keel-live-last-run" yesterday = "2026-06-14" @@ -927,7 +1118,7 @@ def test_atomic_stamp_write_leaves_yesterdays_stamp_intact_on_failure(tmp_path: stamp_path.write_text(yesterday + "\n") try: result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) - assert result.returncode != 0 + assert result.returncode == 66, "a post-cycle stamp-write failure must exit exactly 66" assert stamp_path.read_text().strip() == yesterday, ( "the stamp must never be corrupted by a failed write -- it must read exactly what it " "read before the cycle ran" @@ -950,7 +1141,7 @@ def test_stamp_write_failure_is_not_swallowed(tmp_path: Path) -> None: stamp_path.write_text("2026-06-14\n") try: result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) - assert result.returncode != 0, "a stamp write failure must not exit 0" + assert result.returncode == 66, "a post-cycle stamp-write failure must exit exactly 66" assert sb.calls_log.exists() and sb.calls_log.read_text().strip(), ( "a stamp write failure must alert a human -- silence here IS the Finding-2 bug" ) @@ -958,6 +1149,59 @@ def test_stamp_write_failure_is_not_swallowed(tmp_path: Path) -> None: subprocess.run(["chflags", "nouchg", str(stamp_path)], check=False) +def test_stamp_write_failure_halts_every_subsequent_trigger_until_cleared(tmp_path: Path) -> None: + """Finding 1 (MEDIUM), part (b): the HALT SENTINEL closes the RESIDUAL window neither + pre-flight layer can close -- $STAMP can still become unreplaceable in the gap BETWEEN a + passing pre-flight and the post-cycle write (e.g. a volume drops read-only mid-cycle). By the + time the post-cycle write discovers that, a cycle has ALREADY RUN, and with autonomy ON may + have placed an order. Without a sentinel, the very next trigger would see the day still + unstamped and run ANOTHER cycle, compounding the exact duplicate the day-stamp exists to + prevent. The sentinel bounds the damage to the ONE cycle that already ran: every trigger after + the failure must refuse outright and loudly, not just alert and move on, until a human clears + it. + + Reuses the `chflags uchg` mid-cycle trick to force the post-cycle write to fail (the pre-flight + still passes, since the stamp is not yet immutable when it runs) -- the same mechanism the + Finding-2 tests above use, just followed through to its consequence for LATER triggers instead + of stopping at the first one. + """ + stamp_path = tmp_path / "logs" / ".keel-live-last-run" + halt_path = tmp_path / "logs" / ".keel-live-last-run.halt" + sb = _sandbox(tmp_path, keel_exit_code=0, keel_stub_extra=f'chflags uchg "{stamp_path}"') + stamp_path.write_text("2026-06-14\n") + try: + first = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert first.returncode == 66, "the post-cycle write failure itself still exits 66" + assert halt_path.exists(), "a post-cycle stamp-write failure must drop the halt sentinel" + ran_after_failure = _count_lines(sb.invocations_log) + assert ran_after_failure == 1, ( + "exactly the one cycle that already ran is the damage this is meant to bound" + ) + + calls_before = _count_lines(sb.calls_log) + for day in (16, 17, 18): + again = _run(sb, datetime(2026, 6, day, 1, 20, tzinfo=UTC)) + assert again.returncode == 68, f"day {day}: every trigger under the sentinel exits 68" + assert _count_lines(sb.invocations_log) == ran_after_failure, ( + "the sentinel must block keel from ever being invoked again -- not just alert louder" + ) + assert _count_lines(sb.calls_log) == calls_before + 3, ( + "the halt must alert on EVERY trigger it blocks, not once and then go quiet" + ) + + # A human clears the sentinel (having first fixed the underlying cause -- here, the + # immutable flag). Uses a FRESH sandbox without the `chflags` stub so the next cycle can + # actually complete cleanly, exactly as an operator's next real trigger would. + subprocess.run(["chflags", "nouchg", str(stamp_path)], check=False) + halt_path.unlink() + recovered_sb = _sandbox(tmp_path, keel_exit_code=0) + recovered = _run(recovered_sb, datetime(2026, 6, 19, 1, 20, tzinfo=UTC)) + assert recovered.returncode == 0, "clearing the sentinel must restore normal operation" + assert recovered_sb.stamp.read_text().strip() == "2026-06-19" + finally: + subprocess.run(["chflags", "nouchg", str(stamp_path)], check=False) + + def test_empty_clock_output_refuses_to_run(tmp_path: Path) -> None: """Finding 3 (MED): `date -u` returning EMPTY must not silently read as "already ran, forever". @@ -969,7 +1213,7 @@ def test_empty_clock_output_refuses_to_run(tmp_path: Path) -> None: """ sb = _sandbox(tmp_path, keel_exit_code=0) result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC), date_mode="empty") - assert result.returncode != 0 + assert result.returncode == 64, "an empty clock must exit exactly 64" assert _count_lines(sb.invocations_log) == 0, "a broken clock must never reach a cycle" assert not sb.stamp.exists(), "a broken clock must not be recorded as a completed day" assert "already ran" not in result.stdout, ( @@ -988,29 +1232,78 @@ def test_garbage_clock_output_refuses_to_run(tmp_path: Path) -> None: """ sb = _sandbox(tmp_path, keel_exit_code=0) result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC), date_mode="garbage") - assert result.returncode != 0 + assert result.returncode == 64, "a garbage clock must exit exactly 64, same as an empty one" assert _count_lines(sb.invocations_log) == 0 assert not sb.stamp.exists() assert "already ran" not in result.stdout assert sb.calls_log.exists() and sb.calls_log.read_text().strip() +def test_out_of_range_hour_refuses_to_run(tmp_path: Path) -> None: + """LOW finding: pins the `-gt 23` hour-range check specifically. + + Mutating that condition to `if false` survives the rest of the suite untouched, because every + OTHER clock test here produces HOUR_RAW that either fails the two-digit shape regex in A1 + (`empty`/`garbage`, caught one check earlier) or is an ordinary, in-range hour. `99` is chosen + precisely because it PASSES `^[0-9]{2}$` -- so this is the only test in the file that actually + reaches the `-gt 23` line at all; nothing that is rejected earlier proves anything about it. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC), date_mode="bad_hour") + assert result.returncode == 64, "an out-of-range hour must be rejected the same way as A1" + assert _count_lines(sb.invocations_log) == 0, "a broken clock must never reach a cycle" + assert not sb.stamp.exists(), "a broken clock must not be recorded as a completed day" + assert sb.calls_log.exists() and sb.calls_log.read_text().strip() + + def test_malformed_stamp_content_refuses_to_run(tmp_path: Path) -> None: """Finding 4 (MED): a corrupt on-disk stamp must never be silently COMPARED against today. `"garbage" < "2026-06-15"` is FALSE in a plain string compare, which reads exactly like "already ran" and disables the detector forever -- the same failure class as an unvalidated - empty clock, just entered from the stamp file instead of `date`. + empty clock, just entered from the stamp file instead of `date`. Uses "not-a-date", which + happens to sort ABOVE any real ISO date string -- the case where the malformed stamp sorts + BELOW today instead is the discriminating one for the exit-65 branch specifically, and is + covered separately by `test_malformed_stamp_that_sorts_below_today_still_refuses_to_run`. """ sb = _sandbox(tmp_path, keel_exit_code=0) sb.stamp.write_text("not-a-date\n") result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) - assert result.returncode != 0 + assert result.returncode == 65, "a malformed (non-ISO) stamp must exit exactly 65" assert _count_lines(sb.invocations_log) == 0 assert sb.stamp.read_text().strip() == "not-a-date", "a malformed stamp must not be overwritten" assert sb.calls_log.exists() and sb.calls_log.read_text().strip() +def test_malformed_stamp_that_sorts_below_today_still_refuses_to_run(tmp_path: Path) -> None: + """LOW finding: the discriminating case for the exit-65 branch existing at all. + + `test_malformed_stamp_content_refuses_to_run` uses "not-a-date", which sorts ABOVE any real + ISO date string -- so it lands in the exit-67 (stamp-ahead-of-today) branch too, which also + refuses and alerts, EVEN IF the exit-65 branch were deleted outright. Asserting merely + `returncode != 0` on that test cannot tell the two branches apart, so deleting the exit-65 + branch entirely survives the suite. + + "1999-1-1" is different: it fails the `^[0-9]{4}-[0-9]{2}-[0-9]{2}$` shape check (single-digit + month/day) exactly like "not-a-date" does, but it SORTS BELOW "2026-06-15" as a plain string. + Without a dedicated exit-65 check ahead of the ahead/equal/before comparisons, this stamp would + fall through to "stamp is before today" and RUN A CYCLE on a corrupt stamp -- silently + re-evaluating who-knows-what bar. That is precisely the silent-comparison failure class the A2 + comment in the script warns about, just for a malformed stamp instead of a well-formed one. + """ + sb = _sandbox(tmp_path, keel_exit_code=0) + sb.stamp.write_text("1999-1-1\n") + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + assert result.returncode == 65, ( + "a malformed stamp must exit exactly 65 regardless of how it happens to sort against today" + ) + assert _count_lines(sb.invocations_log) == 0, ( + "a malformed stamp must never let a cycle run, even one that sorts below today" + ) + assert sb.stamp.read_text().strip() == "1999-1-1", "a malformed stamp must not be overwritten" + assert sb.calls_log.exists() and sb.calls_log.read_text().strip() + + def test_clock_rollback_does_not_rerun_or_move_the_stamp_backwards(tmp_path: Path) -> None: """Finding 4 (MED) / Defect 1 (MED): a clock reading a PAST date must not re-run -- and now alerts instead of skipping silently. @@ -1222,6 +1515,82 @@ def test_stuck_detector_escalates_after_consecutive_failures(tmp_path: Path) -> ) +@pytest.mark.parametrize( + "garbage", + [ + "not-a-number", + "-5", + "3.5", + " 12", + "12 ", + "", + ], +) +def test_read_failcount_treats_non_numeric_or_malshaped_content_as_zero( + tmp_path: Path, garbage: str +) -> None: + """LOW finding: pins `read_failcount`'s numeric validation. + + Replacing `read_failcount` with a raw passthrough of `$FAILCOUNT`'s content survives every + OTHER test in this file, because every existing failcount scenario starts from a file that is + either MISSING (already reads as 0 through the `cat ... || true` fallback, not through the + `^[0-9]+$` guard) or already holds a clean integer the guard would pass through unchanged + either way. A raw passthrough only differs from the guarded version when the content is + non-numeric or out of shape -- exactly the cases here. + + A raw passthrough is not merely "wrong", it is a crash risk: `$FAILS="$(($(read_failcount) + + 1))"` is bash ARITHMETIC context, and arithmetic on a non-numeric operand is a hard error + there (unlike string comparison, which merely comes out false). A negative number like `-5` + would not crash but WOULD silently miscount (next value -4 instead of the guarded 1); a + decimal like `3.5` or a leading/trailing-whitespace value would either error out or silently + produce a bogus count depending on the shell. Either way this is exactly the degrade-gracefully + contract `read_failcount`'s own comment promises: a corrupt counter file must make escalation + late or wrong, never make the retry stop happening or the exit status change. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir(parents=True, exist_ok=True) + failcount = logs_dir / ".keel-live-last-run.failures" + failcount.write_text(garbage) + + sb = _sandbox(tmp_path, keel_exit_code=3) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + + assert result.returncode == 3, "the script must surface keel's own exit code, not crash" + assert not sb.stamp.exists(), "a failing cycle must still leave the day open for retry" + assert _count_lines(sb.calls_log) == 0, ( + "garbage must be read as count 0, not as 1 or higher -- so a single failure after it is " + "exactly as silent as the very first failure ever would be" + ) + assert failcount.read_text().strip() == "1", ( + "the garbage must be OVERWRITTEN with a clean count of 1 -- neither preserved verbatim " + "nor corrupted further by the increment" + ) + + +def test_read_failcount_handles_a_large_valid_count_without_crashing_or_miscounting( + tmp_path: Path, +) -> None: + """LOW finding, the companion sanity check to the garbage-content test above: a large but + VALID (all-digit) failcount must be read, incremented, and escalated correctly -- proving the + numeric guard's job is to reject the wrong SHAPE, not to reject size, and that legitimately + large counts are not mistaken for corruption. + """ + logs_dir = tmp_path / "logs" + logs_dir.mkdir(parents=True, exist_ok=True) + failcount = logs_dir / ".keel-live-last-run.failures" + failcount.write_text("119") # one below the next ESCALATE_EVERY=3 multiple (120) + + sb = _sandbox(tmp_path, keel_exit_code=3) + result = _run(sb, datetime(2026, 6, 15, 1, 20, tzinfo=UTC)) + + assert result.returncode == 3 + assert failcount.read_text().strip() == "120", ( + "a large valid count must be incremented normally, not reset -- it is not garbage" + ) + assert _count_lines(sb.calls_log) == 1, "120 is a multiple of ESCALATE_EVERY=3 -- must alert" + assert "120 consecutive" in sb.calls_log.read_text() + + def test_pendlog_is_utc_labelled(tmp_path: Path) -> None: """Finding 10: PENDLOG's timestamp must say UTC, like every other line in this script.