refactor: add reason tag to cancel_all_orders_for_coin log line (#152)

``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) <noreply@anthropic.com>

Author: keitaj

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:

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:

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:

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

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

tests/test_mm_order_tracker.py

@@ -15,13 +15,99 @@
 prevent.
 """
 
+import logging
+import time
 from unittest.mock import MagicMock
 
 import pytest
 
 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``."""
 

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

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
 

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

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