diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..08e4778 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,47 @@ +# Changelog + +All notable changes to HyperTrade are documented here. +The format loosely follows [Keep a Changelog](https://keepachangelog.com/). + +## [Unreleased] + +### Added — Order-failure diagnostic logging (2026-06-28) + +When an order fails, the logs now carry enough context to reconstruct the root +cause. Observability only — no change to the error taxonomy, retry policy, HTTP +status codes, DB schema, or pricing/submission logic. + +- **Correlation across all layers.** `OrderRequest` now carries a `req_id` + (alongside the existing `cloid`); every failure log line in the execution path + is tagged so it can be tied back to the originating webhook request and to the + exchange-side order id. `cloid` threads execution-client → service → webhook → + exchange; `req_id` threads webhook → service. +- **Submitted price is logged before every order.** `market_order` / `limit_order` + emit one INFO line with `mid`, slippage bps, the aggressive price, and the + tick-normalized price actually sent — so a "bad price / could not match" reject + has the exact price on the immediately preceding line. +- **Service-layer rejects log full context + payload.** The five `place_order` + failure sites (leverage-reject, no-response, unexpected-shape, exchange-reject, + unexpected-status) now log the order context (symbol, side, size, reduce_only, + leverage, cloid, req_id) plus the full exchange response via a defensive + `_safe_json` (falls back to `repr` so a serialisation error can never mask the + original failure). +- **Retry loop / webhook handlers enriched.** The terminal network/API retry line + now includes the underlying error string (previously it logged only the attempt + count); the three exception handlers carry `req_id`/`cloid`/`symbol`/`side`. +- **Shared helper.** A single `format_log_context(**fields)` (in + `hypertrade/logging.py`) builds the uniform `key=value` context, skipping + `None`, used by all three layers (no copy-pasted prefix). +- **Secret-safety guard.** A regression test asserts the webhook secret never + appears in failure-level (WARNING+) logs on the order-execution path. + +Design: `docs/superpowers/specs/2026-06-28-order-failure-logging-design.md` · +Plan: `docs/superpowers/plans/2026-06-28-order-failure-logging.md`. + +### Fixed + +- **TD-18** — the *invalid-JSON* path (`_log_invalid_json_body`) no longer leaks + the webhook secret. The raw body, logged at WARNING for debugging, is now passed + through `_redact_secrets`, which masks any `"secret": "…"` field and the + configured secret value before logging. Surfaced during the order-failure-logging + review and fixed on the same branch. diff --git a/docs/TECH_DEBT.md b/docs/TECH_DEBT.md index 4952a20..6265882 100644 --- a/docs/TECH_DEBT.md +++ b/docs/TECH_DEBT.md @@ -88,6 +88,12 @@ code before acting. ## Resolved +- 2026-06-28 `0fbd9f4` — **TD-18**: the invalid-JSON debug log now redacts the + webhook secret. `routes/webhooks.py::_log_invalid_json_body` passes the raw body + through `_redact_secrets` (masks any `"secret": "…"` field via pattern + the + configured secret value verbatim), so a malformed payload can no longer leak + `general.secret` at WARNING level. Covered by + `test_invalid_json_body_log_redacts_secret`. - 2026-06-22 `25cf438` — **TD-2**: domain errors mapped into the taxonomy — unknown symbol → `HyperliquidValidationError` (400), malformed exchange response → `HyperliquidAPIError` (502); no more raw 500s on the order path. diff --git a/docs/superpowers/plans/2026-06-28-order-failure-logging.md b/docs/superpowers/plans/2026-06-28-order-failure-logging.md new file mode 100644 index 0000000..762499b --- /dev/null +++ b/docs/superpowers/plans/2026-06-28-order-failure-logging.md @@ -0,0 +1,640 @@ +# Order Failure Logging Enrichment Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** When an order fails, emit enough diagnostic context in the logs — correlation IDs (`req_id`/`cloid`), full order context, the price actually sent, and the exchange's full response — to reconstruct the root cause. + +**Architecture:** Add one shared `format_log_context()` helper in `hypertrade/logging.py`, carry `req_id` on the request-scoped `OrderRequest` dataclass (it already carries `cloid`), and enrich the existing failure log lines across the three execution layers (execution client → service → webhook). No structural refactor, no DB migration, no behaviour change. + +**Tech Stack:** Python 3.11 (test runner), FastAPI, hyperliquid-python-sdk, pytest, `unittest.mock`. + +## Global Constraints + +- Run tests with `python3.11 -m pytest` (the repo's `python3.14` has no pytest). +- This stays a **thin executor**: observability only — no trading/position logic. +- **Log stream only.** No change to the `failures`/`orders` DB schema, the `HyperliquidError` taxonomy, retry counts, or pricing logic. +- **No secrets in failure logs.** Only order parameters, exchange responses, and computed prices may be logged. The API private key and `general.secret` must never appear. The pre-existing `log.debug("Full webhook payload: %s", raw)` is out of scope and unchanged. +- Failure context is logged at the **same level as the failure** (ERROR for terminal/exchange rejects, WARNING for retryable attempts), so it survives the production INFO daemon level. +- App loggers use `logging.getLogger("uvicorn.error")`. + +--- + +### Task 1: Shared `format_log_context` helper + +**Files:** +- Modify: `hypertrade/logging.py` (append a function near the top, after the `log = ...` line) +- Test: `tests/test_logging_context.py` (create) + +**Interfaces:** +- Produces: `format_log_context(**fields: object) -> str` — joins `key=value` pairs with single spaces, skipping any field whose value is `None`; never raises. Returns `""` when all fields are `None`. + +- [ ] **Step 1: Write the failing test** + +Create `tests/test_logging_context.py`: + +```python +"""Tests for format_log_context — the shared diagnostic-context formatter used to +build a uniform correlation suffix on failure log lines.""" + +from __future__ import annotations + +import pathlib +import sys + +REPO_ROOT = str(pathlib.Path(__file__).resolve().parents[1]) +if REPO_ROOT not in sys.path: + sys.path.insert(0, REPO_ROOT) + +from hypertrade.logging import format_log_context + + +def test_joins_key_values_in_order(): + assert format_log_context(symbol="SOL", side="buy", size=2.0) == "symbol=SOL side=buy size=2.0" + + +def test_skips_none_values(): + assert format_log_context(symbol="SOL", cloid=None, req_id="r-1") == "symbol=SOL req_id=r-1" + + +def test_empty_when_all_none(): + assert format_log_context(a=None, b=None) == "" + + +def test_tolerates_arbitrary_reprable_objects(): + assert format_log_context(payload={"k": 1}) == "payload={'k': 1}" +``` + +- [ ] **Step 2: Run test to verify it fails** + +Run: `python3.11 -m pytest tests/test_logging_context.py -v` +Expected: FAIL with `ImportError: cannot import name 'format_log_context'`. + +- [ ] **Step 3: Write minimal implementation** + +In `hypertrade/logging.py`, immediately after the `log = pylog.getLogger("uvicorn.error")` line, add: + +```python +def format_log_context(**fields: object) -> str: + """Format diagnostic fields as a space-separated ``key=value`` string. + + Used to build a uniform correlation/context suffix for failure log lines so + the prefix is defined once (no copy-paste across call sites). Skips fields + whose value is ``None``; never raises. + """ + return " ".join(f"{key}={value}" for key, value in fields.items() if value is not None) +``` + +- [ ] **Step 4: Run test to verify it passes** + +Run: `python3.11 -m pytest tests/test_logging_context.py -v` +Expected: PASS (4 passed). + +- [ ] **Step 5: Commit** + +```bash +git add hypertrade/logging.py tests/test_logging_context.py +git commit -m "feat(logging): add format_log_context helper for failure-log correlation" +``` + +--- + +### Task 2: Carry `req_id` on `OrderRequest` + +**Files:** +- Modify: `hypertrade/routes/hyperliquid_service.py` (the `OrderRequest` dataclass, ~lines 23-40) +- Modify: `hypertrade/routes/webhooks.py` (the `OrderRequest(...)` construction in `hypertrade_webhook`, ~lines 255-267) +- Test: `tests/test_webhook.py` (add one test) + +**Interfaces:** +- Consumes: nothing new. +- Produces: `OrderRequest.req_id: Optional[str] = None` — the request-scoped correlation id, set by the webhook handler. Consumed by Tasks 4 and 5. + +- [ ] **Step 1: Write the failing test** + +Append to `tests/test_webhook.py`: + +```python +def test_order_request_carries_req_id(monkeypatch): + """The webhook must thread its request id onto OrderRequest so downstream + failure logs can correlate back to the originating request.""" + StubHyperliquidService.reset() + app = make_app(monkeypatch, secret="secret") + client = TestClient(app) + + resp = client.post("/webhook", json=copy.deepcopy(BASE_PAYLOAD)) + assert resp.status_code == 200, resp.text + order_req = StubHyperliquidService.last_order_request + assert order_req is not None + assert isinstance(order_req.req_id, str) and order_req.req_id +``` + +- [ ] **Step 2: Run test to verify it fails** + +Run: `python3.11 -m pytest tests/test_webhook.py::test_order_request_carries_req_id -v` +Expected: FAIL with `AttributeError: 'OrderRequest' object has no attribute 'req_id'`. + +- [ ] **Step 3: Write minimal implementation** + +In `hypertrade/routes/hyperliquid_service.py`, add the field at the end of the `OrderRequest` dataclass (after the `cloid` field): + +```python + # Request-scoped correlation id (the webhook's req_id). Threaded onto the + # request so failure logs in the service/webhook layers can be tied back to + # the originating request. Distinct from cloid (the exchange-side order id). + req_id: Optional[str] = None +``` + +In `hypertrade/routes/webhooks.py`, in the `OrderRequest(...)` construction inside `hypertrade_webhook`, add the `req_id` argument (the local `req_id` is already computed just above, where `cloid_seed` is derived): + +```python + order_request = OrderRequest( + symbol=symbol, + side=side, + signal=signal, + qty=contracts, + price=price, + reduce_only=reduce_only, + post_only=False, + client_id=None, + leverage=leverage, + subaccount=vault_address, + cloid=cloid, + req_id=req_id, + ) +``` + +- [ ] **Step 4: Run test to verify it passes** + +Run: `python3.11 -m pytest tests/test_webhook.py::test_order_request_carries_req_id -v` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add hypertrade/routes/hyperliquid_service.py hypertrade/routes/webhooks.py tests/test_webhook.py +git commit -m "feat(exec): carry req_id on OrderRequest for failure-log correlation" +``` + +--- + +### Task 3: Log the submitted pricing in the execution client + +**Files:** +- Modify: `hypertrade/routes/hyperliquid_execution_client.py` (add import; `limit_order` ~lines 99-123; `market_order` ~lines 125-157) +- Test: `tests/test_execution_client_price.py` (add one test) + +**Interfaces:** +- Consumes: `format_log_context` from Task 1. +- Produces: one INFO log line per submit carrying the exact price about to be sent — so a subsequent reject has the price on the immediately preceding line. + +- [ ] **Step 1: Write the failing test** + +Append to `tests/test_execution_client_price.py`: + +```python +def test_market_order_logs_submitted_pricing(monkeypatch, caplog): + """Before submitting a MARKET IOC, the client logs the mid and the exact + aggressive/normalized price it is about to send, tagged with the cloid — the + primary diagnostic for a 'bad price / could not match' reject.""" + import logging as _logging + client = _client(monkeypatch, 3) + client.data.get_mid = MagicMock(return_value=1000.0) + + with caplog.at_level(_logging.INFO, logger="uvicorn.error"): + client.market_order( + symbol="SOL", side=PositionSide.LONG, size=2.0, + premium_bps=500, cloid="0x" + "a" * 32, + ) + + msgs = [r.getMessage() for r in caplog.records] + assert any( + "mid=1000" in m and "norm_px=1050" in m and ("0x" + "a" * 32) in m + for m in msgs + ), msgs +``` + +- [ ] **Step 2: Run test to verify it fails** + +Run: `python3.11 -m pytest tests/test_execution_client_price.py::test_market_order_logs_submitted_pricing -v` +Expected: FAIL (no log record matches — the pricing line does not exist yet). + +- [ ] **Step 3: Write minimal implementation** + +In `hypertrade/routes/hyperliquid_execution_client.py`, add the import next to the other `from .` / `from hypertrade` imports (after line 14, `from .hyperliquid_errors import translate_request_errors`): + +```python +from hypertrade.logging import format_log_context +``` + +In `market_order`, insert the log line immediately before the `with translate_request_errors("market_order"):` block (after `norm_px = self._normalize_price(...)`): + +```python + log.info( + "Submitting MARKET IOC | %s", + format_log_context( + symbol=symbol, side=side.value, size=size, + mid=f"{mid:.6f}", slippage_bps=slippage_bps, + aggressive_px=f"{aggressive_px:.6f}", norm_px=norm_px, + reduce_only=reduce_only, cloid=cloid, + ), + ) +``` + +In `limit_order`, insert the log line immediately before the `with translate_request_errors("limit_order"):` block (after `norm_price = self._normalize_price(...)`): + +```python + log.info( + "Submitting LIMIT %s | %s", + tif, + format_log_context( + symbol=symbol, side=side.value, size=size, + price=price, norm_price=norm_price, + reduce_only=reduce_only, cloid=cloid, + ), + ) +``` + +- [ ] **Step 4: Run test to verify it passes** + +Run: `python3.11 -m pytest tests/test_execution_client_price.py -v` +Expected: PASS (all price tests, including the new one). + +- [ ] **Step 5: Commit** + +```bash +git add hypertrade/routes/hyperliquid_execution_client.py tests/test_execution_client_price.py +git commit -m "feat(exec): log submitted price (mid/aggressive/norm) before each order" +``` + +--- + +### Task 4: Enrich the service-layer failure logs + +**Files:** +- Modify: `hypertrade/routes/hyperliquid_service.py` (add import + `_safe_json` helper; `place_order` failure branches — leverage reject ~lines 159-164, no-response ~216-218, unexpected-shape ~222-224, exchange-reject ~230-238, unexpected-status ~239-241) +- Test: `tests/test_hyperliquid_service.py` (add two tests) + +**Interfaces:** +- Consumes: `format_log_context` (Task 1), `OrderRequest.req_id` (Task 2). +- Produces: enriched ERROR logs carrying order context + the full exchange payload at each failure site. + +- [ ] **Step 1: Write the failing tests** + +Append to `tests/test_hyperliquid_service.py`: + +```python +def test_exchange_reject_logs_full_context(monkeypatch, caplog): + """On an exchange reject the ERROR log must carry the order context (symbol, + side, size, cloid, req_id) and the error/payload, not just the error string.""" + import logging as _logging + svc, client = _service(monkeypatch) + client.market_order.return_value = { + "response": {"data": {"statuses": [{"error": "Order has invalid price."}]}} + } + with caplog.at_level(_logging.ERROR, logger="uvicorn.error"): + with pytest.raises(HyperliquidRejection): + svc.place_order(OrderRequest( + symbol="SOL", side=Side.BUY, signal=SignalType.OPEN_LONG, + qty=Decimal("2"), price=Decimal("100"), leverage=3, + cloid="0x" + "a" * 32, req_id="req-123", + )) + msg = " ".join(r.getMessage() for r in caplog.records) + assert "symbol=SOL" in msg + assert "side=buy" in msg + assert "size=2" in msg + assert ("cloid=0x" + "a" * 32) in msg + assert "req_id=req-123" in msg + assert "Order has invalid price." in msg + + +def test_no_response_logs_context(monkeypatch, caplog): + """A None exchange response is logged with the order context before raising.""" + import logging as _logging + svc, client = _service(monkeypatch) + client.market_order.return_value = None + with caplog.at_level(_logging.ERROR, logger="uvicorn.error"): + with pytest.raises(HyperliquidAPIError): + svc.place_order(OrderRequest( + symbol="SOL", side=Side.BUY, signal=SignalType.OPEN_LONG, + qty=Decimal("1"), price=Decimal("100"), leverage=1, + cloid="0x" + "b" * 32, req_id="req-456", + )) + msg = " ".join(r.getMessage() for r in caplog.records) + assert "symbol=SOL" in msg and "req_id=req-456" in msg and ("cloid=0x" + "b" * 32) in msg +``` + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `python3.11 -m pytest tests/test_hyperliquid_service.py::test_exchange_reject_logs_full_context tests/test_hyperliquid_service.py::test_no_response_logs_context -v` +Expected: FAIL (the current logs carry only `symbol` + the error/`res`, so the `cloid=`/`req_id=`/`side=` assertions fail). + +- [ ] **Step 3: Write minimal implementation** + +In `hypertrade/routes/hyperliquid_service.py`, add the import after the existing `from .hyperliquid_errors import (...)` block: + +```python +from hypertrade.logging import format_log_context +``` + +Add this module-level helper just after the `log = logging.getLogger("uvicorn.error")` line: + +```python +def _safe_json(obj: object) -> str: + """json.dumps that never raises — falls back to repr for non-serialisable payloads. + + A logging path must never mask the original failure with a serialisation error. + """ + try: + return json.dumps(obj) + except (TypeError, ValueError): + return repr(obj) +``` + +Replace the **leverage-reject** log line (inside the `if leverage_response.get('status') != 'ok':` block): + +```python + log.error( + "Leverage update REJECTED | %s | response=%s", + format_log_context( + symbol=symbol, requested_leverage=leverage, + max_leverage=max_leverage, is_cross=is_cross, + cloid=request.cloid, req_id=request.req_id, + ), + _safe_json(leverage_response), + ) +``` + +Replace the **no-response** branch (`if res is None:`): + +```python + if res is None: + log.error( + "Order execution failed (no response from API) | %s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + reduce_only=request.reduce_only, + cloid=request.cloid, req_id=request.req_id, + ), + ) + raise HyperliquidAPIError("Order Creation did not work") +``` + +Replace the **unexpected-shape** `except` log line: + +```python + except (KeyError, TypeError, IndexError) as exc: + log.error( + "Unexpected order response shape | %s | response=%s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + cloid=request.cloid, req_id=request.req_id, + ), + _safe_json(res), + ) + raise HyperliquidAPIError(f"Unexpected order response shape: {res}") from exc +``` + +Replace the **exchange-reject** branch (`elif "error" in status:`) log line (keep the `raise HyperliquidRejection(...)` unchanged): + +```python + elif "error" in status: + log.error( + "Order rejected by exchange | %s | error=%s | response=%s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + reduce_only=request.reduce_only, leverage=leverage, + cloid=request.cloid, req_id=request.req_id, + ), + status["error"], + _safe_json(res), + ) + raise HyperliquidRejection(f"Exchange rejected order: {status['error']}") +``` + +Replace the **unexpected-status** `else` log line: + +```python + else: + log.error( + "Unexpected order status | %s | status=%s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + cloid=request.cloid, req_id=request.req_id, + ), + _safe_json(status), + ) + raise HyperliquidAPIError(f"Unexpected order status: {status}") +``` + +- [ ] **Step 4: Run tests to verify they pass** + +Run: `python3.11 -m pytest tests/test_hyperliquid_service.py -v` +Expected: PASS (all service tests, including the two new ones — the existing reject/shape tests still pass since exceptions are unchanged). + +- [ ] **Step 5: Commit** + +```bash +git add hypertrade/routes/hyperliquid_service.py tests/test_hyperliquid_service.py +git commit -m "feat(exec): enrich service failure logs with order context + payload" +``` + +--- + +### Task 5: Enrich the webhook retry-loop and handler logs + +**Files:** +- Modify: `hypertrade/routes/webhooks.py` (add import; `_place_order_with_retry` ~lines 85-133; the three exception handlers in `hypertrade_webhook` ~lines 330-401) +- Test: `tests/test_webhook.py` (add one test) + +**Interfaces:** +- Consumes: `format_log_context` (Task 1), `OrderRequest.req_id` (Task 2). +- Produces: the terminal network/API retry line now includes `str(e)` + correlation; rejection/validation lines and the three handlers include `req_id`/`cloid`/`symbol`/`side`. + +- [ ] **Step 1: Write the failing test** + +Append to `tests/test_webhook.py`: + +```python +def test_network_failure_logs_error_and_correlation(monkeypatch, caplog): + """The terminal retry line must carry the underlying error string AND + correlation (cloid); the handler line must carry the req_id.""" + import logging as _logging + StubHyperliquidService.reset() + StubHyperliquidService.should_fail = True + StubHyperliquidService.failure_type = "network" + app = make_app(monkeypatch, secret="secret") + client = TestClient(app) + + with caplog.at_level(_logging.WARNING, logger="uvicorn.error"): + resp = client.post("/webhook", json=copy.deepcopy(BASE_PAYLOAD)) + assert resp.status_code == 503 + + msgs = [r.getMessage() for r in caplog.records] + assert any( + "Order placement failed after" in m and "Network timeout" in m and "cloid=" in m + for m in msgs + ), msgs + assert any( + "Network error placing order" in m and "req_id=" in m for m in msgs + ), msgs +``` + +- [ ] **Step 2: Run test to verify it fails** + +Run: `python3.11 -m pytest tests/test_webhook.py::test_network_failure_logs_error_and_correlation -v` +Expected: FAIL (the terminal line currently logs only the attempt count, with no `str(e)`/`cloid`, and the handler line has no `req_id`). + +- [ ] **Step 3: Write minimal implementation** + +In `hypertrade/routes/webhooks.py`, add the import next to the other relative imports (e.g. after `from ..idempotency import ReserveOutcome`): + +```python +from ..logging import format_log_context +``` + +In `_place_order_with_retry`, build a correlation context once, right after `cloid = order_request.cloid`: + +```python + cloid = order_request.cloid + ctx = format_log_context( + symbol=order_request.symbol, + side=getattr(order_request.side, "value", order_request.side), + cloid=cloid, + req_id=order_request.req_id, + ) +``` + +Then replace the four log lines inside the `try/except` of the retry loop: + +```python + except HyperliquidRejection as e: + if attempt < 1: + log.warning("Order REJECTED (attempt %d) — retrying once with a fresh price: %s | %s", attempt + 1, str(e), ctx) + continue + log.error("Order REJECTED again after one retry — surfacing terminal (no further retry): %s | %s", str(e), ctx) + raise + except HyperliquidValidationError as e: + # Don't retry validation errors - they're permanent + log.warning("Order validation failed, not retrying: %s | %s | order=%s", str(e), ctx, order_request) + raise + except (HyperliquidNetworkError, HyperliquidAPIError) as e: + if attempt < max_retries: + wait_time = 2 ** attempt # Exponential backoff: 1s, 2s, 4s... + log.warning( + "Order placement attempt %d/%d failed, retrying in %ds: %s | %s", + attempt + 1, max_retries + 1, wait_time, str(e), ctx + ) + await asyncio.sleep(wait_time) + else: + log.error("Order placement failed after %d attempts: %s | %s", max_retries + 1, str(e), ctx) + raise +``` + +In `hypertrade_webhook`, enrich the three exception-handler log lines (leave the `db.log_order`/`db.log_failure`/`raise HTTPException` parts unchanged). The locals `req_id`, `cloid`, `symbol`, `side` are all in scope at these points: + +```python + except HyperliquidValidationError as e: + log.warning( + "Order validation error: %s | %s", e, + format_log_context(req_id=req_id, cloid=cloid, symbol=symbol, side=side.value), + ) +``` + +```python + except HyperliquidNetworkError as e: + log.error( + "Network error placing order (after retries): %s | %s", e, + format_log_context(req_id=req_id, cloid=cloid, symbol=symbol, side=side.value), + ) +``` + +```python + except HyperliquidAPIError as e: + log.error( + "API error placing order (after retries): %s | %s", e, + format_log_context(req_id=req_id, cloid=cloid, symbol=symbol, side=side.value), + ) +``` + +- [ ] **Step 4: Run test to verify it passes** + +Run: `python3.11 -m pytest tests/test_webhook.py -v` +Expected: PASS (all webhook tests, including the new one; the existing 503/502/400 retry tests still pass — exceptions/status codes are unchanged). + +- [ ] **Step 5: Commit** + +```bash +git add hypertrade/routes/webhooks.py tests/test_webhook.py +git commit -m "feat(exec): enrich retry-loop + handler logs with error + correlation" +``` + +--- + +### Task 6: Secret-safety regression test + +**Files:** +- Test: `tests/test_webhook.py` (add one test) + +**Interfaces:** +- Consumes: the enriched failure logs from Tasks 4-5. +- Produces: a guarantee that failure-level logs never emit the webhook secret. + +- [ ] **Step 1: Write the test (expected to pass immediately — it guards the constraint)** + +Append to `tests/test_webhook.py`: + +```python +def test_failure_logs_do_not_leak_secret(monkeypatch, caplog): + """A failing order must not emit the webhook secret in failure-level (WARNING+) + logs. (The DEBUG full-payload log is out of scope and excluded by the level.)""" + import logging as _logging + StubHyperliquidService.reset() + StubHyperliquidService.should_fail = True + StubHyperliquidService.failure_type = "api" + app = make_app(monkeypatch, secret="topsecret-xyz") + client = TestClient(app) + + payload = copy.deepcopy(BASE_PAYLOAD) + payload["general"]["secret"] = "topsecret-xyz" + + with caplog.at_level(_logging.WARNING, logger="uvicorn.error"): + resp = client.post("/webhook", json=payload) + assert resp.status_code == 502 + + for record in caplog.records: + assert "topsecret-xyz" not in record.getMessage() +``` + +- [ ] **Step 2: Run test to verify it passes** + +Run: `python3.11 -m pytest tests/test_webhook.py::test_failure_logs_do_not_leak_secret -v` +Expected: PASS (our failure logs carry only order context + exchange responses, never the secret). + +- [ ] **Step 3: Run the full suite** + +Run: `python3.11 -m pytest -q` +Expected: PASS (entire suite green — the suite is hermetic per project memory). + +- [ ] **Step 4: Commit** + +```bash +git add tests/test_webhook.py +git commit -m "test(exec): assert failure logs never leak the webhook secret" +``` + +--- + +## Self-Review + +**Spec coverage:** +- Gap 1 (no `req_id`/`cloid` correlation) → Tasks 2, 4, 5. +- Gap 2 (exchange reject drops order context) → Task 4 (exchange-reject branch). +- Gap 3 (computed aggressive price never logged) → Task 3. +- Gap 4 (terminal retry line drops the error) → Task 5 (terminal network/API line now includes `str(e)`). +- Constraint "no secrets in logs" → Task 6. +- Constraint "log stream only / no schema change / no taxonomy change" → no task touches DB schema or `hyperliquid_errors.py`; all `raise`/status codes preserved. +- Shared helper / no duplicated logic → Task 1 (`format_log_context`), used by Tasks 3-5. + +**Placeholder scan:** No TBD/TODO; every code step shows the full code. + +**Type consistency:** `format_log_context(**fields) -> str` defined in Task 1 and called with keyword args only in Tasks 3-5. `OrderRequest.req_id: Optional[str]` defined in Task 2 and read as `request.req_id` / `order_request.req_id` in Tasks 4-5. `_safe_json(obj) -> str` defined and used only within Task 4's file. `side.value` is used where `side`/`request.side` is a `Side`/`PositionSide` enum (all such call sites); the retry-loop uses `getattr(..., "value", ...)` to tolerate the enum. diff --git a/docs/superpowers/specs/2026-06-28-order-failure-logging-design.md b/docs/superpowers/specs/2026-06-28-order-failure-logging-design.md new file mode 100644 index 0000000..f00ce49 --- /dev/null +++ b/docs/superpowers/specs/2026-06-28-order-failure-logging-design.md @@ -0,0 +1,104 @@ +# Order Failure Logging Enrichment — Design + +**Date:** 2026-06-28 +**Status:** Approved (design) +**Scope:** Diagnostic logging only. No change to the error taxonomy, retry policy, DB schema, or execution behaviour. + +## Problem + +When an order fails it is currently hard to reconstruct *why* from the logs. Four concrete gaps: + +1. **No `req_id` / `cloid` correlation.** The request-logging middleware emits `req_id`, but no log line in the execution path (`hyperliquid_service.place_order`, `webhooks._place_order_with_retry`, the webhook exception handlers) carries it. A failure line cannot be tied back to the originating webhook request nor to the `cloid` the exchange indexed the order under. +2. **Exchange rejections drop the order context.** `hyperliquid_service.py` logs only `symbol` + `status["error"]` on a reject — not the price actually sent, size, side, `reduce_only`, or leverage. +3. **The computed aggressive price is never logged.** `execution_client.market_order` computes `mid → aggressive_px → norm_px` but logs none of it — exactly the value needed to diagnose a "bad price / could not match" reject. +4. **The terminal retry line discards the error.** `webhooks._place_order_with_retry` logs `"Order placement failed after N attempts"` with no `str(e)`. + +## Goal + +On any order failure, the log stream must carry enough context to diagnose root cause: + +- **Correlation:** `req_id` + `cloid` on every failure line in the execution path. +- **Order context:** `symbol`, `side`, `size`, the **price actually sent**, `reduce_only`, `leverage`. +- **Exchange response:** the full response/payload, not just the extracted error string. +- **Pricing:** the computed aggressive pricing (`mid`, slippage bps, `aggressive_px`, `norm_px`) for IOC market orders. + +Constraints (from project memory and the approved scope): + +- **Log stream only.** No DB/schema migration. `failures` and `log_order` are unchanged. +- **No structural refactor.** No `contextvars`/`logging.Filter` infrastructure, no JSON structured logging. +- **Thin executor.** No new trading/position logic; this is observability only. + +## Approach + +`OrderRequest` already carries `cloid`. Add a `req_id` field to it, and that request-scoped dataclass becomes the correlation vehicle through all three layers without changing any method signature. `cloid` is the natural correlation key at the execution-client layer (it has no `req_id`); `req_id`+`cloid` apply at the service and webhook layers. + +## Components / changes + +### 1. Shared context formatter — `hypertrade/logging.py` + +A single helper so the `key=value` diagnostic prefix is never copy-pasted across call sites (global rule: no duplicated logic). `hypertrade/logging.py` is a leaf module already imported for logging utilities, so there is no circular-import risk from `execution_client` / `service` / `webhooks`. + +```python +def format_log_context(**fields: object) -> str: + """Format diagnostic fields as a space-separated 'k=v' string, skipping None. + + Used to build a uniform correlation/context prefix on failure log lines. + Never raises: tolerates None values and arbitrary repr-able objects. + """ + return " ".join(f"{k}={v}" for k, v in fields.items() if v is not None) +``` + +### 2. `OrderRequest.req_id` + +Add `req_id: Optional[str] = None`. The webhook handler sets it alongside `cloid` when building the `OrderRequest`. Threads `req_id` into the retry loop and `place_order` with no signature churn. + +### 3. `execution_client.market_order` / `limit_order` + +Emit one **INFO** line immediately before submitting, carrying the pricing that is about to be sent: + +- `market_order`: `symbol, side, size, mid, slippage_bps, aggressive_px, norm_px, reduce_only, cloid`. +- `limit_order`: `symbol, side, size, price, norm_price, tif, reduce_only, cloid`. + +So when a reject follows, the price actually sent is on the immediately preceding line. INFO level keeps it present under the production INFO daemon level. + +### 4. `hyperliquid_service.place_order` + +Enrich every failure site with the order context (via `format_log_context`, including `req_id` + `cloid`) and the full payload: + +- No-response (`res is None`). +- Unexpected response shape (already logs `res`; add context + correlation). +- **Exchange reject** (`"error" in status`): add `side`, `size`, `reduce_only`, `cloid`, `req_id`, and `json.dumps(res)`. +- Unexpected status. +- Leverage-update reject (already logs the response; add correlation + requested/max leverage context). + +### 5. `webhooks._place_order_with_retry` + +- Terminal network/API line: include `str(e)` + context (`cloid`, `symbol`, attempt count). +- Rejection lines (retry + terminal): include `cloid`. +- Validation line: already logs `order_request`; keep. + +### 6. `webhooks` exception handlers + +Add `req_id` + `cloid` + `symbol` + `side` to the three handler log lines (validation / network / API). + +## Error handling & safety + +- **No secrets in logs.** Only order parameters, exchange responses, and computed prices are logged — the API private key and `general.secret` never appear in those values. The pre-existing `log.debug("Full webhook payload: %s", raw)` (which includes `general.secret` at DEBUG) is out of scope and unchanged. +- **Logging must never raise.** `format_log_context` tolerates `None`; `json.dumps(res)` is wrapped defensively (fall back to `repr(res)` on `TypeError`/`ValueError`) so a non-serialisable payload never masks the original failure. +- **Levels.** Failure context is emitted at the *same level as the failure* (ERROR for terminal/exchange rejects, WARNING for retryable attempts) so it is captured at the production INFO level. The pre-submit pricing line is INFO. + +## Testing (TDD) + +Write the assertions first, then implement. Tests run with `python3.11 -m pytest`. + +- `test_hyperliquid_service.py`: on an exchange-reject response, assert (via `caplog`) the ERROR record contains `cloid`, `symbol`, `side`, `size`, and the response payload. On `res is None` and unexpected-shape, assert context + correlation present. +- `test_hyperliquid_service.py` / new: assert the pre-submit pricing line for a market order contains `mid`, `aggressive_px`, `norm_px`, `cloid`. +- `test_webhook.py`: on a terminal network failure, assert the retry-loop ERROR record contains `str(e)`; on each handler path assert `req_id`/`cloid` present. +- One test asserts that **no secret** (`general.secret` value, private key) appears in captured log output for a failing order. + +## Out of scope (YAGNI) + +- JSON structured logging. +- A `context` column / migration on the `failures` table. +- `contextvars` / `logging.Filter` correlation infrastructure. +- Any change to the `HyperliquidError` taxonomy, retry counts, or pricing logic. diff --git a/hypertrade/logging.py b/hypertrade/logging.py index 7fa3f34..7cf7c06 100644 --- a/hypertrade/logging.py +++ b/hypertrade/logging.py @@ -14,6 +14,16 @@ log = pylog.getLogger("uvicorn.error") +def format_log_context(**fields: object) -> str: + """Format diagnostic fields as a space-separated ``key=value`` string. + + Used to build a uniform correlation/context suffix for failure log lines so + the prefix is defined once (no copy-paste across call sites). Skips fields + whose value is ``None``; never raises. + """ + return " ".join(f"{key}={value}" for key, value in fields.items() if value is not None) + + def configure_logging(log_level: str = "INFO") -> None: """Configure Python logging to use the specified level.""" level = log_level.upper() diff --git a/hypertrade/routes/hyperliquid_execution_client.py b/hypertrade/routes/hyperliquid_execution_client.py index e6f0f41..b2cf98b 100644 --- a/hypertrade/routes/hyperliquid_execution_client.py +++ b/hypertrade/routes/hyperliquid_execution_client.py @@ -10,6 +10,7 @@ from hyperliquid.exchange import Exchange from hyperliquid.utils.types import Cloid from hypertrade.config import get_settings +from hypertrade.logging import format_log_context from .hyperliquid_data_client import HyperliquidDataClient from .hyperliquid_errors import translate_request_errors @@ -110,6 +111,16 @@ def limit_order( is_buy = side == PositionSide.LONG norm_price = self._normalize_price(symbol, price, is_buy=is_buy) + log.info( + "Submitting LIMIT %s | %s", + tif, + format_log_context( + symbol=symbol, side=side.value, size=size, + price=price, norm_price=norm_price, + reduce_only=reduce_only, cloid=cloid, + ), + ) + with translate_request_errors("limit_order"): res = self.exchange.order( symbol, # ← positional: coin @@ -145,6 +156,16 @@ def market_order( aggressive_px = mid * (1.0 + slip) if is_buy else mid * (1.0 - slip) norm_px = self._normalize_price(symbol, aggressive_px, is_buy=is_buy) + log.info( + "Submitting MARKET IOC | %s", + format_log_context( + symbol=symbol, side=side.value, size=size, + mid=f"{mid:.6f}", slippage_bps=slippage_bps, + aggressive_px=f"{aggressive_px:.6f}", norm_px=norm_px, + reduce_only=reduce_only, cloid=cloid, + ), + ) + with translate_request_errors("market_order"): return self.exchange.order( symbol, diff --git a/hypertrade/routes/hyperliquid_service.py b/hypertrade/routes/hyperliquid_service.py index 7a5b787..5ecde9c 100644 --- a/hypertrade/routes/hyperliquid_service.py +++ b/hypertrade/routes/hyperliquid_service.py @@ -17,9 +17,20 @@ HyperliquidAPIError, HyperliquidRejection, ) +from hypertrade.logging import format_log_context log = logging.getLogger("uvicorn.error") +def _safe_json(obj: object) -> str: + """json.dumps that never raises — falls back to repr for non-serialisable payloads. + + A logging path must never mask the original failure with a serialisation error. + """ + try: + return json.dumps(obj) + except (TypeError, ValueError): + return repr(obj) + @dataclass class OrderRequest: """Request parameters for placing an order on Hyperliquid.""" @@ -38,6 +49,10 @@ class OrderRequest: # by the webhook layer so that a retry of the same request reuses the same # cloid, letting us query the exchange for it before resubmitting (TD-1). cloid: Optional[str] = None + # Request-scoped correlation id (the webhook's req_id). Threaded onto the + # request so failure logs in the service/webhook layers can be tied back to + # the originating request. Distinct from cloid (the exchange-side order id). + req_id: Optional[str] = None @dataclass class OrderResult: @@ -157,7 +172,15 @@ def place_order(self, request: OrderRequest) -> dict: # at the exchange's DEFAULT leverage (the naked-10x incident). Abort the trade # so the strategy bot sees a failure and never holds a wrong-leverage position. if leverage_response.get('status') != 'ok': - log.error("Leverage update REJECTED: symbol=%s response=%s", symbol, json.dumps(leverage_response, indent=2)) + log.error( + "Leverage update REJECTED | %s | response=%s", + format_log_context( + symbol=symbol, requested_leverage=leverage, + max_leverage=max_leverage, is_cross=is_cross, + cloid=request.cloid, req_id=request.req_id, + ), + _safe_json(leverage_response), + ) raise HyperliquidValidationError( f"Leverage/margin update rejected for {symbol} " f"(requested {leverage}x, is_cross={is_cross}): {leverage_response.get('response')}" @@ -214,13 +237,27 @@ def place_order(self, request: OrderRequest) -> dict: # Safe printing – handle both filled and error cases if res is None: - log.error("Order execution failed: symbol=%s side=%s size=%s (no response from API)", symbol, request.side, size) + log.error( + "Order execution failed (no response from API) | %s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + reduce_only=request.reduce_only, + cloid=request.cloid, req_id=request.req_id, + ), + ) raise HyperliquidAPIError("Order Creation did not work") else: try: status = res["response"]["data"]["statuses"][0] except (KeyError, TypeError, IndexError) as exc: - log.error("Unexpected order response shape: symbol=%s response=%s", symbol, res) + log.error( + "Unexpected order response shape | %s | response=%s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + cloid=request.cloid, req_id=request.req_id, + ), + _safe_json(res), + ) raise HyperliquidAPIError(f"Unexpected order response shape: {res}") from exc if "filled" in status: st = status["filled"] @@ -231,13 +268,29 @@ def place_order(self, request: OrderRequest) -> dict: # The exchange accepted the request shape but rejected the order # (invalid price, insufficient margin, ...). Surface it instead of # reporting a phantom success, or the strategy bot desyncs from reality. - log.error("Order rejected by exchange: symbol=%s error=%s", symbol, status["error"]) + log.error( + "Order rejected by exchange | %s | error=%s | response=%s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + reduce_only=request.reduce_only, leverage=leverage, + cloid=request.cloid, req_id=request.req_id, + ), + status["error"], + _safe_json(res), + ) # A recoverable exchange rejection (insufficient margin / could-not-match / bad price): # HyperliquidRejection gets ONE fresh-priced retry in the webhook loop, then surfaces # TERMINAL (HTTP 400 → fast pause) — NOT a 502 'transient' the desk would retry for ~1h. raise HyperliquidRejection(f"Exchange rejected order: {status['error']}") else: - log.error("Unexpected order status: symbol=%s status=%s", symbol, status) + log.error( + "Unexpected order status | %s | status=%s", + format_log_context( + symbol=symbol, side=request.side.value, size=size, + cloid=request.cloid, req_id=request.req_id, + ), + _safe_json(status), + ) raise HyperliquidAPIError(f"Unexpected order status: {status}") return res diff --git a/hypertrade/routes/webhooks.py b/hypertrade/routes/webhooks.py index b1834bf..9a6dd88 100644 --- a/hypertrade/routes/webhooks.py +++ b/hypertrade/routes/webhooks.py @@ -7,6 +7,7 @@ import sqlite3 import time import json +import re from datetime import datetime, timezone from typing import Optional @@ -25,6 +26,7 @@ from ..routes.tradingview_enums import SignalType, PositionType, OrderAction, Side from ..idempotency import ReserveOutcome +from ..logging import format_log_context from .hyperliquid_service import ( HyperliquidService, @@ -83,6 +85,12 @@ async def _place_order_with_retry(client: HyperliquidService, order_request: Ord HyperliquidNetworkError: For network errors (retried) """ cloid = order_request.cloid + ctx = format_log_context( + symbol=order_request.symbol, + side=getattr(order_request.side, "value", order_request.side), + cloid=cloid, + req_id=order_request.req_id, + ) for attempt in range(max_retries + 1): # Before any RETRY (attempt > 0) carrying a cloid, confirm the order did # not already land under that cloid — never resubmit a possibly-live order. @@ -112,24 +120,24 @@ async def _place_order_with_retry(client: HyperliquidService, order_request: Ord # then is surfaced TERMINAL (HyperliquidRejection ⊂ ValidationError → HTTP 400 → the strategy # bot pauses/unwinds fast, NEVER the ~1h desk transient-retry). Logged on every attempt. if attempt < 1: - log.warning("Order REJECTED (attempt %d) — retrying once with a fresh price: %s", attempt + 1, str(e)) + log.warning("Order REJECTED (attempt %d) — retrying once with a fresh price: %s | %s", attempt + 1, str(e), ctx) continue - log.error("Order REJECTED again after one retry — surfacing terminal (no further retry): %s", str(e)) + log.error("Order REJECTED again after one retry — surfacing terminal (no further retry): %s | %s", str(e), ctx) raise - except HyperliquidValidationError: + except HyperliquidValidationError as e: # Don't retry validation errors - they're permanent - log.warning("Order validation failed, not retrying: %s", order_request) + log.warning("Order validation failed, not retrying: %s | %s | order=%s", str(e), ctx, order_request) raise except (HyperliquidNetworkError, HyperliquidAPIError) as e: if attempt < max_retries: wait_time = 2 ** attempt # Exponential backoff: 1s, 2s, 4s... log.warning( - "Order placement attempt %d/%d failed, retrying in %ds: %s", - attempt + 1, max_retries + 1, wait_time, str(e) + "Order placement attempt %d/%d failed, retrying in %ds: %s | %s", + attempt + 1, max_retries + 1, wait_time, str(e), ctx ) await asyncio.sleep(wait_time) else: - log.error("Order placement failed after %d attempts", max_retries + 1) + log.error("Order placement failed after %d attempts: %s | %s", max_retries + 1, str(e), ctx) raise @@ -264,6 +272,7 @@ async def hypertrade_webhook( leverage=leverage, subaccount=vault_address, cloid=cloid, + req_id=req_id, ) log.debug( @@ -322,13 +331,17 @@ async def hypertrade_webhook( if reservation.outcome is ReserveOutcome.IN_FLIGHT: raise HTTPException(status_code=409, detail="Duplicate request in flight") + handler_ctx = format_log_context(req_id=req_id, cloid=cloid, symbol=symbol, side=side.value) placed_ok = False try: log.info("Attempting to place order on Hyperliquid: symbol=%s side=%s", symbol, side.value) result = await _place_order_with_retry(client, order_request, max_retries=2) placed_ok = True except HyperliquidValidationError as e: - log.warning("Order validation error: %s", e) + log.warning( + "Order validation error: %s | %s", e, + handler_ctx, + ) if db and req_id: db.log_order( request_id=req_id, @@ -351,7 +364,10 @@ async def hypertrade_webhook( ) raise HTTPException(status_code=400, detail=f"Invalid order: {e}") from e except HyperliquidNetworkError as e: - log.error("Network error placing order (after retries): %s", e) + log.error( + "Network error placing order (after retries): %s | %s", e, + handler_ctx, + ) if db and req_id: db.log_order( request_id=req_id, @@ -377,7 +393,10 @@ async def hypertrade_webhook( detail="Temporary service unavailable - order may have been placed, check manually" ) from e except HyperliquidAPIError as e: - log.error("API error placing order (after retries): %s", e) + log.error( + "API error placing order (after retries): %s | %s", e, + handler_ctx, + ) if db and req_id: db.log_order( request_id=req_id, @@ -563,15 +582,50 @@ def secret_enforcement(request: Request, raw: dict) -> None: raise HTTPException(status_code=401, detail="Unauthorized: invalid webhook secret") +_SECRET_FIELD_RE = re.compile(r'("secret"\s*:\s*")[^"]*(")', re.IGNORECASE) + + +def _redact_secrets(text: str, secret: Optional[str]) -> str: + """Redact credential material from a raw request body before logging (TD-18). + + Masks (1) any JSON ``"secret": ""`` field via pattern, and (2) the + configured webhook secret wherever it appears verbatim — so a malformed + payload logged for debugging on the invalid-JSON path never leaks + ``general.secret`` at WARNING level. Best-effort on malformed input: an + unterminated ``secret`` field may evade the pattern, but a configured secret + is still masked by the literal replacement. Never raises. + """ + redacted = _SECRET_FIELD_RE.sub(r"\1***REDACTED***\2", text) + if secret: + redacted = redacted.replace(secret, "***REDACTED***") + return redacted + + async def _log_invalid_json_body(request: Request) -> None: - """Log the full request body when JSON parsing fails, with req_id.""" + """Log the request body when JSON parsing fails, with req_id. + + The body is redacted of the webhook secret before logging (TD-18): a + malformed payload is still useful for debugging, but ``general.secret`` must + never reach the logs at WARNING level. + """ try: body_bytes = await request.body() body_text = body_bytes.decode("utf-8", errors="replace") except (RuntimeError, UnicodeDecodeError): body_text = "" + # Fetching the secret must never turn this logging helper into a 500 — fall + # back to None (the regex still masks the JSON `secret` field) on any failure. + try: + settings = get_settings() + secret = ( + settings.webhook_secret.get_secret_value() + if getattr(settings, "webhook_secret", None) + else None + ) + except Exception: # pylint: disable=broad-except + secret = None req_id = getattr(request.state, "request_id", None) - log.warning("Invalid JSON body req_id=%s body=%s", req_id, body_text) + log.warning("Invalid JSON body req_id=%s body=%s", req_id, _redact_secrets(body_text, secret)) def _require_json_content_type(request: Request) -> None: """Ensure the request has application/json content type or raise 415.""" diff --git a/tests/test_execution_client_cloid.py b/tests/test_execution_client_cloid.py index 5021722..4532a04 100644 --- a/tests/test_execution_client_cloid.py +++ b/tests/test_execution_client_cloid.py @@ -57,6 +57,7 @@ def _client(monkeypatch) -> HyperliquidExecutionClient: # Deterministic aggressive price so we don't depend on impact data. client._aggressive_price_from_impact = MagicMock(return_value=100.0) client._normalize_price = MagicMock(return_value=100.0) + client.data.get_mid = MagicMock(return_value=1000.0) return client diff --git a/tests/test_execution_client_price.py b/tests/test_execution_client_price.py index fbd1742..b312cef 100644 --- a/tests/test_execution_client_price.py +++ b/tests/test_execution_client_price.py @@ -108,3 +108,43 @@ def test_market_order_prices_off_mid_with_slippage(monkeypatch): client.market_order(symbol="xyz:KR200", side=PositionSide.LONG, size=1.0, premium_bps=500) buy_px = client.exchange.order.call_args.args[3] assert buy_px == 1050.0, f"BUY must price 5% ABOVE mid (crosses up to fill), got {buy_px}" + + +def test_market_order_logs_submitted_pricing(monkeypatch, caplog): + """Before submitting a MARKET IOC, the client logs the mid and the exact + aggressive/normalized price it is about to send, tagged with the cloid — the + primary diagnostic for a 'bad price / could not match' reject.""" + import logging as _logging + client = _client(monkeypatch, 3) + client.data.get_mid = MagicMock(return_value=1000.0) + + with caplog.at_level(_logging.INFO, logger="uvicorn.error"): + client.market_order( + symbol="SOL", side=PositionSide.LONG, size=2.0, + premium_bps=500, cloid="0x" + "a" * 32, + ) + + msgs = [r.getMessage() for r in caplog.records] + assert any( + "mid=1000" in m and "norm_px=1050" in m and ("0x" + "a" * 32) in m + for m in msgs + ), msgs + + +def test_limit_order_logs_submitted_pricing(monkeypatch, caplog): + """limit_order logs the normalized price it is about to submit, tagged with cloid.""" + import logging as _logging + client = _client(monkeypatch, 3) + client.exchange.order.return_value = { + "response": {"data": {"statuses": [{"resting": {"oid": 1}}]}} + } + with caplog.at_level(_logging.INFO, logger="uvicorn.error"): + client.limit_order( + symbol="SOL", side=PositionSide.LONG, size=2.0, price=21.987, + tif="Gtc", cloid="0x" + "c" * 32, + ) + msgs = [r.getMessage() for r in caplog.records] + assert any( + "Submitting LIMIT" in m and "norm_price=" in m and ("0x" + "c" * 32) in m + for m in msgs + ), msgs diff --git a/tests/test_hyperliquid_service.py b/tests/test_hyperliquid_service.py index 74087b5..e832282 100644 --- a/tests/test_hyperliquid_service.py +++ b/tests/test_hyperliquid_service.py @@ -294,3 +294,45 @@ def test_close_order_skips_leverage_update(monkeypatch): )) client.update_leverage.assert_not_called() # never touched on a close client.close_position.assert_called_once() # the exit still goes through + + +def test_exchange_reject_logs_full_context(monkeypatch, caplog): + """On an exchange reject the ERROR log must carry the order context (symbol, + side, size, cloid, req_id) and the error/payload, not just the error string.""" + import logging as _logging + svc, client = _service(monkeypatch) + client.market_order.return_value = { + "response": {"data": {"statuses": [{"error": "Order has invalid price."}]}} + } + with caplog.at_level(_logging.ERROR, logger="uvicorn.error"): + with pytest.raises(HyperliquidRejection): + svc.place_order(OrderRequest( + symbol="SOL", side=Side.BUY, signal=SignalType.OPEN_LONG, + qty=Decimal("2"), price=Decimal("100"), leverage=3, + cloid="0x" + "a" * 32, req_id="req-123", + )) + msg = " ".join(r.getMessage() for r in caplog.records) + assert "symbol=SOL" in msg + assert "side=buy" in msg + assert "size=2" in msg + assert ("cloid=0x" + "a" * 32) in msg + assert "req_id=req-123" in msg + assert "Order has invalid price." in msg + + +def test_no_response_logs_context(monkeypatch, caplog): + """A None exchange response is logged with the order context before raising.""" + import logging as _logging + svc, client = _service(monkeypatch) + client.market_order.return_value = None + with caplog.at_level(_logging.ERROR, logger="uvicorn.error"): + with pytest.raises(HyperliquidAPIError): + svc.place_order(OrderRequest( + symbol="SOL", side=Side.BUY, signal=SignalType.OPEN_LONG, + qty=Decimal("1"), price=Decimal("100"), leverage=1, + cloid="0x" + "b" * 32, req_id="req-456", + )) + msg = " ".join(r.getMessage() for r in caplog.records) + assert "symbol=SOL" in msg and "req_id=req-456" in msg and ("cloid=0x" + "b" * 32) in msg + assert "side=buy" in msg + assert "size=1" in msg diff --git a/tests/test_logging_context.py b/tests/test_logging_context.py new file mode 100644 index 0000000..316cf4b --- /dev/null +++ b/tests/test_logging_context.py @@ -0,0 +1,29 @@ +"""Tests for format_log_context — the shared diagnostic-context formatter used to +build a uniform correlation suffix on failure log lines.""" + +from __future__ import annotations + +import pathlib +import sys + +REPO_ROOT = str(pathlib.Path(__file__).resolve().parents[1]) +if REPO_ROOT not in sys.path: + sys.path.insert(0, REPO_ROOT) + +from hypertrade.logging import format_log_context + + +def test_joins_key_values_in_order(): + assert format_log_context(symbol="SOL", side="buy", size=2.0) == "symbol=SOL side=buy size=2.0" + + +def test_skips_none_values(): + assert format_log_context(symbol="SOL", cloid=None, req_id="r-1") == "symbol=SOL req_id=r-1" + + +def test_empty_when_all_none(): + assert format_log_context(a=None, b=None) == "" + + +def test_tolerates_arbitrary_reprable_objects(): + assert format_log_context(payload={"k": 1}) == "payload={'k': 1}" diff --git a/tests/test_webhook.py b/tests/test_webhook.py index 6cc30bf..6b311db 100644 --- a/tests/test_webhook.py +++ b/tests/test_webhook.py @@ -909,3 +909,111 @@ def test_dex_qualified_symbol_preserves_case(monkeypatch): assert resp2.status_code == 200, resp2.text assert resp2.json()["symbol"] == "LINK" assert StubHyperliquidService.last_order_request.symbol == "LINK" + + +def test_order_request_carries_req_id(monkeypatch): + """The webhook must thread its request id onto OrderRequest so downstream + failure logs can correlate back to the originating request.""" + StubHyperliquidService.reset() + app = make_app(monkeypatch, secret="secret") + client = TestClient(app) + + resp = client.post("/webhook", json=copy.deepcopy(BASE_PAYLOAD)) + assert resp.status_code == 200, resp.text + order_req = StubHyperliquidService.last_order_request + assert order_req is not None + assert isinstance(order_req.req_id, str) and order_req.req_id + + +def test_network_failure_logs_error_and_correlation(monkeypatch, caplog): + """The terminal retry line must carry the underlying error string AND + correlation (cloid); the handler line must carry the req_id.""" + import logging as _logging + StubHyperliquidService.reset() + StubHyperliquidService.should_fail = True + StubHyperliquidService.failure_type = "network" + app = make_app(monkeypatch, secret="secret") + client = TestClient(app) + + with caplog.at_level(_logging.WARNING, logger="uvicorn.error"): + resp = client.post("/webhook", json=copy.deepcopy(BASE_PAYLOAD)) + assert resp.status_code == 503 + + msgs = [r.getMessage() for r in caplog.records] + assert any( + "Order placement failed after" in m and "Network timeout" in m and "cloid=" in m + for m in msgs + ), msgs + assert any( + "Network error placing order" in m and "req_id=" in m for m in msgs + ), msgs + + +def test_failure_logs_do_not_leak_secret(monkeypatch, caplog): + """A failing ORDER (the order-execution failure path) must not emit the webhook + secret in failure-level (WARNING+) logs. The invalid-JSON path is guarded + separately by test_invalid_json_body_log_redacts_secret (TD-18). Capturing at + WARNING also excludes the out-of-scope DEBUG full-payload log.""" + import logging as _logging + StubHyperliquidService.reset() + StubHyperliquidService.should_fail = True + StubHyperliquidService.failure_type = "api" + app = make_app(monkeypatch, secret="topsecret-xyz") + client = TestClient(app) + + payload = copy.deepcopy(BASE_PAYLOAD) + payload["general"]["secret"] = "topsecret-xyz" + + with caplog.at_level(_logging.WARNING, logger="uvicorn.error"): + resp = client.post("/webhook", json=payload) + assert resp.status_code == 502 + + assert len(caplog.records) > 0, "Expected at least one WARNING+ record from the failure path" + for record in caplog.records: + assert "topsecret-xyz" not in record.getMessage() + + +# =================================================================== +# TD-18: the invalid-JSON debug log must not leak the webhook secret +# =================================================================== + +def test_redact_secrets_masks_field_and_configured_value(): + """_redact_secrets masks both a JSON `secret` field and the configured secret + value wherever it appears, and leaves secret-free text untouched (TD-18).""" + from hypertrade.routes.webhooks import _redact_secrets + + # A JSON `secret` field is masked by pattern even with no configured secret. + out1 = _redact_secrets('{"general": {"secret": "abc123"}}', None) + assert "abc123" not in out1 + assert "REDACTED" in out1 + + # The configured secret value is masked wherever it appears, even unquoted/malformed. + out2 = _redact_secrets("noise sek-XYZ trailing", "sek-XYZ") + assert "sek-XYZ" not in out2 + assert "REDACTED" in out2 + + # Secret-free text is returned unchanged. + assert _redact_secrets('{"a": 1}', None) == '{"a": 1}' + + # An empty/None configured secret must not corrupt the text (no per-char replace). + assert _redact_secrets("plain text", "") == "plain text" + + +def test_invalid_json_body_log_redacts_secret(monkeypatch, caplog): + """A malformed JSON body, logged for debugging, must not leak the webhook + secret at WARNING level — while still logging the (redacted) body (TD-18).""" + import logging as _logging + app = make_app(monkeypatch, secret="topsecret-xyz") + client = TestClient(app) + + # Trailing comma -> invalid JSON -> 422 -> _log_invalid_json_body runs. + bad = b'{"general":{"secret":"topsecret-xyz"},}' + with caplog.at_level(_logging.WARNING, logger="uvicorn.error"): + resp = client.post("/webhook", content=bad, headers={"Content-Type": "application/json"}) + assert resp.status_code == 422 + + body_logs = [r.getMessage() for r in caplog.records if "Invalid JSON body" in r.getMessage()] + assert body_logs, "expected an 'Invalid JSON body' WARNING record" + joined = " ".join(body_logs) + assert "topsecret-xyz" not in joined + assert "REDACTED" in joined