From eaa2a53f517b8fa68b3e3d8ad957d7faf88b5ba8 Mon Sep 17 00:00:00 2001 From: keitaj Date: Tue, 5 May 2026 06:20:48 +0900 Subject: [PATCH] refactor: add reason tag to cancel_all_orders_for_coin log line MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ``OrderTracker.cancel_all_orders_for_coin`` is invoked from five distinct control paths — real fill detection, WS fill feed, BBO guard, drain-mode entry, quiet-hour entry — but historically all of them emitted the same ``(post-fill cleanup)`` log message regardless of caller. On illiquid coins where the BBO-guard path dominates, ``grep "post-fill cleanup"`` produced counts that looked like fills were happening when in reality there were zero — actively misleading for any log-driven analysis (per-coin fill rate, monitoring dashboards, post-mortem investigations). This refactor adds an optional ``reason: str = "manual"`` argument to ``cancel_all_orders_for_coin``. Each caller passes a short snake_case tag (``fill`` / ``ws_fill`` / ``bbo_guard`` / ``drain`` / ``quiet_hour``) which is included verbatim in the log line: [mm] Cancelled X/Y orders for COIN (reason=bbo_guard): [oids...] The error path on ``bulk_cancel_orders`` failure carries the same tag, and the legacy "after fill" wording is removed from the error log since most callers are not fill-driven. The default ``"manual"`` preserves backward compatibility for tests / external callers that never passed the new argument. This is a pure observability change — order placement, cancellation, risk guards, and tracker state all behave identically. No CLI flag, env var, or config key is added. Tests: * New ``TestCancelAllOrdersForCoinReason`` (6 tests) pins: - explicit reason appears in the log - default = "manual" - each documented reason value round-trips - empty tracked list short-circuits without logging - ERROR path on API failure also carries the reason - tracked state is cleared regardless of reason * Existing assertions updated across ``test_bbo_guard``, ``test_drain_mode``, ``test_quiet_hours``, ``test_mm_cancel_on_fill`` and ``test_ws_fill_feed`` to pin the per-caller reason value at each integration point. Design doc: hip-3-farming-agent-team/docs/design-doc/20260505_cancel_all_orders_reason_logging.md Background investigation: hip-3-farming-agent-team/research/system_reviews/20260505_0557_copper_fill_investigation.md Co-Authored-By: Claude Opus 4.7 (1M context) --- strategies/market_making_strategy.py | 6 +- strategies/mm_order_tracker.py | 26 +++++++-- tests/test_bbo_guard.py | 6 +- tests/test_drain_mode.py | 4 +- tests/test_mm_cancel_on_fill.py | 2 +- tests/test_mm_order_tracker.py | 86 ++++++++++++++++++++++++++++ tests/test_quiet_hours.py | 4 +- tests/test_ws_fill_feed.py | 2 +- ws/bbo_guard.py | 2 +- ws/fill_feed.py | 2 +- 10 files changed, 121 insertions(+), 19 deletions(-) diff --git a/strategies/market_making_strategy.py b/strategies/market_making_strategy.py index 3a69ad1..8080822 100644 --- a/strategies/market_making_strategy.py +++ b/strategies/market_making_strategy.py @@ -333,7 +333,7 @@ def run(self, coins: List[str]) -> None: # double-filling which doubles adverse selection cost. # NOTE: Does not fire when close_immediately=True because # positions are closed before the next detection pass. - self._tracker.cancel_all_orders_for_coin(coin) + self._tracker.cancel_all_orders_for_coin(coin, reason="fill") logger.info(f"[mm] Cancelled orders for {coin} after fill (prevent double-fill)") # Track loss streaks: detect coins that just closed (had position last cycle, not now) @@ -385,7 +385,7 @@ def run(self, coins: List[str]) -> None: if not self._was_drain: logger.info("[mm] Entering drain mode, cancelling all orders") for coin in coins: - self._tracker.cancel_all_orders_for_coin(coin) + self._tracker.cancel_all_orders_for_coin(coin, reason="drain") self._was_drain = True for coin in coins: try: @@ -416,7 +416,7 @@ def run(self, coins: List[str]) -> None: utc_hour = datetime.now(timezone.utc).hour logger.info(f"[mm] Entering quiet hours (UTC {utc_hour}), cancelling all orders") for coin in coins: - self._tracker.cancel_all_orders_for_coin(coin) + self._tracker.cancel_all_orders_for_coin(coin, reason="quiet_hour") self._was_quiet = True # Still process existing positions but skip new order placement for coin in coins: diff --git a/strategies/mm_order_tracker.py b/strategies/mm_order_tracker.py index ced7c38..5832b35 100644 --- a/strategies/mm_order_tracker.py +++ b/strategies/mm_order_tracker.py @@ -257,11 +257,26 @@ def get_refresh_stats(self, coin: Optional[str] = None) -> Dict[str, int]: "cancelled_age": sum(self._refresh_cancelled_age.values()), } - def cancel_all_orders_for_coin(self, coin: str) -> None: + def cancel_all_orders_for_coin(self, coin: str, reason: str = "manual") -> None: """Cancel all tracked orders for a coin. - Called when one side fills to prevent the opposite side from also - filling (which would double adverse selection cost). + Called from several distinct control paths — real fill detection, + drain mode, quiet-hour entry, BBO guard, WS fill feed — and the + *reason* argument is logged verbatim so observers can tell them + apart downstream. The legacy log claimed "post-fill cleanup" + regardless of caller, which was actively misleading on illiquid + coins where the BBO-guard path dominates. + + Recognised values (free-form, used as a string tag in the log): + + * ``"fill"`` — real fill detection in the strategy main loop + * ``"ws_fill"`` — WS fill feed instant cancel + * ``"bbo_guard"`` — BBO guard cancelled both sides on rapid move + * ``"drain"`` — drain-mode entry (graceful pre-shutdown) + * ``"quiet_hour"`` — quiet-hour entry (full-stop mode) + * ``"manual"`` (default) — unspecified caller / tests + + New callers should pick a short snake_case tag and add it here. Thread-safe: may be called from the WS fill feed thread. """ @@ -277,11 +292,12 @@ def cancel_all_orders_for_coin(self, coin: str) -> None: cancelled = self.order_manager.bulk_cancel_orders(cancel_requests) logger.info( f"[mm] Cancelled {cancelled}/{len(cancel_requests)} orders for {coin} " - f"(post-fill cleanup): {oid_list}" + f"(reason={reason}): {oid_list}" ) except Exception as e: logger.error( - f"[mm] Error cancelling orders for {coin} after fill: {e}, oids: {oid_list}" + f"[mm] Error cancelling orders for {coin} (reason={reason}): " + f"{e}, oids: {oid_list}" ) def cancel_orders_by_side(self, coin: str, side: str) -> None: diff --git a/tests/test_bbo_guard.py b/tests/test_bbo_guard.py index fb5293f..c576be7 100644 --- a/tests/test_bbo_guard.py +++ b/tests/test_bbo_guard.py @@ -43,7 +43,7 @@ def test_large_change_triggers_cancel(self): # 3 bps change on bid — above threshold guard.on_l2_update("BTC", _make_levels(100.03, 100.05)) - tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC") + tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC", reason="bbo_guard") assert guard.stats["changes_detected"] == 1 assert guard.stats["cancels_triggered"] == 1 @@ -53,7 +53,7 @@ def test_ask_change_triggers_cancel(self): # Ask drops by 3 bps guard.on_l2_update("BTC", _make_levels(100.00, 99.99)) - tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC") + tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC", reason="bbo_guard") def test_multiple_coins_independent(self): guard, tracker = _make_guard(threshold_bps=2.0) @@ -64,7 +64,7 @@ def test_multiple_coins_independent(self): guard.on_l2_update("BTC", _make_levels(100.05, 100.07)) guard.on_l2_update("ETH", _make_levels(3000.03, 3000.63)) - tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC") + tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC", reason="bbo_guard") class TestBboGuardEdgeCases: diff --git a/tests/test_drain_mode.py b/tests/test_drain_mode.py index 883b373..e3fc03c 100644 --- a/tests/test_drain_mode.py +++ b/tests/test_drain_mode.py @@ -78,8 +78,8 @@ def test_drain_cancels_all_orders_on_entry(self): strategy.run(coins) assert strategy._tracker.cancel_all_orders_for_coin.call_count == 2 - strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:SP500') - strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:NVDA') + strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:SP500', reason="drain") + strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:NVDA', reason="drain") assert strategy._was_drain is True def test_drain_no_repeat_cancel(self): diff --git a/tests/test_mm_cancel_on_fill.py b/tests/test_mm_cancel_on_fill.py index e6c1183..d191c2c 100644 --- a/tests/test_mm_cancel_on_fill.py +++ b/tests/test_mm_cancel_on_fill.py @@ -149,7 +149,7 @@ def test_new_fill_triggers_cancel(self): strategy.run(['BTC']) - strategy._tracker.cancel_all_orders_for_coin.assert_called_once_with('BTC') + strategy._tracker.cancel_all_orders_for_coin.assert_called_once_with('BTC', reason="fill") def test_no_fill_no_cancel(self): """When a position already existed, no cancel is triggered.""" diff --git a/tests/test_mm_order_tracker.py b/tests/test_mm_order_tracker.py index 60dbc8b..cddaa80 100644 --- a/tests/test_mm_order_tracker.py +++ b/tests/test_mm_order_tracker.py @@ -15,6 +15,8 @@ prevent. """ +import logging +import time from unittest.mock import MagicMock import pytest @@ -22,6 +24,90 @@ from strategies.mm_order_tracker import OrderTracker +class TestCancelAllOrdersForCoinReason: + """``cancel_all_orders_for_coin`` accepts a ``reason`` tag and includes + it verbatim in the log so observers can distinguish the call site + (real fill / drain / quiet hour / bbo guard / ws fill / manual). + Pre-PR the message was hard-coded to "post-fill cleanup", which was + actively misleading on the bbo-guard path. + """ + + def _make_tracker(self): + om = MagicMock() + om.bulk_cancel_orders.return_value = 1 + tracker = OrderTracker( + om, refresh_interval_seconds=30, max_open_orders=4 + ) + tracker._tracked_orders["BTC"] = [(101, "B", time.monotonic())] + return tracker, om + + def test_explicit_reason_appears_in_log(self, caplog): + tracker, _ = self._make_tracker() + with caplog.at_level(logging.INFO, logger="strategies.mm_order_tracker"): + tracker.cancel_all_orders_for_coin("BTC", reason="bbo_guard") + msgs = [r.message for r in caplog.records if "Cancelled" in r.message] + assert len(msgs) == 1 + assert "(reason=bbo_guard)" in msgs[0] + assert "BTC" in msgs[0] + # Legacy phrase must be gone. + assert "post-fill cleanup" not in msgs[0] + + def test_default_reason_is_manual(self, caplog): + """The default keeps backward-compatible call signatures (no kw) + from older tests / external callers working.""" + tracker, _ = self._make_tracker() + with caplog.at_level(logging.INFO, logger="strategies.mm_order_tracker"): + tracker.cancel_all_orders_for_coin("BTC") # no reason + msgs = [r.message for r in caplog.records if "Cancelled" in r.message] + assert len(msgs) == 1 + assert "(reason=manual)" in msgs[0] + + def test_each_reason_value_round_trips(self, caplog): + """Each documented reason string lands in the log unmodified.""" + for reason in ("fill", "ws_fill", "bbo_guard", "drain", "quiet_hour"): + tracker, _ = self._make_tracker() + caplog.clear() + with caplog.at_level(logging.INFO, logger="strategies.mm_order_tracker"): + tracker.cancel_all_orders_for_coin("BTC", reason=reason) + msgs = [r.message for r in caplog.records if "Cancelled" in r.message] + assert len(msgs) == 1, f"missing log for reason={reason}" + assert f"(reason={reason})" in msgs[0] + + def test_no_orders_emits_no_log(self, caplog): + """Empty tracked list short-circuits before logging — important + because COPPER-style coins on bbo_guard path can fire many calls + with nothing to cancel; we don't want a flood of empty cleanup + lines in the log.""" + tracker, _ = self._make_tracker() + tracker._tracked_orders["BTC"] = [] + with caplog.at_level(logging.INFO, logger="strategies.mm_order_tracker"): + tracker.cancel_all_orders_for_coin("BTC", reason="bbo_guard") + msgs = [r.message for r in caplog.records if "Cancelled" in r.message] + assert msgs == [] + + def test_reason_appears_in_error_log_on_api_failure(self, caplog): + tracker, om = self._make_tracker() + om.bulk_cancel_orders.side_effect = Exception("API timeout") + with caplog.at_level(logging.ERROR, logger="strategies.mm_order_tracker"): + tracker.cancel_all_orders_for_coin("BTC", reason="ws_fill") + errs = [ + r for r in caplog.records + if r.levelno == logging.ERROR + and "Error cancelling" in r.message + ] + assert len(errs) == 1 + assert "(reason=ws_fill)" in errs[0].message + # Old "after fill" wording is gone (it was wrong for non-fill paths). + assert "after fill" not in errs[0].message + + def test_tracked_state_cleared_regardless_of_reason(self): + tracker, _ = self._make_tracker() + tracker.cancel_all_orders_for_coin("BTC", reason="drain") + # Same post-condition as the legacy code: tracked list is wiped + # before bulk_cancel runs, so the API call cost is paid only once. + assert tracker._tracked_orders["BTC"] == [] + + class TestCloseOrderInvariant: """Close orders must not appear in ``_tracked_orders``.""" diff --git a/tests/test_quiet_hours.py b/tests/test_quiet_hours.py index 54e4f15..08e3b4a 100644 --- a/tests/test_quiet_hours.py +++ b/tests/test_quiet_hours.py @@ -89,8 +89,8 @@ def test_quiet_hours_cancels_all_orders_on_entry(self, mock_dt): # Should cancel all orders for each coin on entry assert strategy._tracker.cancel_all_orders_for_coin.call_count == 2 - strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:SP500') - strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:NVDA') + strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:SP500', reason="quiet_hour") + strategy._tracker.cancel_all_orders_for_coin.assert_any_call('xyz:NVDA', reason="quiet_hour") assert strategy._was_quiet is True @patch('strategies.market_making_strategy.datetime') diff --git a/tests/test_ws_fill_feed.py b/tests/test_ws_fill_feed.py index 86a4943..6564741 100644 --- a/tests/test_ws_fill_feed.py +++ b/tests/test_ws_fill_feed.py @@ -61,7 +61,7 @@ def test_live_fill_triggers_cancel(self): } }) - tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC") + tracker.cancel_all_orders_for_coin.assert_called_once_with("BTC", reason="ws_fill") assert feed.stats["fills"] == 1 assert feed.stats["cancels"] == 1 diff --git a/ws/bbo_guard.py b/ws/bbo_guard.py index a0bd72b..e669ae5 100644 --- a/ws/bbo_guard.py +++ b/ws/bbo_guard.py @@ -99,7 +99,7 @@ def _try_cancel(self, coin: str, change_bps: float) -> None: return # Rate limit: avoid spamming cancels self._last_cancel_time[coin] = now - self.order_tracker.cancel_all_orders_for_coin(coin) + self.order_tracker.cancel_all_orders_for_coin(coin, reason="bbo_guard") self._cancels_triggered += 1 logger.info( "[bbo-guard] BBO change %.1f bps for %s — cancelled orders", diff --git a/ws/fill_feed.py b/ws/fill_feed.py index e20c09e..5d6985b 100644 --- a/ws/fill_feed.py +++ b/ws/fill_feed.py @@ -200,7 +200,7 @@ def _on_fill(self, msg: Dict) -> None: # Cancel opposite-side orders for each filled coin. # OrderTracker.cancel_all_orders_for_coin is thread-safe (has its own lock). for coin in filled_coins: - self.order_tracker.cancel_all_orders_for_coin(coin) + self.order_tracker.cancel_all_orders_for_coin(coin, reason="ws_fill") self._cancel_count += 1 logger.info( "[ws-fill] Instant cancel for %s (fill detected via WS)", coin