From 9e0d95152e508f7696ff2e6fc2beccdcdcac64be Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 06:40:55 +0200 Subject: [PATCH 01/14] docs(spec): design for order-failure logging enrichment (correlation + context) Co-Authored-By: Claude Opus 4.8 (1M context) --- ...2026-06-28-order-failure-logging-design.md | 104 ++++++++++++++++++ 1 file changed, 104 insertions(+) create mode 100644 docs/superpowers/specs/2026-06-28-order-failure-logging-design.md 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. From 26ccf4feb5e105cd8a97895d0ea6e42589f479cf Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 06:47:21 +0200 Subject: [PATCH 02/14] docs(plan): implementation plan for order-failure logging enrichment Co-Authored-By: Claude Opus 4.8 (1M context) --- .../plans/2026-06-28-order-failure-logging.md | 640 ++++++++++++++++++ 1 file changed, 640 insertions(+) create mode 100644 docs/superpowers/plans/2026-06-28-order-failure-logging.md 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. From 051bf48f4d958f20fd11f199d02e5bfc776ebcee Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 06:59:09 +0200 Subject: [PATCH 03/14] feat(logging): add format_log_context helper for failure-log correlation --- hypertrade/logging.py | 10 ++++++++++ tests/test_logging_context.py | 29 +++++++++++++++++++++++++++++ 2 files changed, 39 insertions(+) create mode 100644 tests/test_logging_context.py 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/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}" From b9e66ba14c5235b7767871c0230caa697a4ee1b2 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:02:47 +0200 Subject: [PATCH 04/14] feat(exec): carry req_id on OrderRequest for failure-log correlation --- hypertrade/routes/hyperliquid_service.py | 4 ++++ hypertrade/routes/webhooks.py | 1 + tests/test_webhook.py | 14 ++++++++++++++ 3 files changed, 19 insertions(+) diff --git a/hypertrade/routes/hyperliquid_service.py b/hypertrade/routes/hyperliquid_service.py index 7a5b787..4a976c7 100644 --- a/hypertrade/routes/hyperliquid_service.py +++ b/hypertrade/routes/hyperliquid_service.py @@ -38,6 +38,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: diff --git a/hypertrade/routes/webhooks.py b/hypertrade/routes/webhooks.py index b1834bf..bc1a82b 100644 --- a/hypertrade/routes/webhooks.py +++ b/hypertrade/routes/webhooks.py @@ -264,6 +264,7 @@ async def hypertrade_webhook( leverage=leverage, subaccount=vault_address, cloid=cloid, + req_id=req_id, ) log.debug( diff --git a/tests/test_webhook.py b/tests/test_webhook.py index 6cc30bf..523c190 100644 --- a/tests/test_webhook.py +++ b/tests/test_webhook.py @@ -909,3 +909,17 @@ 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 From 9d8cdb58d35c222356496c5aa7481df546c7585a Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:07:11 +0200 Subject: [PATCH 05/14] feat(exec): log submitted price (mid/aggressive/norm) before each order --- .../routes/hyperliquid_execution_client.py | 21 +++++++++++++++++++ tests/test_execution_client_cloid.py | 1 + tests/test_execution_client_price.py | 21 +++++++++++++++++++ 3 files changed, 43 insertions(+) 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/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..d249e19 100644 --- a/tests/test_execution_client_price.py +++ b/tests/test_execution_client_price.py @@ -108,3 +108,24 @@ 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 From deaecdc37ea10c584a0c417804cd07560706edd1 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:11:56 +0200 Subject: [PATCH 06/14] feat(exec): enrich service failure logs with order context + payload --- hypertrade/routes/hyperliquid_service.py | 59 ++++++++++++++++++++++-- tests/test_hyperliquid_service.py | 40 ++++++++++++++++ 2 files changed, 94 insertions(+), 5 deletions(-) diff --git a/hypertrade/routes/hyperliquid_service.py b/hypertrade/routes/hyperliquid_service.py index 4a976c7..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.""" @@ -161,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')}" @@ -218,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"] @@ -235,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/tests/test_hyperliquid_service.py b/tests/test_hyperliquid_service.py index 74087b5..553ecdc 100644 --- a/tests/test_hyperliquid_service.py +++ b/tests/test_hyperliquid_service.py @@ -294,3 +294,43 @@ 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 From 4e66a21cfa9c85b9460211ce94abda30d6902ef9 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:16:37 +0200 Subject: [PATCH 07/14] feat(exec): enrich retry-loop + handler logs with error + correlation --- hypertrade/routes/webhooks.py | 36 +++++++++++++++++++++++++---------- tests/test_webhook.py | 24 +++++++++++++++++++++++ 2 files changed, 50 insertions(+), 10 deletions(-) diff --git a/hypertrade/routes/webhooks.py b/hypertrade/routes/webhooks.py index bc1a82b..b9eb38d 100644 --- a/hypertrade/routes/webhooks.py +++ b/hypertrade/routes/webhooks.py @@ -25,6 +25,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 +84,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 +119,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 @@ -329,7 +336,10 @@ async def hypertrade_webhook( 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, + format_log_context(req_id=req_id, cloid=cloid, symbol=symbol, side=side.value), + ) if db and req_id: db.log_order( request_id=req_id, @@ -352,7 +362,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, + format_log_context(req_id=req_id, cloid=cloid, symbol=symbol, side=side.value), + ) if db and req_id: db.log_order( request_id=req_id, @@ -378,7 +391,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, + format_log_context(req_id=req_id, cloid=cloid, symbol=symbol, side=side.value), + ) if db and req_id: db.log_order( request_id=req_id, diff --git a/tests/test_webhook.py b/tests/test_webhook.py index 523c190..a0c5f3d 100644 --- a/tests/test_webhook.py +++ b/tests/test_webhook.py @@ -923,3 +923,27 @@ def test_order_request_carries_req_id(monkeypatch): 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 From cbd045c411e3b8d8cc97afb7e69a3501e7572823 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:20:13 +0200 Subject: [PATCH 08/14] test(exec): assert failure logs never leak the webhook secret --- tests/test_webhook.py | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) diff --git a/tests/test_webhook.py b/tests/test_webhook.py index a0c5f3d..48eff81 100644 --- a/tests/test_webhook.py +++ b/tests/test_webhook.py @@ -947,3 +947,24 @@ def test_network_failure_logs_error_and_correlation(monkeypatch, caplog): 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 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() From c336ed0f0e8d3d4f9ceed183b3d6ee2f9a0e2581 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:23:01 +0200 Subject: [PATCH 09/14] test(exec): assert failure-log secret scan is non-vacuous (>=1 record) Co-Authored-By: Claude Opus 4.8 (1M context) --- tests/test_webhook.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/test_webhook.py b/tests/test_webhook.py index 48eff81..0cbbd73 100644 --- a/tests/test_webhook.py +++ b/tests/test_webhook.py @@ -966,5 +966,6 @@ def test_failure_logs_do_not_leak_secret(monkeypatch, caplog): 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() From 6ad0d4d99ec1c9f33843df4ca636b225d49ffccd Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:31:02 +0200 Subject: [PATCH 10/14] refactor(exec): hoist handler log context + close final-review test gaps - DRY: hoist repeated format_log_context into handler_ctx (3 handlers) - test: cover limit_order pre-submit pricing log - test: assert no-response log carries side/size; narrow secret-test docstring Co-Authored-By: Claude Opus 4.8 (1M context) --- hypertrade/routes/webhooks.py | 7 ++++--- tests/test_execution_client_price.py | 19 +++++++++++++++++++ tests/test_hyperliquid_service.py | 2 ++ tests/test_webhook.py | 7 +++++-- 4 files changed, 30 insertions(+), 5 deletions(-) diff --git a/hypertrade/routes/webhooks.py b/hypertrade/routes/webhooks.py index b9eb38d..e22976f 100644 --- a/hypertrade/routes/webhooks.py +++ b/hypertrade/routes/webhooks.py @@ -330,6 +330,7 @@ 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) @@ -338,7 +339,7 @@ async def hypertrade_webhook( 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), + handler_ctx, ) if db and req_id: db.log_order( @@ -364,7 +365,7 @@ async def hypertrade_webhook( 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), + handler_ctx, ) if db and req_id: db.log_order( @@ -393,7 +394,7 @@ async def hypertrade_webhook( 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), + handler_ctx, ) if db and req_id: db.log_order( diff --git a/tests/test_execution_client_price.py b/tests/test_execution_client_price.py index d249e19..b312cef 100644 --- a/tests/test_execution_client_price.py +++ b/tests/test_execution_client_price.py @@ -129,3 +129,22 @@ def test_market_order_logs_submitted_pricing(monkeypatch, caplog): "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 553ecdc..e832282 100644 --- a/tests/test_hyperliquid_service.py +++ b/tests/test_hyperliquid_service.py @@ -334,3 +334,5 @@ def test_no_response_logs_context(monkeypatch, caplog): )) 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_webhook.py b/tests/test_webhook.py index 0cbbd73..e115a43 100644 --- a/tests/test_webhook.py +++ b/tests/test_webhook.py @@ -950,8 +950,11 @@ def test_network_failure_logs_error_and_correlation(monkeypatch, caplog): 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.)""" + """A failing ORDER (the order-execution failure path) must not emit the webhook + secret in failure-level (WARNING+) logs. NOTE: this guards the order path only — + it does NOT cover the invalid-JSON path (_log_invalid_json_body logs the raw body + at WARNING; see TECH_DEBT). Capturing at WARNING also excludes the out-of-scope + DEBUG full-payload log.""" import logging as _logging StubHyperliquidService.reset() StubHyperliquidService.should_fail = True From a6bcd8c3b7823b77246900ef4a2bc7f5c283d770 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:32:17 +0200 Subject: [PATCH 11/14] docs: changelog for order-failure logging + TD-18 (invalid-JSON body leak) Co-Authored-By: Claude Opus 4.8 (1M context) --- CHANGELOG.md | 46 ++++++++++++++++++++++++++++++++++++++++++++++ docs/TECH_DEBT.md | 12 ++++++++++++ 2 files changed, 58 insertions(+) create mode 100644 CHANGELOG.md diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..26fb3c9 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,46 @@ +# 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`. + +### Noted + +- **TD-18** (tech-debt register): the *invalid-JSON* path + (`_log_invalid_json_body`) still logs the raw request body at WARNING, which can + expose `general.secret` on a malformed payload. Pre-existing and out of scope of + the above (which hardened the order path); tracked for a follow-up redaction. diff --git a/docs/TECH_DEBT.md b/docs/TECH_DEBT.md index 4952a20..782a9e5 100644 --- a/docs/TECH_DEBT.md +++ b/docs/TECH_DEBT.md @@ -54,6 +54,18 @@ code before acting. is already timing-safe (`hmac.compare_digest`). Accepted; revisit only if a header path becomes possible. +- **[TD-18] Invalid-JSON path logs the full raw body at WARNING** (`P2`) — + `routes/webhooks.py::_log_invalid_json_body` logs the entire raw request body + (`log.warning("Invalid JSON body req_id=%s body=%s", req_id, body_text)`) to aid + debugging a malformed payload. If that body contains a readable `general.secret` + (the credential travels in the body — see [TD-9]), the secret is emitted at + WARNING+, i.e. at the production log level, not just DEBUG. The order-execution + *failure* path was explicitly hardened against secret leakage + (`test_failure_logs_do_not_leak_secret`), but this invalid-JSON path was not. + *Fix:* redact/skip the body (or log only its length + a structural hint) on the + invalid-JSON path, mirroring [TD-16]'s "don't log the credential" rule. + Pre-existing; surfaced during the order-failure-logging review (2026-06-28). + ### Maintainability - **[TD-10] `routes/webhooks.py` is 751 lines** (`P2`) — From 0fbd9f44da2730f77bb93d628029c47121cc6b6b Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:43:53 +0200 Subject: [PATCH 12/14] fix(security): redact webhook secret from the invalid-JSON debug log (TD-18) _log_invalid_json_body logged the raw request body at WARNING to aid debugging a malformed payload; a body carrying general.secret therefore leaked the credential at the production log level. Route the body through _redact_secrets, which masks any "secret":"..." field and the configured secret value before logging. Co-Authored-By: Claude Opus 4.8 (1M context) --- CHANGELOG.md | 11 ++++---- docs/TECH_DEBT.md | 18 ++++-------- hypertrade/routes/webhooks.py | 35 +++++++++++++++++++++-- tests/test_webhook.py | 53 ++++++++++++++++++++++++++++++++--- 4 files changed, 94 insertions(+), 23 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 26fb3c9..08e4778 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -38,9 +38,10 @@ status codes, DB schema, or pricing/submission logic. Design: `docs/superpowers/specs/2026-06-28-order-failure-logging-design.md` · Plan: `docs/superpowers/plans/2026-06-28-order-failure-logging.md`. -### Noted +### Fixed -- **TD-18** (tech-debt register): the *invalid-JSON* path - (`_log_invalid_json_body`) still logs the raw request body at WARNING, which can - expose `general.secret` on a malformed payload. Pre-existing and out of scope of - the above (which hardened the order path); tracked for a follow-up redaction. +- **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 782a9e5..87dc7c7 100644 --- a/docs/TECH_DEBT.md +++ b/docs/TECH_DEBT.md @@ -54,18 +54,6 @@ code before acting. is already timing-safe (`hmac.compare_digest`). Accepted; revisit only if a header path becomes possible. -- **[TD-18] Invalid-JSON path logs the full raw body at WARNING** (`P2`) — - `routes/webhooks.py::_log_invalid_json_body` logs the entire raw request body - (`log.warning("Invalid JSON body req_id=%s body=%s", req_id, body_text)`) to aid - debugging a malformed payload. If that body contains a readable `general.secret` - (the credential travels in the body — see [TD-9]), the secret is emitted at - WARNING+, i.e. at the production log level, not just DEBUG. The order-execution - *failure* path was explicitly hardened against secret leakage - (`test_failure_logs_do_not_leak_secret`), but this invalid-JSON path was not. - *Fix:* redact/skip the body (or log only its length + a structural hint) on the - invalid-JSON path, mirroring [TD-16]'s "don't log the credential" rule. - Pre-existing; surfaced during the order-failure-logging review (2026-06-28). - ### Maintainability - **[TD-10] `routes/webhooks.py` is 751 lines** (`P2`) — @@ -100,6 +88,12 @@ code before acting. ## Resolved +- 2026-06-28 `56cfa04` — **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/hypertrade/routes/webhooks.py b/hypertrade/routes/webhooks.py index e22976f..07b531a 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 @@ -581,15 +582,45 @@ 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*")[^"]*(")') + + +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 = "" + settings = get_settings() + secret = ( + settings.webhook_secret.get_secret_value() + if getattr(settings, "webhook_secret", None) + else 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_webhook.py b/tests/test_webhook.py index e115a43..6b311db 100644 --- a/tests/test_webhook.py +++ b/tests/test_webhook.py @@ -951,10 +951,9 @@ def test_network_failure_logs_error_and_correlation(monkeypatch, caplog): 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. NOTE: this guards the order path only — - it does NOT cover the invalid-JSON path (_log_invalid_json_body logs the raw body - at WARNING; see TECH_DEBT). Capturing at WARNING also excludes the out-of-scope - DEBUG full-payload log.""" + 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 @@ -972,3 +971,49 @@ def test_failure_logs_do_not_leak_secret(monkeypatch, caplog): 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 From f7b1b7412be65062e04b9581fd8db3c4815490e6 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:44:20 +0200 Subject: [PATCH 13/14] docs: point TD-18 resolved entry at the fix commit 0fbd9f4 Co-Authored-By: Claude Opus 4.8 (1M context) --- docs/TECH_DEBT.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/TECH_DEBT.md b/docs/TECH_DEBT.md index 87dc7c7..6265882 100644 --- a/docs/TECH_DEBT.md +++ b/docs/TECH_DEBT.md @@ -88,7 +88,7 @@ code before acting. ## Resolved -- 2026-06-28 `56cfa04` — **TD-18**: the invalid-JSON debug log now redacts the +- 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 From 17503f405aa3afbc2f07bd9cfde6f9189cb9b305 Mon Sep 17 00:00:00 2001 From: Gianluigi Davassi Date: Sun, 28 Jun 2026 07:48:00 +0200 Subject: [PATCH 14/14] fix(security): guard secret fetch in invalid-JSON log against raising (TD-18 review) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review of the TD-18 fix: get_settings()/get_secret_value() sat outside the try-except, so a settings failure could turn this logging helper into a 500. Wrap the secret fetch (fall back to None — the regex still masks the field) and make the secret-field regex case-insensitive for defense-in-depth. Co-Authored-By: Claude Opus 4.8 (1M context) --- hypertrade/routes/webhooks.py | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/hypertrade/routes/webhooks.py b/hypertrade/routes/webhooks.py index 07b531a..9a6dd88 100644 --- a/hypertrade/routes/webhooks.py +++ b/hypertrade/routes/webhooks.py @@ -582,7 +582,7 @@ 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*")[^"]*(")') +_SECRET_FIELD_RE = re.compile(r'("secret"\s*:\s*")[^"]*(")', re.IGNORECASE) def _redact_secrets(text: str, secret: Optional[str]) -> str: @@ -613,12 +613,17 @@ async def _log_invalid_json_body(request: Request) -> None: body_text = body_bytes.decode("utf-8", errors="replace") except (RuntimeError, UnicodeDecodeError): body_text = "" - settings = get_settings() - secret = ( - settings.webhook_secret.get_secret_value() - if getattr(settings, "webhook_secret", None) - else None - ) + # 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, _redact_secrets(body_text, secret))