From cba79b1ba0fa003a98967b62f81cf3ff6e2425c5 Mon Sep 17 00:00:00 2001 From: Elmehdi Aitbrahim Date: Thu, 6 Aug 2026 11:32:01 -0400 Subject: [PATCH] fix(telemetry): log an unreachable venue as a warning, not an ERROR traceback A 35-minute offline window on 2026-08-06 (laptop asleep, DNS not up after wake) wrote 124 ERROR records with full 20-frame tracebacks into keel-live.log: the TUI polls the live balance every 30s, and every failed poll was logged twice -- once by `cb_client.get_accounts`, then again by `executor._fetch_available_quote`, which re-logs the exception the client already logged and re-raised. Nothing was broken. The venue was unreachable, every caller already fails soft, and the condition cleared by itself. The cost was that a real `401 Unauthorized` in the same log is one line among 124 -- `grep ERROR` told the operator nothing. Add `telemetry.log_venue_failure`, for any call that crosses the network to a venue. It picks severity by what the failure actually cost: - unreachable, no cycle bound (a dashboard balance refresh) -> WARNING, one line, `unreachable=true` plus a truncated `error` summary - unreachable, inside a trade cycle -> ERROR: rail 13 fails closed on a missing balance, so an order did not go out. Still no traceback, the cause is known - anything else (auth, malformed, a bug) -> ERROR with the full traceback, byte-for-byte what `log_exception` emitted before Unreachability is matched on exception type NAME over the __cause__ chain, so `keel-core` needs no `requests`/`urllib3` dependency to classify their exceptions and the check holds for any broker's HTTP stack. Verified against a real `requests` failure: ConnectionError -> MaxRetryError -> NameResolutionError -> gaierror. `SSLError` is deliberately excluded -- a failed handshake can mean interception, which an operator must see. Control flow is untouched: `get_accounts` still raises, and `_fetch_available_quote` still returns None so rail 13 fails closed. Replaying the 124 recorded failures through the classifier leaves 2 at ERROR -- exactly the 401. Co-Authored-By: Claude Opus 5 (1M context) --- keel/data/cb_client.py | 12 ++- keel/execution/executor.py | 11 ++- packages/keel-core/keel_core/telemetry.py | 84 ++++++++++++++++ tests/data/test_cb_client.py | 62 ++++++++++++ tests/execution/test_executor.py | 52 ++++++++++ tests/test_telemetry.py | 111 ++++++++++++++++++++++ 6 files changed, 327 insertions(+), 5 deletions(-) diff --git a/keel/data/cb_client.py b/keel/data/cb_client.py index 1f671996..f23679df 100644 --- a/keel/data/cb_client.py +++ b/keel/data/cb_client.py @@ -26,7 +26,7 @@ from decimal import Decimal from typing import Any, Protocol -from keel_core.telemetry import log_exception +from keel_core.telemetry import log_exception, log_venue_failure from keel.types import Candle, Granularity, Side @@ -193,11 +193,17 @@ def list_products(self, product_type: str = "SPOT") -> list[dict]: return out def get_accounts(self) -> list[dict]: - """Return authenticated account balances, keyed by currency.""" + """Return authenticated account balances, keyed by currency. + + Logged through `log_venue_failure`, not `log_exception`: this is polled on a cadence by + the TUI's balance refresh, so an unreachable venue would otherwise write a full + traceback every 30s for as long as the machine is offline. Always re-raises, unchanged + -- severity is a logging concern and rail 13 fails closed on the exception itself. + """ try: response = self._transport.get_accounts() except Exception: - log_exception(logger, "cb_client.accounts_fetch_failed") + log_venue_failure(logger, "cb_client.accounts_fetch_failed") raise raw_accounts = _field(response, "accounts", []) or [] accounts = [] diff --git a/keel/execution/executor.py b/keel/execution/executor.py index a5e90008..d590f01f 100644 --- a/keel/execution/executor.py +++ b/keel/execution/executor.py @@ -64,7 +64,7 @@ from typing import Any, Literal from keel_core.products import quote_currency_of -from keel_core.telemetry import log_event, log_exception +from keel_core.telemetry import log_event, log_exception, log_venue_failure from keel.config import Config from keel.data.repository import Repository @@ -281,7 +281,14 @@ def _fetch_available_quote(broker: Any, quote_currency: str | None) -> Decimal | try: accounts = broker.get_accounts() except Exception: - log_exception(logger, "executor.quote_fetch_failed", quote_currency=quote_currency) + # `log_venue_failure`, not `log_exception`: an unreachable venue outside a trade cycle + # is a dashboard balance refresh on a sleeping laptop, and this line is the SECOND + # record for that one failure (`cb_client.get_accounts` logs it first) -- two full + # tracebacks per poll, every 30s, for as long as the machine is offline. Inside a cycle + # it escalates back to ERROR on its own: there it means rail 13 failed closed and an + # order did not go out. Kept as its own event rather than dropped because it carries + # `quote_currency`, and because a non-Coinbase broker may not log anything itself. + log_venue_failure(logger, "executor.quote_fetch_failed", quote_currency=quote_currency) return None for account in accounts or []: diff --git a/packages/keel-core/keel_core/telemetry.py b/packages/keel-core/keel_core/telemetry.py index 3dbec06d..888699a7 100644 --- a/packages/keel-core/keel_core/telemetry.py +++ b/packages/keel-core/keel_core/telemetry.py @@ -20,6 +20,7 @@ import json import logging +import sys import uuid from contextvars import ContextVar, Token from typing import Any @@ -40,6 +41,34 @@ # these names is renamed (not dropped, not allowed to overwrite) -- see module docstring. _RESERVED = frozenset({"ts", "level", "logger", "event", "cycle_id", "exc"}) +# Exception type NAMES that mean "the venue was unreachable" rather than "something is wrong" -- +# see `is_venue_unreachable` for why this is a name match and not an `isinstance` check. Covers +# the builtin socket errors plus the `requests`/`urllib3` wrappers a broker's HTTP stack raises. +_UNREACHABLE_EXC_NAMES = frozenset( + { + "ConnectionError", # builtin, and requests.exceptions.ConnectionError + "ConnectionResetError", + "ConnectionRefusedError", + "ConnectionAbortedError", + "TimeoutError", # builtin, and requests.exceptions.Timeout's socket cause + "Timeout", + "ConnectTimeout", + "ConnectTimeoutError", + "ReadTimeout", + "ReadTimeoutError", + "ProxyError", + "MaxRetryError", + "NewConnectionError", + "NameResolutionError", + "gaierror", # socket.gaierror -- DNS not up yet after a wake + } +) + +# Cap on the one-line `error` summary that replaces a traceback on the unreachable path. Long +# enough to keep the host and the underlying cause `requests` nests into its message, short +# enough that the event stays one readable line. +_ERROR_SUMMARY_MAX_CHARS = 200 + def new_cycle_id() -> str: """Generate a fresh correlation id for one engine cycle.""" @@ -114,6 +143,61 @@ def log_exception(logger: logging.Logger, event: str, /, **fields: Any) -> None: logger.log(logging.ERROR, event, exc_info=True, extra={_FIELDS_ATTR: fields}) +def is_venue_unreachable(exc: BaseException | None) -> bool: + """True when `exc` means "could not reach the venue", not "something is wrong". + + Matched on the exception type's NAME, walked over the `__cause__`/`__context__` chain, + because `requests` wraps the underlying socket/DNS error and the outermost type is not + always the signal. Matching by name (rather than importing `requests`/`urllib3` and using + `isinstance`) keeps `keel-core` free of an HTTP dependency it otherwise does not need, and + keeps the classification working for any broker adapter's HTTP stack. + + `SSLError` is deliberately absent: a failed TLS handshake can mean interception or a bad + certificate, which an operator must see at ERROR rather than have filed as "wifi is down". + """ + seen: set[int] = set() + while exc is not None and id(exc) not in seen: + seen.add(id(exc)) + if type(exc).__name__ in _UNREACHABLE_EXC_NAMES: + return True + exc = exc.__cause__ or exc.__context__ + return False + + +def log_venue_failure(logger: logging.Logger, event: str, /, **fields: Any) -> bool: + """Emit a broker-call failure at a severity that matches what it actually cost. Returns + whether the active exception was classified unreachable. + + Use inside an `except` block, in place of `log_exception`, for any call that crosses the + network to a venue. + + - **Unreachable, outside a trade cycle** (a dashboard's balance refresh while the laptop is + asleep) -> WARNING, one line, no traceback. Nothing was lost; the caller already fails + soft. This is the case that motivated the helper: a 35-minute offline window on + 2026-08-06 wrote 60 twenty-frame ERROR tracebacks through `get_accounts`, around a single + real `401 Unauthorized` that no operator would ever have spotted in the noise. + - **Unreachable, inside a trade cycle** (`cycle_id` bound) -> ERROR. Here it did cost + something: rail 13 fails closed on a missing balance, so an order did not go out. Still + no traceback -- the cause is known and the frames say nothing the summary does not. + - **Anything else** (auth, malformed response, a bug) -> ERROR with the full traceback, + byte-for-byte what `log_exception` would have emitted. + + The unreachable paths add `unreachable=True` and a truncated `error` summary. Caller fields + win over both, on the same principle as `log_event`: a logging call must never raise. + """ + exc = sys.exc_info()[1] + if not is_venue_unreachable(exc): + log_exception(logger, event, **fields) + return False + + level = logging.ERROR if _cycle_id.get() is not None else logging.WARNING + summary = f"{type(exc).__name__}: {exc}" + if len(summary) > _ERROR_SUMMARY_MAX_CHARS: + summary = summary[:_ERROR_SUMMARY_MAX_CHARS] + "..." + log_event(logger, level, event, **{"unreachable": True, "error": summary, **fields}) + return True + + class JsonFormatter(logging.Formatter): """Render a LogRecord as a single-line JSON object.""" diff --git a/tests/data/test_cb_client.py b/tests/data/test_cb_client.py index ec06ba5f..0f6d9bd6 100644 --- a/tests/data/test_cb_client.py +++ b/tests/data/test_cb_client.py @@ -8,10 +8,14 @@ from __future__ import annotations import json +import logging from decimal import Decimal from pathlib import Path from typing import Any +import pytest +from keel_core import telemetry + from keel.data.cb_client import CoinbaseClient from keel.types import Candle, Granularity, Side @@ -532,3 +536,61 @@ def test_cancel_order_returns_false_on_an_empty_result_set(): client = CoinbaseClient(FakeTransport(cancel={"results": []})) assert client.cancel_order("abc") is False + + +# --- get_accounts failure severity -------------------------------------------------------- +# +# `get_accounts` is polled every 30s by the TUI's balance refresh. An offline laptop must not +# write a 20-frame ERROR traceback per poll -- that is what buried a real `401 Unauthorized` +# among 60 connection failures on 2026-08-06. It must still RAISE either way: severity is a +# logging concern, and callers (rail 13 among them) depend on the exception. + + +class _RaisingTransport: + """A transport whose `get_accounts` raises whatever it was handed.""" + + def __init__(self, exc: BaseException) -> None: + self._exc = exc + + def get_accounts(self, **kwargs: Any) -> dict: + raise self._exc + + +def _accounts_failure_payload(caplog, exc: BaseException) -> dict: + formatter = telemetry.JsonFormatter() + client = CoinbaseClient(_RaisingTransport(exc)) + with caplog.at_level(logging.DEBUG, logger="keel.data.cb_client"): + with pytest.raises(type(exc)): + client.get_accounts() + records = [r for r in caplog.records if r.getMessage() == "cb_client.accounts_fetch_failed"] + assert len(records) == 1 + return json.loads(formatter.format(records[0])) + + +def test_get_accounts_logs_an_unreachable_venue_as_a_warning(caplog) -> None: + exc = type("ConnectionError", (Exception,), {})("api.coinbase.com unreachable") + + payload = _accounts_failure_payload(caplog, exc) + + assert payload["level"] == "WARNING" + assert payload["unreachable"] is True + assert "exc" not in payload + + +def test_get_accounts_still_logs_a_401_as_an_error_with_its_traceback(caplog) -> None: + exc = type("HTTPError", (Exception,), {})("401 Client Error: Unauthorized") + + payload = _accounts_failure_payload(caplog, exc) + + assert payload["level"] == "ERROR" + assert "Traceback" in payload["exc"] + + +def test_get_accounts_still_raises_when_the_venue_is_unreachable(caplog) -> None: + """Severity changed; control flow must not. Rail 13 fails closed on this exception.""" + boom = type("ConnectionError", (Exception,), {})("unreachable") + client = CoinbaseClient(_RaisingTransport(boom)) + + with caplog.at_level(logging.DEBUG): + with pytest.raises(type(boom)): + client.get_accounts() diff --git a/tests/execution/test_executor.py b/tests/execution/test_executor.py index e131b2da..42635e3e 100644 --- a/tests/execution/test_executor.py +++ b/tests/execution/test_executor.py @@ -1520,3 +1520,55 @@ def test_no_account_at_all_for_the_required_currency_fails_closed(repo): assert result.placed is False assert result.preview is None assert any("unknown/unavailable" in v for v in result.vetoed_by) + + +# --- _fetch_available_quote failure severity ---------------------------------------------- +# +# The second half of the 2026-08-06 log-noise pair: every `get_accounts` failure was logged +# twice at ERROR with a full traceback -- once by `cb_client`, then again here. Rail 13 still +# fails closed (`None`) either way; only the severity of the record changes. + + +class _UnreachableBroker: + """A broker whose `get_accounts` raises as an offline HTTP stack does.""" + + def __init__(self, exc: BaseException) -> None: + self._exc = exc + + def get_accounts(self) -> list[dict]: + raise self._exc + + +def _quote_failure_payload(caplog, exc: BaseException) -> tuple[Decimal | None, dict]: + from keel_core import telemetry + + from keel.execution.executor import _fetch_available_quote + + formatter = telemetry.JsonFormatter() + with caplog.at_level(logging.DEBUG, logger="keel.execution.executor"): + result = _fetch_available_quote(_UnreachableBroker(exc), "USD") + records = [r for r in caplog.records if r.getMessage() == "executor.quote_fetch_failed"] + assert len(records) == 1 + return result, json.loads(formatter.format(records[0])) + + +def test_quote_fetch_logs_an_unreachable_venue_as_a_warning(caplog) -> None: + exc = type("ConnectionError", (Exception,), {})("api.coinbase.com unreachable") + + result, payload = _quote_failure_payload(caplog, exc) + + assert result is None # rail 13 still fails closed + assert payload["level"] == "WARNING" + assert payload["unreachable"] is True + assert "exc" not in payload + assert payload["quote_currency"] == "USD" + + +def test_quote_fetch_keeps_a_real_broker_error_at_error_with_its_traceback(caplog) -> None: + exc = type("HTTPError", (Exception,), {})("401 Client Error: Unauthorized") + + result, payload = _quote_failure_payload(caplog, exc) + + assert result is None + assert payload["level"] == "ERROR" + assert "Traceback" in payload["exc"] diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index 49910fa1..89b37c4c 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -265,3 +265,114 @@ def test_unbind_venue_restores_the_outer_venue() -> None: finally: telemetry.unbind_venue(outer) assert telemetry.current_venue() is None + + +# --- log_venue_failure -------------------------------------------------------------------- +# +# A venue that cannot be reached (laptop asleep, wifi down, DNS not up yet after wake) is an +# expected condition already handled by every caller, not a defect. Logging it at ERROR with a +# 20-frame traceback on every poll buries the failures that DO mean something -- one offline +# window on 2026-08-06 wrote 60 tracebacks around a single real `401 Unauthorized`. + + +# Stand-ins for `requests.exceptions.*`. `log_venue_failure` matches on `type(exc).__name__` +# precisely so `keel-core` need not depend on `requests`/`urllib3` to classify their exceptions -- +# which means a class of the same name is a faithful fake here. +ConnectionErrorLike = type("ConnectionError", (Exception,), {}) +ConnectTimeoutLike = type("ConnectTimeout", (Exception,), {}) +HTTPErrorLike = type("HTTPError", (Exception,), {}) + + +def _capture_raising(caplog, exc: BaseException, **fields) -> dict: + """Run `log_venue_failure` inside a real `except` block and return the JSON payload.""" + formatter = telemetry.JsonFormatter() + with caplog.at_level(logging.DEBUG, logger="keel.test"): + try: + raise exc + except BaseException: + telemetry.log_venue_failure( + logging.getLogger("keel.test"), "cb_client.accounts_fetch_failed", **fields + ) + assert len(caplog.records) == 1 + return json.loads(formatter.format(caplog.records[0])) + + +def test_unreachable_venue_is_a_warning_not_an_error(caplog) -> None: + payload = _capture_raising(caplog, ConnectionErrorLike("api.coinbase.com unreachable")) + + assert payload["level"] == "WARNING" + assert payload["event"] == "cb_client.accounts_fetch_failed" + assert payload["unreachable"] is True + + +def test_unreachable_venue_carries_a_summary_instead_of_a_traceback(caplog) -> None: + """The operator still learns what happened -- in one line, not twenty frames.""" + payload = _capture_raising(caplog, ConnectionErrorLike("api.coinbase.com unreachable")) + + assert "exc" not in payload + assert payload["error"] == "ConnectionError: api.coinbase.com unreachable" + + +def test_a_long_unreachable_message_is_truncated_to_stay_one_line(caplog) -> None: + payload = _capture_raising(caplog, ConnectionErrorLike("x" * 5_000)) + + assert len(payload["error"]) <= 220 + assert payload["error"].endswith("...") + + +def test_a_timeout_is_also_unreachable(caplog) -> None: + payload = _capture_raising(caplog, ConnectTimeoutLike("timed out")) + + assert payload["level"] == "WARNING" + assert payload["unreachable"] is True + + +def test_a_real_error_keeps_its_traceback_at_error(caplog) -> None: + """The 401 that the 60 tracebacks were burying. This must NOT be downgraded.""" + payload = _capture_raising(caplog, HTTPErrorLike("401 Client Error: Unauthorized")) + + assert payload["level"] == "ERROR" + assert "exc" in payload + assert "Traceback" in payload["exc"] + assert "unreachable" not in payload + + +def test_unreachable_is_detected_through_the_cause_chain(caplog) -> None: + """`requests` wraps the socket error, so the outermost type is not always the signal.""" + cause = ConnectionErrorLike("failed to resolve api.coinbase.com") + wrapper = RuntimeError("balance read failed") + wrapper.__cause__ = cause + + payload = _capture_raising(caplog, wrapper) + + assert payload["level"] == "WARNING" + assert payload["unreachable"] is True + + +def test_unreachable_during_a_trade_cycle_stays_an_error(caplog) -> None: + """Outside a cycle this is a dashboard refresh missing a balance -- cosmetic. INSIDE one it + blocked real work (rail 13 fails closed and the order does not go out), so it keeps ERROR.""" + token = telemetry.bind_cycle("cycle-abc") + try: + payload = _capture_raising(caplog, ConnectionErrorLike("unreachable")) + finally: + telemetry.unbind_cycle(token) + + assert payload["level"] == "ERROR" + assert payload["unreachable"] is True + assert "exc" not in payload # still no traceback -- the cause is known and uninteresting + + +def test_caller_fields_survive_on_the_warning_path(caplog) -> None: + payload = _capture_raising( + caplog, ConnectionErrorLike("unreachable"), quote_currency="USD" + ) + + assert payload["quote_currency"] == "USD" + + +def test_a_caller_field_wins_over_the_generated_one(caplog) -> None: + """A logging call must never raise on a duplicate keyword.""" + payload = _capture_raising(caplog, ConnectionErrorLike("unreachable"), error="mine") + + assert payload["error"] == "mine"