From f8213452ea26550bd27512d67269774336ed400f Mon Sep 17 00:00:00 2001 From: 0xallam Date: Sat, 25 Apr 2026 23:43:19 -0700 Subject: [PATCH] =?UTF-8?q?feat(logging):=20close=20audit=20gaps=20?= =?UTF-8?q?=E2=80=94=20SDK=20records,=20proxy=20tracebacks,=20CLI/docker/p?= =?UTF-8?q?osthog?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Five gaps from the post-implementation audit, closed: 1. **SDK logger captured.** The openai-agents SDK uses ``logging.getLogger("openai.agents")`` for its own lifecycle events (Runner.run starts, tool dispatch, model retries, exceptions). Previous setup only attached handlers to the ``strix`` root, so SDK-internal events were dropped. Tracked-roots tuple now covers both, with the same FileHandler/StreamHandler/Filter chain. 2. **Proxy tool exception tracebacks.** Every ``@function_tool`` in ``strix/tools/proxy/tools.py`` returns a JSON error to the LLM via the ``_err(name, exc)`` helper. The tracebacks were silently formatted away — the LLM saw the message, the human reading the log saw nothing. ``_err`` now emits ``logger.exception(...)`` covering all five tools at once. 3. **CLI bootstrap.** ``strix/interface/main.py`` had its module ``logger`` removed by the previous commit and was emitting nothing. Restored, plus log lines for env validation, docker check, LLM warm-up, and image pull (debug for already-present, info for pull, exception for failures). 4. **Docker client.** ``strix/runtime/docker_client.py`` had no logger. Container creation now logs caps + exposed ports at DEBUG and the resulting container id at INFO. 5. **PostHog telemetry.** ``strix/telemetry/posthog.py`` had no logger. Now logs send success/failure at DEBUG, version-detection failures at DEBUG, and disabled-skip at DEBUG (so the log shows when telemetry is off, instead of being silent about it). Co-Authored-By: Claude Opus 4.7 (1M context) --- strix/interface/main.py | 25 +++++++++++++++++++++-- strix/runtime/docker_client.py | 18 ++++++++++++++++- strix/telemetry/logging.py | 37 ++++++++++++++++++++++------------ strix/telemetry/posthog.py | 13 ++++++++++-- strix/tools/proxy/tools.py | 5 +++++ 5 files changed, 80 insertions(+), 18 deletions(-) diff --git a/strix/interface/main.py b/strix/interface/main.py index 8c4409f..488e8be 100644 --- a/strix/interface/main.py +++ b/strix/interface/main.py @@ -42,14 +42,21 @@ from strix.telemetry.tracer import get_global_tracer HOST_GATEWAY_HOSTNAME = "host.docker.internal" +import logging # noqa: E402 + + # Per-scan logging is set up by ``setup_scan_logging`` from inside # ``orchestration.scan.run_strix_scan`` once the scan ``run_dir`` is # known — that's where ``strix.*`` levels and handlers are owned. Pre-scan -# work (``main()``, env validation, image pull) emits at WARNING+ to -# stderr via the SDK / stdlib defaults. +# work (``main()``, env validation, image pull) emits via the module +# logger; once setup_scan_logging runs, those records start landing in +# the file too. + +logger = logging.getLogger(__name__) def validate_environment() -> None: + logger.info("Validating environment") console = Console() missing_required_vars = [] missing_optional_vars = [] @@ -162,14 +169,20 @@ def validate_environment() -> None: padding=(1, 2), ) + logger.error("Missing required env vars: %s", missing_required_vars) console.print("\n") console.print(panel) console.print() sys.exit(1) + logger.info( + "Environment OK (optional missing: %s)", + missing_optional_vars or "none", + ) def check_docker_installed() -> None: if shutil.which("docker") is None: + logger.error("Docker CLI not found in PATH") console = Console() error_text = Text() error_text.append("DOCKER NOT INSTALLED", style="bold red") @@ -188,10 +201,12 @@ def check_docker_installed() -> None: ) console.print("\n", panel, "\n") sys.exit(1) + logger.debug("Docker CLI present") async def warm_up_llm() -> None: console = Console() + logger.info("Warming up LLM connection") try: llm = load_settings().llm @@ -214,8 +229,10 @@ async def warm_up_llm() -> None: response = litellm.completion(**completion_kwargs) validate_llm_response(response) + logger.info("LLM warm-up succeeded for model %s", llm.model) except Exception as e: + logger.exception("LLM warm-up failed") error_text = Text() error_text.append("LLM CONNECTION FAILED", style="bold red") error_text.append("\n\n", style="white") @@ -473,8 +490,10 @@ def pull_docker_image() -> None: image = load_settings().runtime.image if image_exists(client, image): + logger.debug("Docker image already present locally: %s", image) return + logger.info("Pulling docker image: %s", image) console.print() console.print(f"[dim]Pulling image[/] {image}") console.print("[dim yellow]This only happens on first run and may take a few minutes...[/]") @@ -489,6 +508,7 @@ def pull_docker_image() -> None: last_update = process_pull_line(line, layers_info, status, last_update) except DockerException as e: + logger.exception("Failed to pull docker image %s", image) console.print() error_text = Text() error_text.append("FAILED TO PULL IMAGE", style="bold red") @@ -506,6 +526,7 @@ def pull_docker_image() -> None: console.print(panel, "\n") sys.exit(1) + logger.info("Docker image %s ready", image) success_text = Text() success_text.append("Docker image ready", style="#22c55e") console.print(success_text) diff --git a/strix/runtime/docker_client.py b/strix/runtime/docker_client.py index 8970030..f066951 100644 --- a/strix/runtime/docker_client.py +++ b/strix/runtime/docker_client.py @@ -17,6 +17,7 @@ re-merging the parent body. Track upstream for an injection hook. from __future__ import annotations +import logging import uuid from typing import Any @@ -32,6 +33,9 @@ from docker.models.containers import Container # type: ignore[import-untyped, u from docker.utils import parse_repository_tag # type: ignore[import-untyped, unused-ignore] +logger = logging.getLogger(__name__) + + class StrixDockerSandboxClient(DockerSandboxClient): """``DockerSandboxClient`` subclass that injects Strix-required capabilities. @@ -100,4 +104,16 @@ class StrixDockerSandboxClient(DockerSandboxClient): extra_hosts = create_kwargs.setdefault("extra_hosts", {}) extra_hosts["host.docker.internal"] = "host-gateway" - return self.docker_client.containers.create(**create_kwargs) + logger.debug( + "Creating sandbox container: image=%s caps=%s exposed_ports=%s", + image, + cap_add, + list(exposed_ports), + ) + container = self.docker_client.containers.create(**create_kwargs) + logger.info( + "Sandbox container created: id=%s image=%s", + container.short_id if hasattr(container, "short_id") else "?", + image, + ) + return container diff --git a/strix/telemetry/logging.py b/strix/telemetry/logging.py index d7d177d..7900c01 100644 --- a/strix/telemetry/logging.py +++ b/strix/telemetry/logging.py @@ -72,6 +72,15 @@ _NOISY_LIBS: tuple[str, ...] = ( _HANDLER_TAG = "_strix_scan_handler" +# Logger roots that also receive our scan handlers. ``strix`` covers +# everything we own. ``openai.agents`` is the openai-agents SDK's +# canonical logger (verified: ``agents/logger.py``, ``agents/__init__.py``, +# ``agents/tracing/logger.py`` all use this namespace) — without +# attaching here, SDK-internal Runner / tool-dispatch / model-retry +# events would be invisible. +_TRACKED_ROOTS: tuple[str, ...] = ("strix", "openai.agents") + + def setup_scan_logging(run_dir: Path, *, debug: bool | None = None) -> Callable[[], None]: """Attach scan-scoped handlers; return a teardown callable. @@ -114,23 +123,25 @@ def setup_scan_logging(run_dir: Path, *, debug: bool | None = None) -> Callable[ stream_handler.addFilter(context_filter) setattr(stream_handler, _HANDLER_TAG, True) - strix_root = logging.getLogger("strix") - strix_root.setLevel(logging.DEBUG) - strix_root.addHandler(file_handler) - strix_root.addHandler(stream_handler) - # Stop ``strix.*`` records from also bubbling to the python root - # logger's lastResort handler (which would double-print to stderr). - strix_root.propagate = False + tracked_loggers = [logging.getLogger(name) for name in _TRACKED_ROOTS] + for tracked in tracked_loggers: + tracked.setLevel(logging.DEBUG) + tracked.addHandler(file_handler) + tracked.addHandler(stream_handler) + # Stop these records from also bubbling to the python root + # logger's lastResort handler (would double-print to stderr). + tracked.propagate = False for name in _NOISY_LIBS: logging.getLogger(name).setLevel(logging.WARNING) def _teardown() -> None: - for handler in list(strix_root.handlers): - if getattr(handler, _HANDLER_TAG, False): - strix_root.removeHandler(handler) - with contextlib.suppress(Exception): - handler.flush() - handler.close() + for tracked in tracked_loggers: + for handler in list(tracked.handlers): + if getattr(handler, _HANDLER_TAG, False): + tracked.removeHandler(handler) + with contextlib.suppress(Exception): + handler.flush() + handler.close() return _teardown diff --git a/strix/telemetry/posthog.py b/strix/telemetry/posthog.py index 1d6ddce..19656fb 100644 --- a/strix/telemetry/posthog.py +++ b/strix/telemetry/posthog.py @@ -1,4 +1,5 @@ import json +import logging import platform import sys import urllib.request @@ -12,6 +13,9 @@ from strix.config import load_settings if TYPE_CHECKING: from strix.telemetry.tracer import Tracer + +logger = logging.getLogger(__name__) + _POSTHOG_PUBLIC_API_KEY = "phc_7rO3XRuNT5sgSKAl6HDIrWdSGh1COzxw0vxVIAR6vVZ" _POSTHOG_HOST = "https://us.i.posthog.com" @@ -41,11 +45,13 @@ def _get_version() -> str: return version("strix-agent") except Exception: # noqa: BLE001 + logger.debug("strix-agent version lookup failed", exc_info=True) return "unknown" def _send(event: str, properties: dict[str, Any]) -> None: if not _is_enabled(): + logger.debug("posthog disabled; skipping event %s", event) return try: payload = { @@ -61,8 +67,11 @@ def _send(event: str, properties: dict[str, Any]) -> None: ) with urllib.request.urlopen(req, timeout=10): # noqa: S310 # nosec B310 pass - except Exception: # noqa: BLE001, S110 - pass # nosec B110 + except Exception: # noqa: BLE001 + # Telemetry must never disrupt a scan; log + swallow. + logger.debug("posthog send failed for event %s", event, exc_info=True) + else: + logger.debug("posthog event sent: %s", event) def _base_props() -> dict[str, Any]: diff --git a/strix/tools/proxy/tools.py b/strix/tools/proxy/tools.py index e1c3d42..52a25ef 100644 --- a/strix/tools/proxy/tools.py +++ b/strix/tools/proxy/tools.py @@ -14,6 +14,7 @@ from __future__ import annotations import dataclasses import json +import logging import re from dataclasses import is_dataclass from datetime import datetime @@ -24,6 +25,9 @@ from agents import RunContextWrapper, function_tool from strix.tools.proxy import _calls +logger = logging.getLogger(__name__) + + if TYPE_CHECKING: from caido_sdk_client import Client @@ -79,6 +83,7 @@ def _no_client() -> str: def _err(name: str, exc: Exception) -> str: + logger.exception("%s failed", name) return json.dumps( {"success": False, "error": f"{name} failed: {exc}"}, ensure_ascii=False,