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"