From 8558025678f000aaa83722e9ae52a9b677d67381 Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Thu, 13 Aug 2026 01:17:29 -0400 Subject: [PATCH] feat(engine): two observable invariants, because neither past defect was findable by testing #254 and #257 both survived the entire project with 2,712 tests passing. Neither was found by looking for defects: #254 surfaced from a 34x non-monotonic trade count, #257 from asking why #254's fix REDUCED trade counts. The reason tests could not catch either generalises -- a frozen backtest and a highly selective strategy produce identical output, and so do a patient limit fill and a lucky one. Adding tests does not help, because a test asserts a behaviour someone already imagined. These two make each defect class announce itself in the ordinary output of an ordinary run. 1. PENDING LIFESPAN INVARIANT (keel/strategy/backtest.py) Asserts a pending setup is never carried across more than one bar. Since #257 the fill is unconditional, so the correct value is exactly 1 for every rule on every series -- checked, not thresholded, with no per-asset tuning and no false-positive mode. On UNI-USD under #254 this counter would have read ~40,000. The obvious alternative -- warn when trades stop long before the series ends -- was considered and REJECTED. #257 made the freeze structurally impossible, so a dead tail now only ever means the rule genuinely stopped firing (regime change, threshold too strict). That warning would fire exclusively on legitimate runs and burn the attention budget a real alert needs. If resting entry orders return (#260 Option B) the bound stops being 1, and the value it becomes IS the cancel/replace policy, stated in one place. 2. INTENT DIVERGENCE LOG (keel/execution/executor.py) The executor already persisted the rule's intended entry (`expected_fill`) and the achieved fill (`actual_fill`) on the same order row, and nothing compared them. That missing subtraction is exactly how #257 stayed invisible. `_log_intent_divergence` now reports signed basis points on every fill. Logged UNCONDITIONALLY, not past a threshold: a cutoff right for BTC is wrong for a thin book, and the per-asset liquidity model that would set one does not exist (#259). Gating this on that work would block the cheap half behind the expensive half. Same principle as #247 printing the fee rate -- make the number visible first, act on it second. Signed rather than absolute, because "we paid up" and "we got filled cheaper" are opposite failures for a rule whose entry encodes a condition. Never raises: telemetry on a settled order must not be able to fail a cycle. VERIFICATION. The lifespan invariant cannot be violated through the public API, so there is no red-then-green test and pretending otherwise would be theatre. Instead it was proven live: the fill path was deliberately broken and the assertion fired immediately, naming the rule and bar index. It also now sits in the hot loop of every backtest, so all 2,717 tests and the baseline golden execute it on every run. The divergence log has four real tests asserting on the STRUCTURED payload rather than caplog.text, which would have passed vacuously for any values. Neither touches order routing. 2717 passed, ruff clean. Refs #254, #257, #259, #260. Co-Authored-By: Claude Opus 5 (1M context) --- keel/execution/executor.py | 57 ++++++++++++++++++++-- keel/strategy/backtest.py | 42 +++++++++++++++- tests/execution/test_executor.py | 82 ++++++++++++++++++++++++++++++++ tests/strategy/test_backtest.py | 39 +++++++++++++++ 4 files changed, 215 insertions(+), 5 deletions(-) diff --git a/keel/execution/executor.py b/keel/execution/executor.py index 4e697a22..cde31fcc 100644 --- a/keel/execution/executor.py +++ b/keel/execution/executor.py @@ -60,7 +60,7 @@ import time from collections.abc import Callable, Mapping from dataclasses import dataclass, replace -from decimal import Decimal +from decimal import Decimal, InvalidOperation from typing import Any, Literal from keel_broker_api.results import Preview @@ -526,7 +526,7 @@ def _run_order( ) if success and status == "filled": - _upgrade_to_observed_economics(broker, repo, order_id, place_result, now_ts) + _upgrade_to_observed_economics(broker, repo, order_id, place_result, now_ts, intent) if not success: log_event( @@ -568,7 +568,12 @@ def _run_order( def _upgrade_to_observed_economics( - broker: Any, repo: Repository, order_id: int, place_result: dict[str, Any], now_ts: int + broker: Any, + repo: Repository, + order_id: int, + place_result: dict[str, Any], + now_ts: int, + intent: OrderIntent | None = None, ) -> None: """Replace an immediately-filled order's ESTIMATED economics with the exchange's observed ones. @@ -600,6 +605,52 @@ def _upgrade_to_observed_economics( if not fill or fill <= 0: return repo.update_order(order_id, actual_fill=fill, fee=fees, updated_at=now_ts) + _log_intent_divergence(order_id, intent, fill) + + +def _log_intent_divergence(order_id: int, intent: OrderIntent | None, realized: Any) -> None: + """Report how far the achieved fill sat from the price the RULE asked for. + + Both numbers were already persisted on the order row -- `expected_fill` at placement and + `actual_fill` from the venue -- and nothing compared them. That gap is exactly how #257 went + unnoticed: the executor places MARKET orders (`order_type="market"`, `limit_price=None`), so a + rule's `Setup.entry` is recorded and then not used to execute. For a rule entering at the + signal-bar close (`turtle_breakout`, `rsi_meanrev`) that is nearly free; for one whose entry + encodes a CONDITION (`pullback_continuation` uses `signal_candle.high + buffer_ticks` to demand + follow-through) production silently takes trades the rule meant to decline (#260). + + Logged UNCONDITIONALLY rather than past a threshold. A basis-point threshold that is right for + BTC is wrong for a thin book, and the per-asset liquidity model that would set it does not + exist yet (#259) -- gating this on that work would block the cheap half behind the expensive + half. This follows what #247 did with the fee rate: make the number visible first, act on it + second. `divergence_bps` is signed, so direction is legible without recomputing it: positive + means the fill came in ABOVE the rule's intended entry. + + Never raises. This is telemetry attached to an order that has already been placed and settled; + a formatting problem here must not fail a cycle. + """ + if intent is None: + return + try: + expected = Decimal(str(intent.entry)) + actual = Decimal(str(realized)) + if expected <= 0: + return + divergence_bps = (actual - expected) / expected * Decimal(10_000) + except (InvalidOperation, TypeError, ValueError): + log_exception(logger, "executor.intent_divergence_uncomputable", order_id=order_id) + return + + log_event( + logger, + logging.INFO, + "executor.intent_divergence", + order_id=order_id, + product=intent.product_id, + intent_entry=str(expected), + realized_fill=str(actual), + divergence_bps=f"{divergence_bps:.2f}", + ) def _order_row(intent: OrderIntent, mode: str, now_ts: int) -> dict[str, Any]: diff --git a/keel/strategy/backtest.py b/keel/strategy/backtest.py index d3ce1174..1997abec 100644 --- a/keel/strategy/backtest.py +++ b/keel/strategy/backtest.py @@ -69,8 +69,8 @@ # support, which touching would make a resting MAKER fill). Now that every entry is a market # order at the open, the taker rate is the right one for all of them, unconditionally. # -# Until #247 this -# default was the MAKER rate (0.006) while the fill model was unchanged, and the two halves of +# Until #247 this default was the MAKER rate (0.006) while the fill model was unchanged, and the +# two halves of # the project disagreed **in writing**: `config.yaml`'s own `fees:` comment says "taker_pct is # the sim's default -- it fills market-style at next-bar open", and `keel_core.config # .FeesConfig` has carried `taker_pct = 0.012` as its default the whole time. The config was @@ -242,10 +242,48 @@ def backtest( position: _OpenPosition | None = None pending: Setup | None = None trading_tf = _rule_trading_tf(rule) + #: Bars the current `pending` has survived. Since #257 a setup detected on bar i is filled + #: unconditionally at bar i+1's open, so this can only ever reach 1 -- see the invariant + #: check at the top of the loop. + pending_age = 0 for i, candle in enumerate(candles): candles_by_tf = {trading_tf: candles[: i + 1]} + # ENGINE INVARIANT: a pending setup is never carried across more than one bar. + # + # This is an assertion, not a heuristic, and it has no false-positive mode: since #257 + # every pending fills at the next bar's open, so the correct value is exactly 1 for every + # rule on every series. It is checked rather than thresholded, needs no per-asset tuning, + # and cannot fire on legitimate behaviour. + # + # It exists because #254 was invisible for the life of the project. A setup whose entry + # and stop were both never revisited pinned `pending` forever, `detect()` was never called + # again, and the engine silently switched its own detector off. On UNI-USD this counter + # would have read ~40,000. Nothing else caught it: 2,712 tests passed, and a frozen + # backtest is indistinguishable from a selective one in any summary output. + # + # The obvious alternative -- warn when trades stop long before the series ends -- was + # considered and REJECTED. #257 made the freeze structurally impossible, so a dead tail + # now only ever means the rule genuinely stopped firing (a regime change, a threshold too + # strict for recent volatility). Such a warning would fire exclusively on legitimate runs + # and spend the attention budget a real alert needs. + # + # If resting entry orders are ever reintroduced (#260's "Option B"), this bound stops + # being 1 -- and the value it becomes IS the cancel/replace policy, stated in one place. + if pending is not None: + pending_age += 1 + if pending_age > 1: + raise AssertionError( + f"engine invariant violated: rule {rule.name!r} on " + f"{getattr(pending, 'product_id', '?')} carried a pending setup across " + f"{pending_age} bars (bar index {i}). Since #257 every pending fills at the " + f"next bar's open, so this cannot exceed 1 -- the fill path has regressed " + f"(cf. #254, where the detector silently stopped being called)." + ) + else: + pending_age = 0 + if position is None and pending is None: pending = rule.detect(candles_by_tf) continue diff --git a/tests/execution/test_executor.py b/tests/execution/test_executor.py index b17e8e07..cc9b9f63 100644 --- a/tests/execution/test_executor.py +++ b/tests/execution/test_executor.py @@ -39,6 +39,7 @@ scale_out, trail_stop_atr, ) +from keel.execution.guards import OrderIntent from keel.strategy.rules.base import Action, Setup, Signal from keel.types import Side from tests.conftest import attest_subscription @@ -1613,3 +1614,84 @@ def test_a_placed_bracket_clears_an_earlier_unprotected_record(repo): ) assert repo.get_state("unbracketed:BTC-USD") is None + + +def _divergence_fields(caplog) -> dict: + """The structured payload of the last `executor.intent_divergence` record. + + `log_event` attaches fields via `extra`, not the message, so `caplog.text` shows only the + event name -- asserting on it would pass for any values at all. + """ + from keel_core.telemetry import _FIELDS_ATTR + + records = [r for r in caplog.records if r.getMessage() == "executor.intent_divergence"] + assert records, "no executor.intent_divergence record was emitted" + return getattr(records[-1], _FIELDS_ATTR) + + +class TestIntentDivergenceLog: + """#260 mitigation: the executor records the rule's intended entry and the achieved fill + side by side and never compared them. That missing subtraction is how #257 stayed invisible. + """ + + @staticmethod + def _intent(entry: str = "50000") -> OrderIntent: + return OrderIntent( + product_id="BTC-USD", + side=Side.BUY, + qty=Decimal("0.001"), + entry=Decimal(entry), + stop=Decimal("49000"), + notional=Decimal("50"), + is_dca=False, + rule_kind="pullback_continuation", + ) + + def test_divergence_is_logged_with_signed_basis_points(self, caplog) -> None: + from keel.execution.executor import _log_intent_divergence + + with caplog.at_level(logging.INFO): + # Filled 50 above a 50,000 intent -> +10.00 bps. + _log_intent_divergence(order_id=7, intent=self._intent(), realized=Decimal("50050")) + + assert _divergence_fields(caplog)["divergence_bps"] == "10.00" + + def test_divergence_is_signed_so_direction_is_legible(self, caplog) -> None: + """Negative means the fill came in BELOW the rule's intended entry. + + Signedness is the point: an unsigned magnitude cannot distinguish "we paid up" from "we + got filled cheaper", and for a rule whose entry encodes a confirmation condition those + are opposite failures. + """ + from keel.execution.executor import _log_intent_divergence + + with caplog.at_level(logging.INFO): + _log_intent_divergence(order_id=8, intent=self._intent(), realized=Decimal("49950")) + + assert _divergence_fields(caplog)["divergence_bps"] == "-10.00" + + def test_logged_unconditionally_even_when_divergence_is_zero(self, caplog) -> None: + """No threshold, deliberately. + + A basis-point cutoff right for BTC is wrong for a thin book, and the per-asset liquidity + model that would set one does not exist yet (#259). Gating this on that work would block + the cheap half behind the expensive half -- so every fill reports, exactly as #247 made + the fee rate report on every backtest. + """ + from keel.execution.executor import _log_intent_divergence + + with caplog.at_level(logging.INFO): + _log_intent_divergence(order_id=9, intent=self._intent(), realized=Decimal("50000")) + + fields = _divergence_fields(caplog) + assert fields["divergence_bps"] == "0.00" + assert fields["product"] == "BTC-USD" + + def test_never_raises_on_unusable_input(self, caplog) -> None: + """Telemetry on an already-settled order must not be able to fail a cycle.""" + from keel.execution.executor import _log_intent_divergence + + with caplog.at_level(logging.INFO): + _log_intent_divergence(order_id=10, intent=None, realized=Decimal("50000")) + _log_intent_divergence(order_id=11, intent=self._intent("0"), realized=Decimal("1")) + _log_intent_divergence(order_id=12, intent=self._intent(), realized="not-a-number") diff --git a/tests/strategy/test_backtest.py b/tests/strategy/test_backtest.py index dca95f8b..c2e6df91 100644 --- a/tests/strategy/test_backtest.py +++ b/tests/strategy/test_backtest.py @@ -329,3 +329,42 @@ def test_detector_cannot_be_frozen_by_an_unfilled_setup(self) -> None: # model this was 3 (every flat bar re-asked, because nothing ever filled) -- so this # number is also what distinguishes the two fill models. assert rule.detect_calls == 1 + + +class TestPendingLifespanInvariant: + """A pending setup must never survive more than one bar (#254 / #257). + + HONEST NOTE ON COVERAGE: this invariant cannot be violated through the public API, because + since #257 the fill is unconditional -- there is no input that makes the engine carry a setup. + So there is no red-then-green test for it, and pretending otherwise would be theatre. + + What actually protects it is that the assertion sits in the hot loop of `backtest()`, so + EVERY existing test in this file, the baseline golden, and the whole sim suite now execute it. + If someone reintroduces a carried pending -- resting orders for #260's Option B, say -- the + suite fails loudly with a message naming the rule and the bar, instead of the silence that let + #254 survive the entire project. + + The tests below pin the contract itself so its value is stated somewhere a reader will find. + """ + + def test_a_long_series_that_rarely_fires_never_trips_the_invariant(self) -> None: + """The #254 shape: a rule that mostly declines, over many bars, must run clean.""" + rule = _ScriptedRule( + trigger_ts=600, entry=Decimal(110), stop=Decimal(95), target=Decimal(130) + ) + candles = [_candle(ts, "100", "101", "99", "100") for ts in range(0, 6000, 60)] + result = backtest(rule, candles) # must not raise + assert isinstance(result, BacktestResult) + + def test_an_unfillable_setup_still_resolves_within_one_bar(self) -> None: + """The exact #254 trigger: entry and stop both unreachable, forever. + + Before #257 this pinned `pending` for the rest of the series. It must now fill on the very + next bar instead, which is what keeps the lifespan at 1. + """ + rule = _StaleThenReachableRule(switch_ts=10**9) + candles = [_candle(ts, "100", "101", "99", "100") for ts in range(0, 3000, 60)] + result = backtest(rule, candles) # must not raise + + assert len(result.trades) == 1 # filled immediately, then held to the end of the series + assert result.trades[0].outcome == "open"