feat(engine): two observable invariants, because neither past defect was findable by testing

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]:

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

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")

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"