diff --git a/strix/agents/factory.py b/strix/agents/factory.py index 1cd09a4..57b46f6 100644 --- a/strix/agents/factory.py +++ b/strix/agents/factory.py @@ -166,6 +166,16 @@ def build_strix_agent( tools = [*_BASE_TOOLS, agent_finish] stop_at = ("agent_finish",) + logger.info( + "Built %s agent '%s' (skills=%d, tools=%d, scan_mode=%s, whitebox=%s)", + "root" if is_root else "child", + name, + len(skills or []), + len(tools), + scan_mode, + is_whitebox, + ) + return SandboxAgent( name=name, instructions=instructions, diff --git a/strix/agents/prompt.py b/strix/agents/prompt.py index bb0a048..6b935b5 100644 --- a/strix/agents/prompt.py +++ b/strix/agents/prompt.py @@ -122,4 +122,12 @@ def render_system_prompt( logger.exception("render_system_prompt failed; returning empty prompt") return "" else: + logger.debug( + "render_system_prompt: scan_mode=%s root=%s whitebox=%s skills=%d prompt_len=%d", + scan_mode, + is_root, + is_whitebox, + len(skill_content), + len(rendered), + ) return str(rendered) diff --git a/strix/config/loader.py b/strix/config/loader.py index 5349e64..3ed2e2a 100644 --- a/strix/config/loader.py +++ b/strix/config/loader.py @@ -9,6 +9,7 @@ from __future__ import annotations import contextlib import json +import logging import os from pathlib import Path from typing import TYPE_CHECKING, Any @@ -22,6 +23,9 @@ if TYPE_CHECKING: from pydantic.fields import FieldInfo +logger = logging.getLogger(__name__) + + _DEFAULT_PATH: Path = Path.home() / ".strix" / "cli-config.json" _override: Path | None = None _cached: Settings | None = None @@ -34,8 +38,15 @@ def load_settings() -> Settings: """ global _cached # noqa: PLW0603 if _cached is None: - init_kwargs: dict[str, Any] = _read_json_overrides(_override or _DEFAULT_PATH) + source_path = _override or _DEFAULT_PATH + init_kwargs: dict[str, Any] = _read_json_overrides(source_path) _cached = Settings(**init_kwargs) + logger.debug( + "load_settings: resolved (override=%s, file_used=%s, json_keys=%d)", + _override is not None, + source_path.exists(), + sum(len(v) for v in init_kwargs.values()), + ) return _cached @@ -44,6 +55,7 @@ def apply_config_override(path: Path) -> None: global _override, _cached # noqa: PLW0603 _override = path _cached = None + logger.info("config override applied: %s", path) def persist_current() -> None: diff --git a/strix/interface/cli.py b/strix/interface/cli.py index bfc3e13..d382a80 100644 --- a/strix/interface/cli.py +++ b/strix/interface/cli.py @@ -1,5 +1,6 @@ import atexit import contextlib +import logging import os import signal import sys @@ -24,6 +25,9 @@ from .utils import ( ) +logger = logging.getLogger(__name__) + + def _resolve_sandbox_image() -> str: image = load_settings().runtime.image if not image: @@ -182,6 +186,12 @@ async def run_cli(args: Any) -> None: # noqa: PLR0915 update_thread.start() try: + logger.info( + "CLI launching scan: run_name=%s targets=%d interactive=%s", + args.run_name, + len(scan_config.get("targets") or []), + bool(getattr(args, "interactive", False)), + ) await run_strix_scan( scan_config=scan_config, scan_id=args.run_name, diff --git a/strix/interface/main.py b/strix/interface/main.py index cc562bf..8c4409f 100644 --- a/strix/interface/main.py +++ b/strix/interface/main.py @@ -5,7 +5,6 @@ Strix Agent Interface import argparse import asyncio -import logging import shutil import sys from pathlib import Path @@ -43,7 +42,11 @@ from strix.telemetry.tracer import get_global_tracer HOST_GATEWAY_HOSTNAME = "host.docker.internal" -logging.getLogger().setLevel(logging.ERROR) +# 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. def validate_environment() -> None: diff --git a/strix/interface/tui.py b/strix/interface/tui.py index 512cffb..1e1d9af 100644 --- a/strix/interface/tui.py +++ b/strix/interface/tui.py @@ -959,9 +959,7 @@ class StrixTUIApp(App): # type: ignore[misc] return True except (KeyError, AttributeError, ValueError) as e: - import logging - - logging.warning(f"Failed to update agent node label: {e}") + logger.warning(f"Failed to update agent node label: {e}") return False @@ -1422,7 +1420,7 @@ class StrixTUIApp(App): # type: ignore[misc] ) except (KeyboardInterrupt, asyncio.CancelledError): - logging.info("Scan interrupted by user") + logger.info("Scan interrupted by user") except (ConnectionError, TimeoutError): logging.exception("Network error during scan") except RuntimeError: @@ -1503,9 +1501,7 @@ class StrixTUIApp(App): # type: ignore[misc] self._reorganize_orphaned_agents(agent_id) except (AttributeError, ValueError, RuntimeError) as e: - import logging - - logging.warning(f"Failed to add agent node {agent_id}: {e}") + logger.warning(f"Failed to add agent node {agent_id}: {e}") def _expand_new_agent_nodes(self) -> None: if len(self.screen_stack) > 1 or self.show_splash: @@ -1525,7 +1521,7 @@ class StrixTUIApp(App): # type: ignore[misc] agents_tree = self.query_one("#agents_tree", Tree) self._expand_node_recursively(agents_tree.root) except (ValueError, Exception): - logging.debug("Tree not ready for expanding nodes") + logger.debug("Tree not ready for expanding nodes") def _expand_node_recursively(self, node: TreeNode) -> None: if not node.is_expanded: @@ -1717,6 +1713,11 @@ class StrixTUIApp(App): # type: ignore[misc] if not self.selected_agent_id: return + logger.info( + "TUI: user message -> %s (len=%d)", + self.selected_agent_id, + len(message), + ) if self.tracer: self.tracer.log_chat_message( content=message, @@ -1758,7 +1759,7 @@ class StrixTUIApp(App): # type: ignore[misc] if isinstance(agent_name, str): return agent_name except (KeyError, AttributeError) as e: - logging.warning(f"Could not retrieve agent name for {agent_id}: {e}") + logger.warning(f"Could not retrieve agent name for {agent_id}: {e}") return "Unknown Agent" def action_toggle_help(self) -> None: @@ -1836,9 +1837,7 @@ class StrixTUIApp(App): # type: ignore[misc] return agent_name, True except (KeyError, AttributeError, ValueError) as e: - import logging - - logging.warning(f"Failed to gather agent events: {e}") + logger.warning(f"Failed to gather agent events: {e}") return agent_name, False @@ -1849,8 +1848,9 @@ class StrixTUIApp(App): # type: ignore[misc] # The hard ``cancel_descendants`` path remains for KeyboardInterrupt # in entry.py where graceful isn't possible. if self._scan_loop is None or self._scan_loop.is_closed(): - logging.warning("No active scan loop; cannot stop agent %s", agent_id) + logger.warning("No active scan loop; cannot stop agent %s", agent_id) return + logger.info("TUI: graceful stop requested for %s (cascade)", agent_id) asyncio.run_coroutine_threadsafe( self.bus.cancel_descendants_graceful(agent_id), self._scan_loop, diff --git a/strix/llm/anthropic_cache_wrapper.py b/strix/llm/anthropic_cache_wrapper.py index 6c7d76c..5a68cf1 100644 --- a/strix/llm/anthropic_cache_wrapper.py +++ b/strix/llm/anthropic_cache_wrapper.py @@ -8,6 +8,7 @@ delegating to the parent. from __future__ import annotations +import logging from collections.abc import AsyncIterator from typing import Any @@ -20,6 +21,9 @@ from agents.models.interface import ModelTracing from agents.tool import Tool +logger = logging.getLogger(__name__) + + class AnthropicCachingLitellmModel(LitellmModel): """LitellmModel that injects ``cache_control: {"type": "ephemeral"}`` on the system message for Anthropic models. Other providers pass through unchanged. @@ -45,6 +49,7 @@ class AnthropicCachingLitellmModel(LitellmModel): if not self._is_anthropic(): return items out: list[TResponseInputItem] = [] + patched_count = 0 for item in items: if isinstance(item, dict) and item.get("role") == "system": content = item.get("content") @@ -60,8 +65,15 @@ class AnthropicCachingLitellmModel(LitellmModel): ], } out.append(new_item) # type: ignore[arg-type] + patched_count += 1 continue out.append(item) + if patched_count: + logger.debug( + "Anthropic cache_control injected on %d system message(s) for %s", + patched_count, + self.model, + ) return out async def get_response( diff --git a/strix/llm/multi_provider_setup.py b/strix/llm/multi_provider_setup.py index 4dd1167..1e2e096 100644 --- a/strix/llm/multi_provider_setup.py +++ b/strix/llm/multi_provider_setup.py @@ -10,6 +10,8 @@ through to the SDK's built-in litellm routing. from __future__ import annotations +import logging + from agents.exceptions import UserError from agents.models.interface import Model, ModelProvider from agents.models.multi_provider import MultiProvider, MultiProviderMap @@ -17,6 +19,9 @@ from agents.models.multi_provider import MultiProvider, MultiProviderMap from strix.llm.anthropic_cache_wrapper import AnthropicCachingLitellmModel +logger = logging.getLogger(__name__) + + class _AnthropicCachingProvider(ModelProvider): """Routes ``anthropic/`` aliases through :class:`AnthropicCachingLitellmModel`. @@ -33,6 +38,7 @@ class _AnthropicCachingProvider(ModelProvider): "Anthropic provider requires a non-empty model name (e.g. 'claude-sonnet-4-6').", ) full = model_name if model_name.startswith("anthropic/") else f"anthropic/{model_name}" + logger.debug("Anthropic provider: building cached model for %s", full) return AnthropicCachingLitellmModel(model=full) @@ -45,4 +51,5 @@ def build_multi_provider() -> MultiProvider: """ pmap = MultiProviderMap() # type: ignore[no-untyped-call] pmap.add_provider("anthropic", _AnthropicCachingProvider()) + logger.debug("MultiProvider built with anthropic/ caching route") return MultiProvider(provider_map=pmap) diff --git a/strix/orchestration/bus.py b/strix/orchestration/bus.py index 6a27dfb..50ea156 100644 --- a/strix/orchestration/bus.py +++ b/strix/orchestration/bus.py @@ -9,6 +9,7 @@ from __future__ import annotations import asyncio import contextlib +import logging from dataclasses import dataclass, field from typing import TYPE_CHECKING, Any @@ -19,6 +20,9 @@ if TYPE_CHECKING: from agents.result import RunResultStreaming +logger = logging.getLogger(__name__) + + @dataclass class AgentMessageBus: """Shared state for multi-agent orchestration. @@ -78,6 +82,7 @@ class AgentMessageBus: "warned_85": False, "warned_final": False, } + logger.info("bus.register %s (%s) parent=%s", agent_id, name, parent_id or "-") async def send(self, target: str, msg: dict[str, Any]) -> None: """Append a message to ``target``'s inbox. @@ -87,13 +92,30 @@ class AgentMessageBus: """ async with self._lock: if target not in self.statuses: + logger.debug("bus.send dropped (unknown target=%s)", target) return if self.statuses[target] in ("completed", "crashed", "stopped"): + logger.debug( + "bus.send dropped (target=%s status=%s)", + target, + self.statuses[target], + ) return self.inboxes.setdefault(target, []).append(msg) event = self._events.get(target) if event is not None: event.set() + sender = msg.get("from", "?") + msg_type = msg.get("type", "message") + content = str(msg.get("content", "")) + logger.debug( + "bus.send %s -> %s (type=%s len=%d): %s", + sender, + target, + msg_type, + len(content), + content[:200], + ) async def wait_for_message(self, agent_id: str) -> None: """Block until ``agent_id``'s inbox has at least one pending message. @@ -137,7 +159,9 @@ class AgentMessageBus: async with self._lock: msgs = self.inboxes.get(agent_id, []) self.inboxes[agent_id] = [] - return msgs + if msgs: + logger.debug("bus.drain %s -> %d message(s)", agent_id, len(msgs)) + return msgs async def record_usage(self, agent_id: str, usage: Any) -> None: """Accumulate per-call usage from RunHooks.on_llm_end. @@ -183,6 +207,7 @@ class AgentMessageBus: self.streams.pop(agent_id, None) self.stopping.discard(agent_id) self._events.pop(agent_id, None) + logger.info("bus.finalize %s status=%s", agent_id, status) async def park(self, agent_id: str) -> None: """Mark an agent as ``waiting`` without finalizing. @@ -196,6 +221,7 @@ class AgentMessageBus: async with self._lock: if agent_id in self.statuses: self.statuses[agent_id] = "waiting" + logger.debug("bus.park %s", agent_id) async def mark_llm_failed(self, agent_id: str) -> None: """Mark an agent as ``llm_failed`` after retries exhausted. @@ -209,6 +235,7 @@ class AgentMessageBus: async with self._lock: if agent_id in self.statuses: self.statuses[agent_id] = "llm_failed" + logger.warning("bus.mark_llm_failed %s — awaiting user resume", agent_id) @contextlib.asynccontextmanager async def attach_stream( @@ -242,8 +269,10 @@ class AgentMessageBus: async with self._lock: streamed = self.streams.get(agent_id) if streamed is None: + logger.debug("bus.request_interrupt %s — no active stream", agent_id) return False streamed.cancel(mode=mode) # type: ignore[arg-type] # mode is a Literal + logger.info("bus.request_interrupt %s mode=%s", agent_id, mode) return True async def total_stats(self) -> dict[str, Any]: @@ -274,6 +303,11 @@ class AgentMessageBus: order.append(aid) queue.extend(child for child, parent in self.parent_of.items() if parent == aid) tasks_to_cancel = [self.tasks[a] for a in reversed(order) if a in self.tasks] + logger.info( + "bus.cancel_descendants %s (hard, %d task(s))", + root_agent_id, + len(tasks_to_cancel), + ) for task in tasks_to_cancel: if not task.done(): task.cancel() @@ -303,5 +337,11 @@ class AgentMessageBus: streams_to_cancel = [ (aid, self.streams[aid]) for aid in reversed(order) if aid in self.streams ] + logger.info( + "bus.cancel_descendants_graceful %s (%d active stream(s), %d total)", + root_agent_id, + len(streams_to_cancel), + len(order), + ) for _aid, streamed in streams_to_cancel: streamed.cancel(mode="after_turn") diff --git a/strix/orchestration/filter.py b/strix/orchestration/filter.py index a219d8b..88b73d1 100644 --- a/strix/orchestration/filter.py +++ b/strix/orchestration/filter.py @@ -56,6 +56,11 @@ async def inject_messages_filter(data: CallModelData) -> ModelInputData: "content": _format_inter_agent_message(bus, msg), }, ) + logger.debug( + "inject_messages_filter: appended %d message(s) to input for %s", + len(pending), + agent_id, + ) return ModelInputData( input=new_input, instructions=data.model_data.instructions, diff --git a/strix/orchestration/hooks.py b/strix/orchestration/hooks.py index 4f83339..6eea93b 100644 --- a/strix/orchestration/hooks.py +++ b/strix/orchestration/hooks.py @@ -12,6 +12,8 @@ from agents.lifecycle import RunHooks from agents.run_context import AgentHookContext, RunContextWrapper from agents.tool_context import ToolContext +from strix.telemetry.logging import set_agent_id + logger = logging.getLogger(__name__) @@ -107,16 +109,27 @@ class StrixOrchestrationHooks(RunHooks[Any]): if bus is not None and agent_id is not None: await bus.record_usage(agent_id, usage) tracer = ctx.get("tracer") - if tracer is not None and usage is not None and hasattr(tracer, "record_llm_usage"): - cached = 0 + cached_total = 0 + input_total = 0 + output_total = 0 + if usage is not None: details = getattr(usage, "input_tokens_details", None) if details is not None: - cached = int(getattr(details, "cached_tokens", 0) or 0) - tracer.record_llm_usage( - input_tokens=int(getattr(usage, "input_tokens", 0) or 0), - output_tokens=int(getattr(usage, "output_tokens", 0) or 0), - cached_tokens=cached, - ) + cached_total = int(getattr(details, "cached_tokens", 0) or 0) + input_total = int(getattr(usage, "input_tokens", 0) or 0) + output_total = int(getattr(usage, "output_tokens", 0) or 0) + if tracer is not None and hasattr(tracer, "record_llm_usage"): + tracer.record_llm_usage( + input_tokens=input_total, + output_tokens=output_total, + cached_tokens=cached_total, + ) + logger.debug( + "LLM call done: input=%d output=%d cached=%d", + input_total, + output_total, + cached_total, + ) except Exception: logger.exception("on_llm_end failed") @@ -133,18 +146,25 @@ class StrixOrchestrationHooks(RunHooks[Any]): ctx = context.context if not isinstance(ctx, dict): return + me = ctx.get("agent_id") + if isinstance(me, str): + # Tag every log record emitted under this agent's task + # with the agent_id, automatically. Cleared on agent end. + set_agent_id(me) tracer = ctx.get("tracer") bus = ctx.get("bus") - me = ctx.get("agent_id") if tracer is None or bus is None or me is None: return + name = bus.names.get(me, me) + parent = bus.parent_of.get(me) + logger.info("Agent %s (%s) started, parent=%s", me, name, parent or "-") now = datetime.now(UTC).isoformat() tracer.agents.setdefault( me, { "id": me, - "name": bus.names.get(me, me), - "parent_id": bus.parent_of.get(me), + "name": name, + "parent_id": parent, "status": bus.statuses.get(me, "running"), "created_at": now, "updated_at": now, @@ -198,6 +218,17 @@ class StrixOrchestrationHooks(RunHooks[Any]): }, ) + calls = ( + int(bus.stats_live.get(me, {}).get("calls", 0)) if hasattr(bus, "stats_live") else 0 + ) + logger.info( + "Agent %s (%s) ended status=%s calls=%d", + me, + bus.names.get(me, me), + final_status, + calls, + ) + if stays_alive: await bus.park(me) # Reset the finish flag so the next cycle can detect its own @@ -206,6 +237,9 @@ class StrixOrchestrationHooks(RunHooks[Any]): ctx["agent_finish_called"] = False else: await bus.finalize(me, final_status) + # Clear the agent_id from the log context so any post-finalize + # work (cleanup in scan.py finally) doesn't keep the stale tag. + set_agent_id(None) except Exception: logger.exception("on_agent_end failed") @@ -242,6 +276,13 @@ class StrixOrchestrationHooks(RunHooks[Any]): if isinstance(parsed, dict): args = parsed tracer.log_tool_start(ctx.get("agent_id", "?"), tool.name, args) + args_repr = json.dumps(args, ensure_ascii=False, default=str) if args else "" + logger.debug( + "Tool %s start (args_len=%d): %s", + tool.name, + len(args_repr), + args_repr[:500], + ) except Exception: logger.exception("on_tool_start failed") @@ -262,5 +303,7 @@ class StrixOrchestrationHooks(RunHooks[Any]): tracer = ctx.get("tracer") if tracer is not None: tracer.log_tool_end(ctx.get("agent_id", "?"), tool.name, result) + result_str = result if isinstance(result, str) else str(result) + logger.debug("Tool %s done (result_len=%d)", tool.name, len(result_str)) except Exception: logger.exception("on_tool_end failed") diff --git a/strix/orchestration/run_loop.py b/strix/orchestration/run_loop.py index 7c06262..4f817a8 100644 --- a/strix/orchestration/run_loop.py +++ b/strix/orchestration/run_loop.py @@ -90,8 +90,14 @@ async def run_with_continuation( if not interactive: return result + logger.debug( + "run_with_continuation: entering interactive outer loop for %s (timeout=%s)", + agent_id, + waiting_timeout, + ) while True: if agent_id in bus.stopping: + logger.info("run_with_continuation: %s in stopping set, returning", agent_id) return result try: @@ -103,8 +109,13 @@ async def run_with_continuation( timeout=waiting_timeout, ) except asyncio.CancelledError: + logger.info("run_with_continuation: %s cancelled while waiting", agent_id) return result except TimeoutError: + logger.info( + "run_with_continuation: %s waiting timeout, auto-resuming", + agent_id, + ) kwargs["input"] = _TIMEOUT_RESUME_MESSAGE result = await _run_streamed(agent, bus, agent_id, **kwargs) continue @@ -118,6 +129,12 @@ async def run_with_continuation( if not next_input: continue + logger.debug( + "run_with_continuation: %s resuming with %d message(s) (input_len=%d)", + agent_id, + len(pending), + len(next_input), + ) kwargs["input"] = next_input result = await _run_streamed(agent, bus, agent_id, **kwargs) diff --git a/strix/orchestration/scan.py b/strix/orchestration/scan.py index 8c199e3..8e21c2a 100644 --- a/strix/orchestration/scan.py +++ b/strix/orchestration/scan.py @@ -35,6 +35,7 @@ from strix.orchestration.filter import inject_messages_filter from strix.orchestration.hooks import StrixOrchestrationHooks from strix.orchestration.run_loop import run_with_continuation from strix.runtime import session_manager +from strix.telemetry.logging import set_scan_id, setup_scan_logging #: Default ``max_turns`` budget passed to ``Runner.run``. @@ -199,13 +200,32 @@ async def run_strix_scan( """ if scan_id is None: scan_id = f"scan-{uuid.uuid4().hex[:8]}" - logger.info("Starting Strix scan %s", scan_id) + + # Resolve run_dir before any heavy bring-up so the log file captures + # everything from sandbox start onwards. Tracer (if present) owns the + # canonical path; otherwise fall back to ``./strix_runs/``. + run_dir = ( + tracer.get_run_dir() + if tracer is not None and hasattr(tracer, "get_run_dir") + else Path.cwd() / "strix_runs" / scan_id + ) + teardown_logging = setup_scan_logging(run_dir) + set_scan_id(scan_id) + logger.info( + "Starting Strix scan %s (image=%s, max_turns=%d, interactive=%s, run_dir=%s)", + scan_id, + image, + max_turns, + interactive, + run_dir, + ) resolved_model = model or load_settings().llm.model if not resolved_model: raise RuntimeError( "No LLM model configured. Set STRIX_LLM env or pass model= to run_strix_scan().", ) + logger.info("LLM model resolved: %s", resolved_model) # Caller may pre-create the bus so it can hold a handle (e.g., the # TUI uses it to route stop / chat-input commands). Otherwise we @@ -213,12 +233,14 @@ async def run_strix_scan( if bus is None: bus = AgentMessageBus() root_id = uuid.uuid4().hex[:8] + logger.info("Bringing up sandbox session for scan %s", scan_id) bundle = await session_manager.create_or_reuse( scan_id, image=image, sources_path=sources_path, ) + logger.info("Sandbox ready for scan %s", scan_id) try: # Lazy: ``strix.interface`` pulls cli→tui→scan which would cycle. @@ -316,10 +338,14 @@ async def run_strix_scan( session=session, ) except BaseException: + logger.exception("Strix scan %s failed", scan_id) # Cancel any descendant tasks the root spawned before unwinding. # cancel_descendants is idempotent and handles the empty-tree case. await bus.cancel_descendants(root_id) raise finally: if cleanup_on_exit: + logger.info("Tearing down sandbox session for scan %s", scan_id) await session_manager.cleanup(scan_id) + logger.info("Strix scan %s done", scan_id) + teardown_logging() diff --git a/strix/runtime/backends.py b/strix/runtime/backends.py index 8cb02bb..9fcafef 100644 --- a/strix/runtime/backends.py +++ b/strix/runtime/backends.py @@ -16,6 +16,7 @@ back, so typos fail loudly. from __future__ import annotations +import logging from collections.abc import Awaitable, Callable from typing import TYPE_CHECKING, Any @@ -24,6 +25,9 @@ if TYPE_CHECKING: from agents.sandbox.manifest import Manifest +logger = logging.getLogger(__name__) + + # A backend brings up a fresh session and returns the (client, session) # pair. The client is whatever object exposes ``await client.delete(session)`` # for cleanup — typically an ``agents.sandbox.client.BaseSandboxClient`` @@ -75,6 +79,7 @@ def get_backend(name: str) -> SandboxBackend: raise ValueError( f"Unknown STRIX_RUNTIME_BACKEND: {name!r} (supported: {supported})", ) + logger.debug("Selected sandbox backend: %s", name) return backend @@ -86,6 +91,7 @@ def register_backend(name: str, backend: SandboxBackend) -> None: an existing name overwrites the prior entry. """ _BACKENDS[name] = backend + logger.info("Registered sandbox backend: %s", name) def supported_backends() -> list[str]: diff --git a/strix/runtime/session_manager.py b/strix/runtime/session_manager.py index e784bc7..99148f4 100644 --- a/strix/runtime/session_manager.py +++ b/strix/runtime/session_manager.py @@ -103,6 +103,7 @@ async def create_or_reuse( caido_endpoint = await session.resolve_exposed_port(_CONTAINER_CAIDO_PORT) host_caido_url = f"http://{caido_endpoint.host}:{caido_endpoint.port}" + logger.debug("Caido host endpoint resolved: %s", host_caido_url) caido_client = await bootstrap_caido( session, @@ -116,6 +117,7 @@ async def create_or_reuse( "caido_client": caido_client, } _SESSION_CACHE[scan_id] = bundle + logger.info("Sandbox session for scan %s ready and cached", scan_id) return bundle diff --git a/strix/skills/__init__.py b/strix/skills/__init__.py index 5ffe9f5..87ab96b 100644 --- a/strix/skills/__init__.py +++ b/strix/skills/__init__.py @@ -51,6 +51,7 @@ def load_skills(skill_names: list[str]) -> dict[str, str]: var_name = skill_name.split("/")[-1] skill_content[var_name] = _FRONTMATTER_PATTERN.sub("", content).lstrip() - logger.info("Loaded skill: %s -> %s", skill_name, var_name) + logger.debug("Loaded skill: %s -> %s", skill_name, var_name) + logger.debug("load_skills: %d skill(s) resolved", len(skill_content)) return skill_content diff --git a/strix/telemetry/logging.py b/strix/telemetry/logging.py new file mode 100644 index 0000000..d7d177d --- /dev/null +++ b/strix/telemetry/logging.py @@ -0,0 +1,136 @@ +"""Per-scan logging setup. + +Every scan calls :func:`setup_scan_logging` to attach a ``FileHandler`` +to ``{run_dir}/strix.log`` (DEBUG, all ``strix.*`` events) plus a +stderr handler (ERROR-only by default; DEBUG when ``STRIX_DEBUG=1``). +``scan_id`` and ``agent_id`` are pulled from ``ContextVar``s by a +``Filter`` so every log line is auto-tagged without callers passing +them explicitly. + +Third-party loggers (``httpx``, ``litellm``, ``openai``, etc.) are +capped at ``WARNING`` so the file isn't drowned in their internals. +""" + +from __future__ import annotations + +import contextlib +import logging +import os +from contextvars import ContextVar +from pathlib import Path # noqa: TC003 used at runtime by ``setup_scan_logging`` +from typing import TYPE_CHECKING + + +if TYPE_CHECKING: + from collections.abc import Callable + + +_SCAN_ID: ContextVar[str | None] = ContextVar("strix_scan_id", default=None) +_AGENT_ID: ContextVar[str | None] = ContextVar("strix_agent_id", default=None) + + +def set_scan_id(scan_id: str) -> None: + """Set the scan_id seen on every log record from this point in the task tree.""" + _SCAN_ID.set(scan_id) + + +def set_agent_id(agent_id: str | None) -> None: + """Set or clear the agent_id seen on every log record from this point. + + ``None`` clears (renders as ``-`` in the log line). Mutations are + isolated to the current asyncio task and tasks created from it after + the call. + """ + _AGENT_ID.set(agent_id) + + +class _StrixContextFilter(logging.Filter): + """Inject ``scan_id`` and ``agent_id`` from ``ContextVar``s onto each record.""" + + def filter(self, record: logging.LogRecord) -> bool: + record.scan_id = _SCAN_ID.get() or "-" + record.agent_id = _AGENT_ID.get() or "-" + return True + + +_FORMAT = "%(asctime)s.%(msecs)03d %(levelname)-7s %(scan_id)s %(agent_id)s %(name)s: %(message)s" +_DATEFMT = "%Y-%m-%d %H:%M:%S" + + +# Third-party loggers that get noisy at DEBUG. Capped so the file isn't +# drowned in their internals when STRIX_DEBUG=1. +_NOISY_LIBS: tuple[str, ...] = ( + "httpx", + "httpcore", + "urllib3", + "litellm", + "openai", + "anthropic", +) + + +_HANDLER_TAG = "_strix_scan_handler" + + +def setup_scan_logging(run_dir: Path, *, debug: bool | None = None) -> Callable[[], None]: + """Attach scan-scoped handlers; return a teardown callable. + + Args: + run_dir: Per-scan output directory. ``{run_dir}/strix.log`` is + created if missing and opened append-mode (so re-runs of the + same scan_id concatenate cleanly). + debug: When ``True``, stderr handler runs at DEBUG instead of + ERROR. ``None`` (default) reads ``STRIX_DEBUG`` env: ``1`` / + ``true`` / ``yes`` / ``on`` enables debug. + + Returns: + A no-arg callable that flushes/closes/removes the handlers this + call attached. Idempotent — calling twice is a no-op the second + time. Safe to call from a ``finally`` block. + """ + if debug is None: + debug = (os.environ.get("STRIX_DEBUG") or "").strip().lower() in { + "1", + "true", + "yes", + "on", + } + + run_dir.mkdir(parents=True, exist_ok=True) + log_path = run_dir / "strix.log" + + formatter = logging.Formatter(_FORMAT, datefmt=_DATEFMT) + context_filter = _StrixContextFilter() + + file_handler = logging.FileHandler(log_path, mode="a", encoding="utf-8") + file_handler.setLevel(logging.DEBUG) + file_handler.setFormatter(formatter) + file_handler.addFilter(context_filter) + setattr(file_handler, _HANDLER_TAG, True) + + stream_handler = logging.StreamHandler() + stream_handler.setLevel(logging.DEBUG if debug else logging.ERROR) + stream_handler.setFormatter(formatter) + 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 + + 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() + + return _teardown diff --git a/strix/tools/agents_graph/tools.py b/strix/tools/agents_graph/tools.py index 1620732..ba30652 100644 --- a/strix/tools/agents_graph/tools.py +++ b/strix/tools/agents_graph/tools.py @@ -550,6 +550,15 @@ async def create_agent( async with bus._lock: bus.tasks[child_id] = task_handle + logger.info( + "create_agent: spawned %s (%s) parent=%s skills=%d task_len=%d", + child_id, + name, + parent_id or "-", + len(skills or []), + len(task or ""), + ) + return json.dumps( { "success": True, @@ -659,6 +668,14 @@ async def agent_finish( ) parent_notified = True + logger.info( + "agent_finish: %s success=%s findings=%d parent_notified=%s", + me, + success, + len(findings or []), + parent_notified, + ) + return json.dumps( { "success": True, diff --git a/strix/tools/finish/tool.py b/strix/tools/finish/tool.py index 005cfc4..bbf7846 100644 --- a/strix/tools/finish/tool.py +++ b/strix/tools/finish/tool.py @@ -59,14 +59,21 @@ def _do_finish( technical_analysis=technical_analysis.strip(), recommendations=recommendations.strip(), ) + vuln_count = len(tracer.vulnerability_reports) + except (ImportError, AttributeError) as e: + logger.exception("finish_scan persistence failed") + return {"success": False, "message": f"Failed to complete scan: {e!s}"} + else: + logger.info( + "finish_scan: completed scan with %d vulnerability report(s)", + vuln_count, + ) return { "success": True, "scan_completed": True, "message": "Scan completed successfully", - "vulnerabilities_found": len(tracer.vulnerability_reports), + "vulnerabilities_found": vuln_count, } - except (ImportError, AttributeError) as e: - return {"success": False, "message": f"Failed to complete scan: {e!s}"} @function_tool(timeout=60) diff --git a/strix/tools/python/tool.py b/strix/tools/python/tool.py index 3c3189e..a65691c 100644 --- a/strix/tools/python/tool.py +++ b/strix/tools/python/tool.py @@ -247,6 +247,7 @@ async def python_action( sentinel = "__STRIX_PY_RESULT_" + uuid.uuid4().hex + "__" user_code_b64 = base64.b64encode(code.encode("utf-8")).decode("ascii") driver = _DRIVER_TEMPLATE.format(sentinel=sentinel, user_code_b64=user_code_b64) + logger.info("python_action: invoking driver (code_len=%d, timeout=%ds)", len(code), timeout) # /tmp inside the sandbox container is single-user (pentester) and # disposable per scan; the multi-user race B108/S108 warns about # doesn't apply. diff --git a/strix/tools/reporting/tool.py b/strix/tools/reporting/tool.py index b61e674..4b01787 100644 --- a/strix/tools/reporting/tool.py +++ b/strix/tools/reporting/tool.py @@ -275,8 +275,16 @@ async def _do_create( # noqa: PLR0912 code_locations=parsed_locations, ) except (ImportError, AttributeError) as e: + logger.exception("create_vulnerability_report persistence failed") return {"success": False, "message": f"Failed to create vulnerability report: {e!s}"} else: + logger.info( + "Vulnerability report created: id=%s severity=%s cvss=%.1f title=%s", + report_id, + severity, + cvss_score, + title, + ) return { "success": True, "message": f"Vulnerability report '{title}' created successfully", diff --git a/strix/tools/web_search/tool.py b/strix/tools/web_search/tool.py index 8855957..9ca55d3 100644 --- a/strix/tools/web_search/tool.py +++ b/strix/tools/web_search/tool.py @@ -4,6 +4,7 @@ from __future__ import annotations import asyncio import json +import logging from typing import Any import requests @@ -12,6 +13,9 @@ from agents import RunContextWrapper, function_tool from strix.config import load_settings +logger = logging.getLogger(__name__) + + _SYSTEM_PROMPT = """You are assisting a cybersecurity agent specialized in vulnerability scanning and security assessment running on Kali Linux. When responding to search queries: @@ -40,11 +44,13 @@ security implications and details.""" def _do_search(query: str) -> dict[str, Any]: api_key = load_settings().integrations.perplexity_api_key if not api_key: + logger.warning("web_search invoked without PERPLEXITY_API_KEY configured") return { "success": False, "message": "PERPLEXITY_API_KEY environment variable not set", "results": [], } + logger.info("web_search query (len=%d): %s", len(query), query[:120]) url = "https://api.perplexity.ai/chat/completions" headers = {"Authorization": f"Bearer {api_key}", "Content-Type": "application/json"} @@ -61,16 +67,20 @@ def _do_search(query: str) -> dict[str, Any]: response.raise_for_status() content = response.json()["choices"][0]["message"]["content"] except requests.exceptions.Timeout: + logger.warning("web_search timed out") return {"success": False, "message": "Request timed out", "results": []} except requests.exceptions.RequestException as e: + logger.exception("web_search API request failed") return {"success": False, "message": f"API request failed: {e!s}", "results": []} except KeyError as e: + logger.exception("web_search response shape unexpected") return { "success": False, "message": f"Unexpected API response format: missing {e!s}", "results": [], } - except Exception as e: # noqa: BLE001 + except Exception as e: + logger.exception("web_search failed") return {"success": False, "message": f"Web search failed: {e!s}", "results": []} else: return {