diff --git a/.agents/skills/sensitive-logging-audit/SKILL.md b/.agents/skills/sensitive-logging-audit/SKILL.md new file mode 100644 index 0000000000..ca150f4240 --- /dev/null +++ b/.agents/skills/sensitive-logging-audit/SKILL.md @@ -0,0 +1,78 @@ +--- +name: sensitive-logging-audit +description: Audit and fix sensitive-data exposure through Python runtime logging in openai-agents-python. Use when reviewing logging, print, warnings, stderr, traceback, MCP names, model or tool exceptions, redaction flags, or any diagnostic path that may retain user data. +--- + +# Sensitive Logging Audit + +## Objective + +Find candidate output sinks, trace their values manually, fix demonstrated leaks at shared runtime boundaries, and prove redaction with adversarial tests. + +The collector is only a syntax-based search aid. It does not resolve Python aliases or control flow, certify policy guards, or prove that an absent candidate is safe. + +## Workflow + +### 1. Establish the review surface + +- Work in the current checkout and preserve unrelated changes. +- Read `src/agents/_debug.py`, `src/agents/logger.py`, and the affected callers. +- Treat exception messages, arguments, tracebacks, causes, contexts, notes, names, URLs, and arbitrary values as potentially sensitive. +- Read [the Python redaction validation matrix](references/redaction-validation.md). + +Run the collector tests, then collect candidates: + +```bash +uv run python .agents/skills/sensitive-logging-audit/scripts/test_inventory.py +uv run python .agents/skills/sensitive-logging-audit/scripts/inventory_logging.py \ + --format json --output /tmp/sensitive-logging-candidates.json +``` + +The report intentionally contains no `policy`, `safe`, or guard classification. + +### 2. Supplement the collector with source search + +The collector does not follow assignments such as `emit = logger.error`. Search the source directly and inspect aliases, callbacks, wrappers, and reflective dispatch: + +```bash +rg -n '\.(debug|info|warning|warn|error|exception|critical|fatal|log)\b' src/agents +rg -n '\b(print|pprint|pp|warn|warn_explicit|write|writelines|print_exc|print_exception)\b' src/agents +rg -n 'DONT_LOG_(MODEL|TOOL)_DATA|log_(model|tool|model_and_tool)_action' src/agents +``` + +Do not turn collector coverage or a textual guard into a security conclusion. Trace producers and callers. + +### 3. Classify manually + +Assign each reviewed path one disposition: + +- `model`: model requests, responses, Realtime events, or derived values. +- `tool`: tool arguments, outputs, MCP data, tool events, or derived values. +- `model+tool`: either class may reach the sink. +- `operational`: demonstrated to contain only non-sensitive SDK metadata. +- `intentional-output`: explicitly user-facing output rather than diagnostics. +- `uncertain`: source tracing is incomplete. + +Record evidence in the audit report. The script does not validate or inherit dispositions. + +### 4. Fix runtime boundaries + +Before changing runtime behavior, use `$implementation-strategy`. + +- Check the relevant `_debug.DONT_LOG_MODEL_DATA` and `_debug.DONT_LOG_TOOL_DATA` flags before formatting or inspecting sensitive values. +- Redact mixed model/tool values when either flag disables data logging. +- In redacted mode, emit a fixed message and omit sensitive `args`, `extra`, and `exc_info`. +- Build diagnostic-only context lazily so redacted mode never reads it. +- Preserve useful diagnostics when sensitive-data logging is explicitly enabled. +- Keep logging failure from changing fallback, cleanup, event, rejection, or cancellation behavior. +- For MCP URLs, remove credentials, query parameters, and fragments in diagnostic mode; never use sanitized names as a substitute for fixed redacted messages. + +### 5. Prove caller behavior + +Add tests at every changed caller boundary. Inspect the complete `LogRecord`, not only rendered text. Test both redacted policies, diagnostic mode, hostile objects, exception chains, and the caller's observable fallback or cleanup behavior as applicable. + +### 6. Re-run and close out + +Re-run the collector, the manual searches, focused tests, and applicable repository gates. Use `$code-change-verification` for runtime or test changes and `$pr-draft-summary` when required. + +Report candidate counts as search coverage only. Lead with confirmed leaks fixed, retained intentional output, reviewed uncertainty, and verification results. Never report a clean collector result as proof that no sensitive logging path exists. diff --git a/.agents/skills/sensitive-logging-audit/agents/openai.yaml b/.agents/skills/sensitive-logging-audit/agents/openai.yaml new file mode 100644 index 0000000000..1f0e17b1bd --- /dev/null +++ b/.agents/skills/sensitive-logging-audit/agents/openai.yaml @@ -0,0 +1,4 @@ +interface: + display_name: "Sensitive Logging Audit" + short_description: "Audit and fix sensitive Python logging paths" + default_prompt: "Use $sensitive-logging-audit to inventory, verify, and fix sensitive logging leaks in this repository." diff --git a/.agents/skills/sensitive-logging-audit/references/redaction-validation.md b/.agents/skills/sensitive-logging-audit/references/redaction-validation.md new file mode 100644 index 0000000000..35b2ab6cba --- /dev/null +++ b/.agents/skills/sensitive-logging-audit/references/redaction-validation.md @@ -0,0 +1,63 @@ +# Python sensitive logging validation + +The collector reports syntactic logging and raw-output candidates. It does not resolve aliases, prove receiver types, evaluate guards, classify payloads, or support a completeness claim. Review candidates together with direct source searches and runtime tests. + +## Required validation matrix + +Test every changed sensitive caller boundary in both redacted and diagnostic modes. Use a unique sentinel for each source and inspect both rendered output and the complete `LogRecord`. + +| Case | Model flag | Tool flag | Value | Required assertion | +| --- | --- | --- | --- | --- | +| Model redaction | on | off | `Exception(secret)` | No sentinel or exception object remains in the record | +| Tool redaction | off | on | `Exception(secret)` | No sentinel or exception object remains in the record | +| Both redacted | on | on | model and tool values | Neither sentinel remains anywhere in the record | +| Diagnostic mode | off | off | ordinary exception | Existing diagnostic detail and traceback behavior remain | +| Hostile string | applicable | applicable | object whose `__str__` raises or returns a secret | Logging does not fail or reveal the secret | +| Hostile repr | applicable | applicable | object whose `__repr__` raises or returns a secret | Logging does not fail or reveal the secret | +| Hostile class access | applicable | applicable | exception overriding `__getattribute__` | Redacted logging does not inspect the exception | +| Exception chain | applicable | applicable | `__cause__`, `__context__`, notes, or `ExceptionGroup` containing secrets | No chained secret is attached or rendered | +| Supplemental arguments | applicable | applicable | fixed message plus secret formatting argument | Formatting arguments are omitted in redacted mode | +| Extra payload | applicable | applicable | `extra={"detail": secret}` | Secret `LogRecord` attributes are omitted | +| Traceback payload | applicable | applicable | `exc_info=True` or an exception tuple | `exc_info` and `exc_text` are absent in redacted mode | +| MCP server or tool name | tool | on | path token or custom-name sentinel | Log uses a fixed message and does not read or attach the name | +| URL-derived MCP name | tool | off | URL credentials, query, and fragment | Log retains only scheme, host, port, and path; the runtime value is unchanged | + +Also test the observable caller behavior after logging. Redaction is incorrect if it prevents a fallback result, cleanup, event emission, rejection, or cancellation from completing. + +## Inspect the full LogRecord + +Do not assert only against `caplog.text` or a mock call converted to a string. In redacted mode, inspect at least: + +- `record.msg` +- `record.args` +- `record.exc_info` +- `record.exc_text` +- values added through `record.__dict__` +- the final output of a real `logging.Formatter` + +The sensitive object itself must not remain attached even when its string representation is absent. A custom handler or exporter may inspect raw record fields. + +## Review procedure + +1. Run the collector against all of `src/agents`. +2. Run the supplemental `rg` searches from `SKILL.md` and inspect aliases and dynamic dispatch. +3. Review raw output and ambiguous receivers first. +4. Review caught values, `logger.exception`, `exc_info`, `extra`, and formatting arguments. +5. Trace model, tool, Realtime, MCP, session, sandbox, voice, tracing, and cleanup values to their producers. +6. Classify intentional output separately from diagnostics; do not silently exempt `print` or warnings. +7. Add focused tests at every changed caller boundary. +8. Re-run the collector and source searches after the fix. + +An empty or unchanged collector report is not proof of safety. Assignment aliases, monkey-patched methods, dynamically installed handlers, non-constant reflection, and arbitrary runtime data flow require manual inspection. + +## Audit report expectations + +For each confirmed or uncertain path, record: + +- The source location and value producer. +- The manual disposition: `model`, `tool`, `model+tool`, `operational`, `intentional-output`, or `uncertain`. +- Concrete evidence for the disposition. +- The fix or reason for retaining the path. +- The caller-level regression test, when behavior changed. + +Do not reuse a disposition solely because a fingerprint or call text is unchanged. diff --git a/.agents/skills/sensitive-logging-audit/scripts/inventory_logging.py b/.agents/skills/sensitive-logging-audit/scripts/inventory_logging.py new file mode 100644 index 0000000000..da2bea1f20 --- /dev/null +++ b/.agents/skills/sensitive-logging-audit/scripts/inventory_logging.py @@ -0,0 +1,360 @@ +#!/usr/bin/env python3 +from __future__ import annotations + +import argparse +import ast +import hashlib +import json +import re +import sys +from collections import Counter +from collections.abc import Iterable, Mapping, Sequence +from dataclasses import asdict, dataclass +from pathlib import Path +from typing import Any + +LOG_METHODS = { + "critical", + "debug", + "error", + "exception", + "fatal", + "info", + "log", + "warn", + "warning", +} +POLICY_HELPERS = { + "log_model_action_debug", + "log_model_action_error", + "log_model_action_warning", + "log_model_and_tool_action_debug", + "log_model_and_tool_action_error", + "log_model_and_tool_action_warning", + "log_tool_action_debug", + "log_tool_action_error", + "log_tool_action_warning", +} +RAW_OUTPUT_METHODS = { + "pp", + "pprint", + "print", + "print_exc", + "print_exception", + "warn", + "warn_explicit", + "write", + "writelines", +} +CALLBACK_KEYWORDS = {"callback", "handler"} + + +@dataclass(frozen=True) +class Candidate: + fingerprint: str + file: str + line: int + column: int + kind: str + method: str + context: str + call: str + reason: str + + def to_dict(self) -> dict[str, Any]: + return asdict(self) + + +def normalize_path(path: str | Path) -> str: + return str(path).replace("\\", "/") + + +def collect_source_files(roots: Sequence[str | Path]) -> list[Path]: + files: set[Path] = set() + for root_value in roots: + root = Path(root_value).resolve() + if root.is_file(): + if root.suffix == ".py": + files.add(root) + continue + if not root.is_dir(): + raise FileNotFoundError(f"Inventory root does not exist: {root_value}") + for path in root.rglob("*.py"): + relative_parts = path.relative_to(root).parts + if any(part.startswith(".") or part == "__pycache__" for part in relative_parts): + continue + files.add(path.resolve()) + return sorted(files) + + +def normalize_node(node: ast.AST, source: str) -> str: + segment = ast.get_source_segment(source, node) + if segment is None: + segment = ast.dump(node, annotate_fields=True, include_attributes=False) + return re.sub(r"\s+", " ", segment).strip() + + +def dotted_name(node: ast.AST) -> str | None: + if isinstance(node, ast.Name): + return node.id + if isinstance(node, ast.Attribute): + receiver = dotted_name(node.value) + return f"{receiver}.{node.attr}" if receiver else node.attr + return None + + +def terminal_name(node: ast.AST) -> str | None: + name = dotted_name(node) + return name.rsplit(".", 1)[-1] if name else None + + +def make_parent_map(tree: ast.AST) -> dict[ast.AST, ast.AST]: + return {child: parent for parent in ast.walk(tree) for child in ast.iter_child_nodes(parent)} + + +def scope_context(node: ast.AST, parents: Mapping[ast.AST, ast.AST]) -> str: + parts: list[str] = [] + current = parents.get(node) + while current is not None: + if isinstance(current, ast.ClassDef): + parts.append(f"class:{current.name}") + elif isinstance(current, ast.FunctionDef | ast.AsyncFunctionDef): + parts.append(f"function:{current.name}") + elif isinstance(current, ast.Lambda): + parts.append("lambda") + current = parents.get(current) + return ">".join(reversed(parts)) or "" + + +def callback_arguments(call: ast.Call) -> Iterable[tuple[ast.AST, str | None]]: + yield from ((argument, None) for argument in call.args) + yield from ( + (keyword.value, keyword.arg) for keyword in call.keywords if keyword.arg is not None + ) + + +def looks_like_callback(node: ast.AST, keyword: str | None) -> bool: + method = terminal_name(node) + if method not in LOG_METHODS: + return False + if keyword is not None and ( + keyword.startswith("on_") + or keyword.endswith(("_callback", "_handler")) + or keyword in CALLBACK_KEYWORDS + ): + return True + if not isinstance(node, ast.Attribute): + return False + receiver = dotted_name(node.value) + receiver_name = receiver.rsplit(".", 1)[-1].lower() if receiver else "" + return receiver_name in {"log", "logger"} or receiver_name.endswith(("_log", "_logger")) + + +def selected_getattr_method(call: ast.Call) -> str | None: + if terminal_name(call.func) != "getattr" or len(call.args) < 2: + return None + attribute = call.args[1] + if not isinstance(attribute, ast.Constant) or not isinstance(attribute.value, str): + return None + if attribute.value in LOG_METHODS | RAW_OUTPUT_METHODS: + return attribute.value + return None + + +def classify_call(call: ast.Call) -> tuple[str, str, str] | None: + qualified_method = dotted_name(call.func) + method = terminal_name(call.func) + if method in POLICY_HELPERS: + return ( + "policy-helper-call", + method, + "Known redaction helper; review the caller's data classification and fixed message.", + ) + if method in LOG_METHODS and not ( + method == "warn" and qualified_method in {"warn", "warnings.warn"} + ): + return ( + "logging-call-candidate", + method, + "Logging-like method name; inspect the receiver and every attached value.", + ) + if method in RAW_OUTPUT_METHODS: + return ( + "raw-output-call-candidate", + method, + "Direct-output method name; verify its destination and whether values " + "can be sensitive.", + ) + selected = selected_getattr_method(call) + if selected is not None: + return ( + "getattr-sink-candidate", + selected, + "Constant getattr selects an output-like method; trace the receiver and later uses.", + ) + return None + + +def inventory_source(source: str, file_path: str = "fixture.py") -> list[Candidate]: + normalized_path = normalize_path(file_path) + tree = ast.parse(source, filename=normalized_path) + parents = make_parent_map(tree) + candidates: list[Candidate] = [] + recorded: set[tuple[int, str, str]] = set() + + def record(node: ast.AST, kind: str, method: str, call: str, reason: str) -> None: + key = (id(node), kind, method) + if key in recorded: + return + recorded.add(key) + line = getattr(node, "lineno", 1) + column = getattr(node, "col_offset", 0) + 1 + context = scope_context(node, parents) + fingerprint = hashlib.sha256( + f"{normalized_path}\0{line}\0{column}\0{kind}\0{method}\0{call}".encode() + ).hexdigest()[:12] + candidates.append( + Candidate( + fingerprint=fingerprint, + file=normalized_path, + line=line, + column=column, + kind=kind, + method=method, + context=context, + call=call, + reason=reason, + ) + ) + + for node in ast.walk(tree): + if not isinstance(node, ast.Call): + continue + classification = classify_call(node) + if classification is not None: + kind, method, reason = classification + record(node, kind, method, normalize_node(node, source), reason) + for argument, keyword in callback_arguments(node): + if not looks_like_callback(argument, keyword): + continue + method = terminal_name(argument) + if method is None: + continue + record( + argument, + "logging-callback-candidate", + method, + normalize_node(argument, source), + "Logging-like callable passed to a callback-shaped argument; inspect " + "registration and payloads.", + ) + + candidates.sort(key=lambda item: (item.file, item.line, item.column, item.kind, item.method)) + return candidates + + +def summarize(candidates: Sequence[Candidate]) -> dict[str, int]: + kinds = Counter(candidate.kind for candidate in candidates) + return { + "totalCandidates": len(candidates), + "loggingCalls": kinds["logging-call-candidate"], + "rawOutputCalls": kinds["raw-output-call-candidate"], + "policyHelperCalls": kinds["policy-helper-call"], + "getattrSelections": kinds["getattr-sink-candidate"], + "callbackReferences": kinds["logging-callback-candidate"], + } + + +def parse_args(argv: Sequence[str] | None = None) -> argparse.Namespace: + parser = argparse.ArgumentParser( + description=( + "Collect syntactic Python logging and raw-output candidates for manual review." + ) + ) + parser.add_argument("roots", nargs="*", default=["src/agents"]) + parser.add_argument("--format", choices=("json", "markdown"), default="markdown") + parser.add_argument("--summary-only", action="store_true") + parser.add_argument("--output", type=Path) + return parser.parse_args(argv) + + +def build_report(args: argparse.Namespace) -> dict[str, Any]: + cwd = Path.cwd().resolve() + candidates: list[Candidate] = [] + for path in collect_source_files(args.roots): + try: + display_path = path.relative_to(cwd) + except ValueError: + display_path = path + source = path.read_text(encoding="utf-8") + try: + candidates.extend(inventory_source(source, str(display_path))) + except SyntaxError as error: + raise SyntaxError( + f"Failed to parse {display_path}:{error.lineno}: {error.msg}" + ) from error + + report: dict[str, Any] = { + "contract": ( + "Syntactic candidates only. Manual review and runtime tests are required; " + "absence from this report is not proof of safety." + ), + "summary": summarize(candidates), + } + if not args.summary_only: + report["candidates"] = [candidate.to_dict() for candidate in candidates] + return report + + +def render_markdown(report: Mapping[str, Any], summary_only: bool) -> str: + summary = report["summary"] + lines = [ + "# Sensitive logging candidates", + "", + f"> {report['contract']}", + "", + f"- Total candidates: {summary['totalCandidates']}", + f"- Logging calls: {summary['loggingCalls']}", + f"- Raw-output calls: {summary['rawOutputCalls']}", + f"- Policy-helper calls: {summary['policyHelperCalls']}", + f"- Constant getattr selections: {summary['getattrSelections']}", + f"- Callback references: {summary['callbackReferences']}", + ] + if not summary_only: + lines.extend( + [ + "", + "| Location | Kind | Method | Context | Fingerprint |", + "| --- | --- | --- | --- | --- |", + ] + ) + for candidate in report.get("candidates", []): + location = f"{candidate['file']}:{candidate['line']}" + lines.append( + f"| {location} | {candidate['kind']} | {candidate['method']} | " + f"{candidate['context']} | {candidate['fingerprint']} |" + ) + return "\n".join(lines) + "\n" + + +def main(argv: Sequence[str] | None = None) -> int: + args = parse_args(argv) + try: + report = build_report(args) + output = ( + json.dumps(report, indent=2, sort_keys=True) + "\n" + if args.format == "json" + else render_markdown(report, args.summary_only) + ) + if args.output: + args.output.write_text(output, encoding="utf-8") + else: + sys.stdout.write(output) + return 0 + except (OSError, SyntaxError, ValueError, json.JSONDecodeError) as error: + print(f"Sensitive logging candidate collection failed: {error}", file=sys.stderr) + return 1 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/.agents/skills/sensitive-logging-audit/scripts/test_inventory.py b/.agents/skills/sensitive-logging-audit/scripts/test_inventory.py new file mode 100644 index 0000000000..44a6b42a1a --- /dev/null +++ b/.agents/skills/sensitive-logging-audit/scripts/test_inventory.py @@ -0,0 +1,195 @@ +from __future__ import annotations + +import unittest +from pathlib import Path +from tempfile import TemporaryDirectory + +from inventory_logging import collect_source_files, inventory_source, summarize + + +class InventoryTests(unittest.TestCase): + def test_collects_direct_logging_calls_without_certifying_receivers(self) -> None: + candidates = inventory_source( + """ +from logging import error + +logger.debug("ready") +logger.error("failed: %s", secret) +error(secret) +task.exception() +""" + ) + + self.assertEqual( + [(item.kind, item.method) for item in candidates], + [ + ("logging-call-candidate", "debug"), + ("logging-call-candidate", "error"), + ("logging-call-candidate", "error"), + ("logging-call-candidate", "exception"), + ], + ) + + def test_collects_policy_helpers_without_claiming_their_callers_are_safe(self) -> None: + candidates = inventory_source( + """ +from agents.logger import log_model_action_error + +log_model_action_error(logger, "failed", error) +agents.logger.log_model_and_tool_action_warning(logger, "failed", error) +""" + ) + + self.assertEqual( + [(item.kind, item.method) for item in candidates], + [ + ("policy-helper-call", "log_model_action_error"), + ("policy-helper-call", "log_model_and_tool_action_warning"), + ], + ) + + def test_collects_raw_output_method_names(self) -> None: + candidates = inventory_source( + """ +import os +import pprint +import sys +import traceback +import warnings + +print(secret) +pprint.pp(secret) +warnings.warn(secret) +sys.stderr.buffer.write(secret_bytes) +sys.stdout.writelines([secret]) +traceback.print_exception(error) +os.write(2, secret_bytes) +""" + ) + + self.assertEqual( + [(item.kind, item.method) for item in candidates], + [ + ("raw-output-call-candidate", "print"), + ("raw-output-call-candidate", "pp"), + ("raw-output-call-candidate", "warn"), + ("raw-output-call-candidate", "write"), + ("raw-output-call-candidate", "writelines"), + ("raw-output-call-candidate", "print_exception"), + ("raw-output-call-candidate", "write"), + ], + ) + + def test_collects_constant_getattr_sink_selections(self) -> None: + candidates = inventory_source( + """ +emit = getattr(logger, "error") +writer = builtins.getattr(stream, "write") +ignored = getattr(logger, method_name) +""" + ) + + self.assertEqual( + [(item.kind, item.method) for item in candidates], + [ + ("getattr-sink-candidate", "error"), + ("getattr-sink-candidate", "write"), + ], + ) + + def test_collects_obvious_logging_callbacks(self) -> None: + candidates = inventory_source( + """ +register(log.warning) +register(on_error=service.error) +register(result=request.error) +""" + ) + + self.assertEqual( + [(item.kind, item.method, item.call) for item in candidates], + [ + ("logging-callback-candidate", "warning", "log.warning"), + ("logging-callback-candidate", "error", "service.error"), + ], + ) + + def test_keeps_the_output_schema_free_of_security_certification(self) -> None: + candidate = inventory_source('logger.error("failed", secret)')[0].to_dict() + + self.assertEqual( + set(candidate), + { + "fingerprint", + "file", + "line", + "column", + "kind", + "method", + "context", + "call", + "reason", + }, + ) + self.assertNotIn("policy", candidate) + self.assertNotIn("safe", candidate) + + def test_reports_enclosing_scope_as_review_context(self) -> None: + candidate = inventory_source( + """ +class Worker: + def report(self): + logger.error(secret) +""" + )[0] + + self.assertEqual(candidate.context, "class:Worker>function:report") + + def test_does_not_claim_to_follow_assignment_aliases(self) -> None: + candidates = inventory_source( + """ +emit = logger.error +emit(secret) +""" + ) + + self.assertEqual(candidates, []) + + def test_summary_counts_only_syntactic_candidate_categories(self) -> None: + candidates = inventory_source( + """ +logger.error(secret) +print(secret) +log_tool_action_error(logger, "failed", error) +register(on_error=service.error) +getattr(logger, "warning") +""" + ) + + self.assertEqual( + summarize(candidates), + { + "totalCandidates": 5, + "loggingCalls": 1, + "rawOutputCalls": 1, + "policyHelperCalls": 1, + "getattrSelections": 1, + "callbackReferences": 1, + }, + ) + + def test_collect_source_files_filters_hidden_children_relative_to_root(self) -> None: + with TemporaryDirectory(prefix=".hidden-parent-") as directory: + root = Path(directory) / "scan" + root.mkdir() + visible = root / "visible.py" + visible.write_text("print('visible')\n") + hidden = root / ".cache" + hidden.mkdir() + (hidden / "hidden.py").write_text("print('hidden')\n") + + self.assertEqual(collect_source_files([root]), [visible.resolve()]) + + +if __name__ == "__main__": + unittest.main() diff --git a/src/agents/agent.py b/src/agents/agent.py index 4f3c54a074..f5977d9e54 100644 --- a/src/agents/agent.py +++ b/src/agents/agent.py @@ -29,7 +29,7 @@ from .exceptions import ModelBehaviorError, UserError from .guardrail import InputGuardrail, OutputGuardrail from .handoffs import Handoff -from .logger import logger +from .logger import log_model_and_tool_action_error, logger from .mcp import MCPUtil from .model_settings import ModelSettings, _coerce_model_settings, _declared_model_settings_type from .models.default_models import ( @@ -854,10 +854,16 @@ async def _run_handler(payload: AgentToolStreamEvent) -> None: maybe_result = stream_handler(payload) if inspect.isawaitable(maybe_result): await maybe_result - except Exception: - logger.exception( - "Error while handling on_stream event for agent tool %s.", - self.name, + except Exception as exc: + + def diagnostic_extra() -> dict[str, object]: + return {"agent_name": self.name} + + log_model_and_tool_action_error( + logger, + "Error while handling an agent tool on_stream event", + exc, + diagnostic_extra=diagnostic_extra, ) async def dispatch_stream_events() -> None: diff --git a/src/agents/extensions/experimental/codex/codex_tool.py b/src/agents/extensions/experimental/codex/codex_tool.py index 534245dbd1..2c252e3d00 100644 --- a/src/agents/extensions/experimental/codex/codex_tool.py +++ b/src/agents/extensions/experimental/codex/codex_tool.py @@ -17,7 +17,7 @@ from agents import _debug from agents.exceptions import ModelBehaviorError, UserError -from agents.logger import logger +from agents.logger import log_model_and_tool_action_error, log_tool_action_error, logger from agents.models import _openai_shared from agents.run_context import RunContextWrapper from agents.strict_schema import ensure_strict_json_schema @@ -952,8 +952,12 @@ def _try_store_thread_id_in_run_context_after_error( try: _store_thread_id_in_run_context(ctx, key, thread_id) - except Exception: - logger.exception("Failed to store Codex thread id in run context after error.") + except Exception as exc: + log_tool_action_error( + logger, + "Failed to store Codex thread id in run context after error", + exc, + ) def _set_pydantic_context_value(context: BaseModel, key: str, value: str) -> bool: @@ -1047,8 +1051,12 @@ async def _run_handler(payload: CodexToolStreamEvent) -> None: maybe_result = on_stream(payload) if inspect.isawaitable(maybe_result): await maybe_result - except Exception: - logger.exception("Error while handling Codex on_stream event.") + except Exception as exc: + log_model_and_tool_action_error( + logger, + "Error while handling Codex on_stream event", + exc, + ) async def _dispatch() -> None: assert event_queue is not None diff --git a/src/agents/extensions/memory/advanced_sqlite_session.py b/src/agents/extensions/memory/advanced_sqlite_session.py index 2dd1e947fe..822c123570 100644 --- a/src/agents/extensions/memory/advanced_sqlite_session.py +++ b/src/agents/extensions/memory/advanced_sqlite_session.py @@ -11,8 +11,14 @@ from agents.result import RunResult from agents.usage import Usage +from ... import _debug from ..._tool_identity import is_reserved_synthetic_tool_namespace, tool_qualified_name from ...items import TResponseInputItem +from ...logger import ( + log_model_action_error, + log_model_action_warning, + log_model_and_tool_action_error, +) from ...memory import SQLiteSession from ...memory.session_settings import SessionSettings, resolve_session_limit @@ -172,9 +178,11 @@ def _add_items_sync(): self._insert_items(conn, items) self._insert_structure_metadata(conn, items) conn.commit() - except Exception: + except Exception as exc: conn.rollback() - self._logger.exception("Failed to add items for session %s", self.session_id) + log_model_and_tool_action_error( + self._logger, "Failed to add session items", exc + ) raise await asyncio.to_thread(_add_items_sync) @@ -462,7 +470,16 @@ async def store_run_usage(self, result: RunResult) -> None: turn_anchor=turn_anchor, ) except Exception as e: - self._logger.error("Failed to store usage for session %s: %s", self.session_id, e) + + def diagnostic_extra() -> dict[str, object]: + return {"session_id": self.session_id} + + log_model_action_error( + self._logger, + "Failed to store session usage", + e, + diagnostic_extra=diagnostic_extra, + ) def _capture_current_turn(self) -> tuple[int, str, int | None]: """Return (current_turn, branch_id, turn_anchor) in one locked read. @@ -581,15 +598,19 @@ def _add_structure_sync(): try: await asyncio.to_thread(_add_structure_sync) - except Exception: - self._logger.exception( - "Failed to add structure metadata for session %s", self.session_id + except Exception as exc: + log_model_and_tool_action_error( + self._logger, + "Failed to add session structure metadata", + exc, ) # Try to clean up any orphaned messages to maintain consistency. try: await self._cleanup_orphaned_messages() - except Exception: - self._logger.exception("Failed to cleanup orphaned messages") + except Exception as cleanup_exc: + log_model_and_tool_action_error( + self._logger, "Failed to cleanup orphaned session messages", cleanup_exc + ) raise def _insert_structure_metadata( @@ -870,13 +891,21 @@ def _validate_turn(): old_branch = self._current_branch_id await asyncio.to_thread(self._commit_branch_pointer, branch_name, generation) - self._logger.debug( - "Created branch '%s' from turn %s ('%s') in '%s'", - branch_name, - turn_number, - turn_content, - old_branch, - ) + if _debug.DONT_LOG_MODEL_DATA: + self._logger.debug( + "Created branch '%s' from turn %s in '%s'", + branch_name, + turn_number, + old_branch, + ) + else: + self._logger.debug( + "Created branch '%s' from turn %s ('%s') in '%s'", + branch_name, + turn_number, + turn_content, + old_branch, + ) return branch_name async def create_branch_from_content( @@ -1580,7 +1609,9 @@ def _update_sync(): try: input_details_json = json.dumps(usage_data.input_tokens_details.__dict__) except (TypeError, ValueError) as e: - self._logger.warning("Failed to serialize input tokens details: %s", e) + log_model_action_warning( + self._logger, "Failed to serialize input token details", e + ) input_details_json = None if ( @@ -1590,7 +1621,9 @@ def _update_sync(): try: output_details_json = json.dumps(usage_data.output_tokens_details.__dict__) except (TypeError, ValueError) as e: - self._logger.warning("Failed to serialize output tokens details: %s", e) + log_model_action_warning( + self._logger, "Failed to serialize output token details", e + ) output_details_json = None with closing(conn.cursor()) as cursor: diff --git a/src/agents/extensions/memory/dapr_session.py b/src/agents/extensions/memory/dapr_session.py index eaed2574f5..e923940f11 100644 --- a/src/agents/extensions/memory/dapr_session.py +++ b/src/agents/extensions/memory/dapr_session.py @@ -43,7 +43,7 @@ ) from ...items import TResponseInputItem -from ...logger import logger +from ...logger import log_model_and_tool_action_error, logger from ...memory.session import SessionABC from ...memory.session_settings import ( SessionSettings, @@ -461,5 +461,5 @@ async def ping(self) -> bool: ) return True except Exception: - logger.error("Dapr connection failed: %s", initial_error) + log_model_and_tool_action_error(logger, "Dapr connection failed", initial_error) return False diff --git a/src/agents/extensions/sandbox/blaxel/mounts.py b/src/agents/extensions/sandbox/blaxel/mounts.py index 1476a1eb5d..d31a61edb0 100644 --- a/src/agents/extensions/sandbox/blaxel/mounts.py +++ b/src/agents/extensions/sandbox/blaxel/mounts.py @@ -25,6 +25,7 @@ from pathlib import Path from typing import Any, Literal +from ....logger import log_tool_action_warning from ....sandbox.entries import GCSMount, Mount, R2Mount, S3Mount from ....sandbox.entries.mounts.base import MountStrategyBase from ....sandbox.errors import MountConfigError @@ -668,7 +669,12 @@ async def _detach_drive(sandbox: Any, mount_path: str) -> None: try: await drives.unmount(mount_path) except Exception as e: - logger.warning("drive detach failed for %s (non-fatal): %s", mount_path, e) + log_tool_action_warning( + logger, + "Drive detach failed (non-fatal)", + e, + diagnostic_extra=lambda: {"mount_path": mount_path}, + ) __all__ = [ diff --git a/src/agents/extensions/sandbox/blaxel/sandbox.py b/src/agents/extensions/sandbox/blaxel/sandbox.py index 02c8e87b38..02d41a9712 100644 --- a/src/agents/extensions/sandbox/blaxel/sandbox.py +++ b/src/agents/extensions/sandbox/blaxel/sandbox.py @@ -29,6 +29,7 @@ from pydantic import BaseModel, Field +from ....logger import log_tool_action_debug, log_tool_action_warning from ....sandbox.entries import Mount from ....sandbox.errors import ( ExecTimeoutError, @@ -453,7 +454,9 @@ async def start(self) -> None: } ) except Exception as e: - logger.debug("workspace root mkdir failed (will retry during materialization): %s", e) + log_tool_action_debug( + logger, "Workspace root mkdir failed; retrying during materialization", e + ) await super().start() async def stop(self) -> None: @@ -467,7 +470,7 @@ async def shutdown(self) -> None: # When pause_on_exit is True the sandbox is kept alive. Blaxel # automatically resumes it on the next connection. except Exception as e: - logger.warning("sandbox delete failed during shutdown: %s", e) + log_tool_action_warning(logger, "Sandbox delete failed during shutdown", e) async def _validate_path_access(self, path: Path | str, *, for_write: bool = False) -> Path: return await self._validate_remote_path_access(path, for_write=for_write) @@ -626,7 +629,7 @@ async def running(self) -> bool: await asyncio.wait_for(self._sandbox.fs.ls("/"), timeout=10.0) return True except Exception as e: - logger.debug("sandbox health check failed: %s", e) + log_tool_action_debug(logger, "Sandbox health check failed", e) return False # -- workspace persistence ----------------------------------------------- @@ -690,7 +693,7 @@ async def persist_workspace(self) -> io.IOBase: "rm", "-f", "--", tar_path, timeout=self.state.timeouts.cleanup_s ) except Exception as e: - logger.debug("persist cleanup rm failed (non-fatal): %s", e) + log_tool_action_debug(logger, "Persist cleanup failed (non-fatal)", e) remount_error: WorkspaceArchiveReadError | None = None for mount_entry, mount_path in reversed(unmounted_mounts): @@ -764,7 +767,7 @@ async def hydrate_workspace(self, data: io.IOBase) -> None: "rm", "-f", "--", tar_path, timeout=self.state.timeouts.cleanup_s ) except Exception as e: - logger.debug("hydrate cleanup rm failed (non-fatal): %s", e) + log_tool_action_debug(logger, "Hydrate cleanup failed (non-fatal)", e) # -- PTY ----------------------------------------------------------------- @@ -947,7 +950,7 @@ async def _pty_ws_reader(self, entry: _BlaxelPtySessionEntry) -> None: ): break except Exception as e: - logger.debug("PTY ws reader terminated with error: %s", e) + log_tool_action_debug(logger, "PTY WebSocket reader terminated with an error", e) finally: entry.done = True entry.output_notify.set() @@ -1018,14 +1021,14 @@ async def _terminate_pty_entry(self, entry: _BlaxelPtySessionEntry) -> None: try: await entry.ws.close() except Exception as e: - logger.debug("PTY ws close error (non-fatal): %s", e) + log_tool_action_debug(logger, "PTY WebSocket close failed (non-fatal)", e) if entry.http_session is not None: try: await entry.http_session.close() except Exception as e: - logger.debug("PTY http session close error (non-fatal): %s", e) + log_tool_action_debug(logger, "PTY HTTP session close failed (non-fatal)", e) except Exception as e: - logger.debug("PTY entry termination error (non-fatal): %s", e) + log_tool_action_debug(logger, "PTY entry termination failed (non-fatal)", e) # --------------------------------------------------------------------------- @@ -1126,7 +1129,7 @@ async def delete(self, session: SandboxSession) -> SandboxSession: try: await inner.shutdown() except Exception as e: - logger.warning("shutdown error during delete (non-fatal): %s", e) + log_tool_action_warning(logger, "Shutdown failed during delete (non-fatal)", e) return session async def resume( @@ -1152,7 +1155,7 @@ async def resume( blaxel_sandbox = await SandboxInstance.get(state.sandbox_name) reconnected = True except Exception as e: - logger.debug("sandbox get() failed, will recreate: %s", e) + log_tool_action_debug(logger, "Sandbox lookup failed; recreating", e) if not reconnected or blaxel_sandbox is None: create_config = _build_create_config( diff --git a/src/agents/extensions/sandbox/cloudflare/sandbox.py b/src/agents/extensions/sandbox/cloudflare/sandbox.py index a3f94ec591..ab492ff823 100644 --- a/src/agents/extensions/sandbox/cloudflare/sandbox.py +++ b/src/agents/extensions/sandbox/cloudflare/sandbox.py @@ -29,6 +29,8 @@ import aiohttp +from .... import _debug +from ....logger import log_tool_action_debug from ....sandbox.errors import ( ConfigurationError, ErrorCode, @@ -693,13 +695,16 @@ async def _shutdown_backend(self) -> None: async with http.delete(url) as resp: if resp.status < 400 or resp.status == 404: return - detail = await _read_cloudflare_response_body(resp) - logger.debug( - "Failed to delete Cloudflare sandbox on shutdown: %s", - _cloudflare_http_error_message("DELETE /sandbox", resp.status, detail), - ) - except Exception: - logger.debug("Failed to delete Cloudflare sandbox on shutdown", exc_info=True) + if _debug.DONT_LOG_TOOL_DATA: + logger.debug("Failed to delete Cloudflare sandbox on shutdown") + else: + detail = await _read_cloudflare_response_body(resp) + logger.debug( + "Failed to delete Cloudflare sandbox on shutdown: %s", + _cloudflare_http_error_message("DELETE /sandbox", resp.status, detail), + ) + except Exception as exc: + log_tool_action_debug(logger, "Failed to delete Cloudflare sandbox on shutdown", exc) async def _after_shutdown(self) -> None: await self._close_http() @@ -846,7 +851,10 @@ async def _pump_ws_output(self, entry: _CloudflarePtyProcessEntry) -> None: try: payload = json.loads(msg.data) except json.JSONDecodeError: - logger.debug("Ignoring non-JSON PTY text frame: %s", msg.data) + if _debug.DONT_LOG_TOOL_DATA: + logger.debug("Ignoring non-JSON PTY text frame") + else: + logger.debug("Ignoring non-JSON PTY text frame: %s", msg.data) continue msg_type = payload.get("type") @@ -859,7 +867,10 @@ async def _pump_ws_output(self, entry: _CloudflarePtyProcessEntry) -> None: entry.output_notify.set() break if msg_type == "error": - logger.warning("Cloudflare PTY error frame: %s", payload.get("message")) + if _debug.DONT_LOG_TOOL_DATA: + logger.warning("Cloudflare PTY error frame") + else: + logger.warning("Cloudflare PTY error frame: %s", payload.get("message")) entry.output_closed.set() entry.output_notify.set() break @@ -875,8 +886,8 @@ async def _pump_ws_output(self, entry: _CloudflarePtyProcessEntry) -> None: break except asyncio.CancelledError: raise - except Exception: - logger.debug("Cloudflare PTY pump ended with an exception", exc_info=True) + except Exception as exc: + log_tool_action_debug(logger, "Cloudflare PTY pump ended with an exception", exc) entry.output_closed.set() entry.output_notify.set() diff --git a/src/agents/extensions/sandbox/daytona/sandbox.py b/src/agents/extensions/sandbox/daytona/sandbox.py index 294afc6cf3..988d5a2778 100644 --- a/src/agents/extensions/sandbox/daytona/sandbox.py +++ b/src/agents/extensions/sandbox/daytona/sandbox.py @@ -26,6 +26,7 @@ from pydantic import BaseModel, Field +from ....logger import log_tool_action_debug from ....sandbox.entries import Mount from ....sandbox.errors import ( ExecTimeoutError, @@ -1335,7 +1336,7 @@ async def resume( await daytona_sandbox.start(timeout=state.start_timeout) reconnected = True except Exception as e: - logger.debug("daytona sandbox get() failed, will recreate: %s", e) + log_tool_action_debug(logger, "Daytona sandbox lookup failed; recreating", e) if not reconnected or daytona_sandbox is None: params = await self._build_create_params( diff --git a/src/agents/extensions/sandbox/e2b/sandbox.py b/src/agents/extensions/sandbox/e2b/sandbox.py index 324d08bfdf..ecbe8bc0bf 100644 --- a/src/agents/extensions/sandbox/e2b/sandbox.py +++ b/src/agents/extensions/sandbox/e2b/sandbox.py @@ -34,6 +34,7 @@ from pydantic import BaseModel, Field +from ....logger import log_tool_action_warning from ....sandbox.entries import Mount from ....sandbox.errors import ( ExecNonZeroError, @@ -858,6 +859,12 @@ async def _after_start_failed(self) -> None: async def _shutdown_backend(self) -> None: # Best-effort kill of the remote sandbox. + def diagnostic_extra() -> dict[str, object]: + return { + "sandbox_id": self.state.sandbox_id, + "pause_on_exit": self.state.pause_on_exit, + } + try: if self.state.pause_on_exit: await _sandbox_pause(self._sandbox) @@ -865,33 +872,27 @@ async def _shutdown_backend(self) -> None: await _sandbox_kill(self._sandbox) except Exception as e: if self.state.pause_on_exit: - logger.warning( + log_tool_action_warning( + logger, "Failed to pause E2B sandbox on shutdown; falling back to kill.", - extra={ - "sandbox_id": self.state.sandbox_id, - "pause_on_exit": self.state.pause_on_exit, - }, - exc_info=e, + e, + diagnostic_extra=diagnostic_extra, ) try: await _sandbox_kill(self._sandbox) except Exception as kill_exc: - logger.warning( + log_tool_action_warning( + logger, "Failed to kill E2B sandbox after pause fallback failure.", - extra={ - "sandbox_id": self.state.sandbox_id, - "pause_on_exit": self.state.pause_on_exit, - }, - exc_info=kill_exc, + kill_exc, + diagnostic_extra=diagnostic_extra, ) else: - logger.warning( + log_tool_action_warning( + logger, "Failed to kill E2B sandbox on shutdown.", - extra={ - "sandbox_id": self.state.sandbox_id, - "pause_on_exit": self.state.pause_on_exit, - }, - exc_info=e, + e, + diagnostic_extra=diagnostic_extra, ) async def _exec_internal( diff --git a/src/agents/extensions/sandbox/modal/sandbox.py b/src/agents/extensions/sandbox/modal/sandbox.py index 930d9f8b59..b70f840119 100644 --- a/src/agents/extensions/sandbox/modal/sandbox.py +++ b/src/agents/extensions/sandbox/modal/sandbox.py @@ -33,6 +33,7 @@ from modal.config import config as modal_config from modal.container_process import ContainerProcess +from ....logger import log_tool_action_warning from ....sandbox.config import DEFAULT_PYTHON_SANDBOX_IMAGE from ....sandbox.entries import Mount from ....sandbox.errors import ( @@ -1327,8 +1328,9 @@ async def restore_ephemeral_paths() -> WorkspaceArchiveReadError | None: if not rm_out.ok(): cleanup_restore_error = await restore_ephemeral_paths() if cleanup_restore_error is not None: - logger.warning( - "Failed to restore Modal ephemeral paths after cleanup failure: %s", + log_tool_action_warning( + logger, + "Failed to restore Modal ephemeral paths after cleanup failure", cleanup_restore_error, ) raise WorkspaceArchiveReadError( @@ -1352,8 +1354,9 @@ async def restore_ephemeral_paths() -> WorkspaceArchiveReadError | None: except Exception as e: restore_error = await restore_ephemeral_paths() if restore_error is not None: - logger.warning( - "Failed to restore Modal ephemeral paths after snapshot failure: %s", + log_tool_action_warning( + logger, + "Failed to restore Modal ephemeral paths after snapshot failure", restore_error, ) raise WorkspaceArchiveReadError( diff --git a/src/agents/logger.py b/src/agents/logger.py index bd81a82716..18b8670680 100644 --- a/src/agents/logger.py +++ b/src/agents/logger.py @@ -1,3 +1,244 @@ import logging +from collections.abc import Callable, Mapping +from types import TracebackType + +from . import _debug logger = logging.getLogger("openai.agents") + +_DiagnosticExtra = Callable[[], Mapping[str, object]] +_DIAGNOSTIC_CONTEXT_FIELD = "openai_agents_diagnostic_context" + + +def _exception_info( + exc: BaseException, +) -> tuple[type[BaseException], BaseException, TracebackType | None]: + """Build logging exception info without evaluating exception truthiness.""" + traceback = BaseException.__getattribute__(exc, "__traceback__") + return type(exc), exc, traceback + + +def _log_record_extra(diagnostic_extra: _DiagnosticExtra | None) -> dict[str, object] | None: + if diagnostic_extra is None: + return None + try: + return {_DIAGNOSTIC_CONTEXT_FIELD: dict(diagnostic_extra())} + except Exception: + return None + + +def _log_action_error( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + redact: bool, + stacklevel: int, + diagnostic_extra: _DiagnosticExtra | None, +) -> None: + """Log an action failure without inspecting a redacted exception.""" + if redact: + target_logger.error("%s", message, stacklevel=stacklevel) + else: + target_logger.error( + "%s: %s", + message, + exc, + exc_info=_exception_info(exc), + extra=_log_record_extra(diagnostic_extra), + stacklevel=stacklevel, + ) + + +def _log_action_at_level( + log_method: Callable[..., None], + message: str, + exc: BaseException, + *, + redact: bool, + stacklevel: int, + diagnostic_extra: _DiagnosticExtra | None, +) -> None: + """Log an action failure at a caller-selected level.""" + if redact: + log_method("%s", message, stacklevel=stacklevel) + else: + log_method( + "%s: %s", + message, + exc, + exc_info=_exception_info(exc), + extra=_log_record_extra(diagnostic_extra), + stacklevel=stacklevel, + ) + + +def log_model_action_error( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Log a model-data failure according to the model logging policy.""" + _log_action_error( + target_logger, + message, + exc, + redact=_debug.DONT_LOG_MODEL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_model_action_debug( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Debug-log a model-data failure according to the model logging policy.""" + _log_action_at_level( + target_logger.debug, + message, + exc, + redact=_debug.DONT_LOG_MODEL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_model_action_warning( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Warning-log a model-data failure according to the model logging policy.""" + _log_action_at_level( + target_logger.warning, + message, + exc, + redact=_debug.DONT_LOG_MODEL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_tool_action_error( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Log a tool-data failure according to the tool logging policy.""" + _log_action_error( + target_logger, + message, + exc, + redact=_debug.DONT_LOG_TOOL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_tool_action_debug( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Debug-log a tool-data failure according to the tool logging policy.""" + _log_action_at_level( + target_logger.debug, + message, + exc, + redact=_debug.DONT_LOG_TOOL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_tool_action_warning( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Warning-log a tool-data failure according to the tool logging policy.""" + _log_action_at_level( + target_logger.warning, + message, + exc, + redact=_debug.DONT_LOG_TOOL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_model_and_tool_action_error( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Log a mixed model/tool-data failure only when both data policies allow it.""" + _log_action_error( + target_logger, + message, + exc, + redact=_debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_model_and_tool_action_debug( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Debug-log a mixed-data failure only when both data policies allow it.""" + _log_action_at_level( + target_logger.debug, + message, + exc, + redact=_debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) + + +def log_model_and_tool_action_warning( + target_logger: logging.Logger, + message: str, + exc: BaseException, + *, + stacklevel: int = 3, + diagnostic_extra: _DiagnosticExtra | None = None, +) -> None: + """Warning-log a mixed-data failure only when both data policies allow it.""" + _log_action_at_level( + target_logger.warning, + message, + exc, + redact=_debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA, + stacklevel=stacklevel, + diagnostic_extra=diagnostic_extra, + ) diff --git a/src/agents/mcp/_logging.py b/src/agents/mcp/_logging.py new file mode 100644 index 0000000000..ffb6df97b5 --- /dev/null +++ b/src/agents/mcp/_logging.py @@ -0,0 +1,52 @@ +from typing import Protocol +from urllib.parse import urlsplit, urlunsplit + +from .. import _debug + +_URL_DERIVED_NAME_PREFIXES = ("sse: ", "streamable_http: ", "streamable-http: ") + + +class _MCPServerNameSource(Protocol): + @property + def name(self) -> str: ... + + +def get_mcp_server_log_name(name: str) -> str: + """Remove URL credentials, query parameters, and fragments from MCP log names.""" + prefix = next( + (candidate for candidate in _URL_DERIVED_NAME_PREFIXES if name.startswith(candidate)), + "", + ) + candidate = name[len(prefix) :] if prefix else name + + try: + parsed = urlsplit(candidate) + except ValueError: + if prefix or candidate.lower().startswith(("http://", "https://")): + return f"{prefix}" + return name + + if parsed.scheme not in {"http", "https"}: + return name + + try: + hostname = parsed.hostname + port = parsed.port + except ValueError: + return f"{prefix}" + + if not parsed.netloc or not hostname or any(character.isspace() for character in hostname): + return f"{prefix}" + + host = f"[{hostname}]" if ":" in hostname else hostname + if port is not None: + host = f"{host}:{port}" + sanitized = urlunsplit((parsed.scheme, host, parsed.path, "", "")) + return f"{prefix}{sanitized}" + + +def get_mcp_server_log_message(message: str, server: _MCPServerNameSource) -> str: + """Build an MCP log message without reading the server name in redacted mode.""" + if _debug.DONT_LOG_TOOL_DATA: + return message + return f"{message} '{get_mcp_server_log_name(server.name)}'" diff --git a/src/agents/mcp/manager.py b/src/agents/mcp/manager.py index 235816819d..b8838be3e3 100644 --- a/src/agents/mcp/manager.py +++ b/src/agents/mcp/manager.py @@ -6,7 +6,8 @@ from dataclasses import dataclass from typing import Any -from ..logger import logger +from ..logger import log_tool_action_debug, log_tool_action_error, logger +from ._logging import get_mcp_server_log_message from .server import MCPServer @@ -260,10 +261,18 @@ async def cleanup_all(self) -> None: except asyncio.CancelledError as exc: if not self.suppress_cancelled_error: raise - logger.debug("Cleanup cancelled for MCP server '%s': %s", server.name, exc) + log_tool_action_debug( + logger, + get_mcp_server_log_message("Cleanup cancelled for MCP server", server), + exc, + ) self.errors[server] = exc except Exception as exc: - logger.exception("Failed to cleanup MCP server '%s': %s", server.name, exc) + log_tool_action_error( + logger, + get_mcp_server_log_message("Failed to cleanup MCP server", server), + exc, + ) self.errors[server] = exc async def _run_with_timeout( @@ -305,7 +314,11 @@ def _refresh_active_servers(self) -> None: self._active_servers = list(self._all_servers) def _record_failure(self, server: MCPServer, exc: BaseException, phase: str) -> None: - logger.exception("Failed to %s MCP server '%s': %s", phase, server.name, exc) + log_tool_action_error( + logger, + get_mcp_server_log_message(f"Failed to {phase} MCP server", server), + exc, + ) if server not in self._failed_server_set: self.failed_servers.append(server) self._failed_server_set.add(server) @@ -343,10 +356,18 @@ async def _cleanup_servers(self, servers: Iterable[MCPServer]) -> None: except asyncio.CancelledError as exc: if not self.suppress_cancelled_error: raise - logger.debug("Cleanup cancelled for MCP server '%s': %s", server.name, exc) + log_tool_action_debug( + logger, + get_mcp_server_log_message("Cleanup cancelled for MCP server", server), + exc, + ) self.errors[server] = exc except Exception as exc: - logger.exception("Failed to cleanup MCP server '%s': %s", server.name, exc) + log_tool_action_error( + logger, + get_mcp_server_log_message("Failed to cleanup MCP server", server), + exc, + ) self.errors[server] = exc async def _connect_all_parallel(self, servers: list[MCPServer]) -> None: diff --git a/src/agents/mcp/server.py b/src/agents/mcp/server.py index 2681606b5e..4f8f89c293 100644 --- a/src/agents/mcp/server.py +++ b/src/agents/mcp/server.py @@ -38,11 +38,18 @@ ) from typing_extensions import NotRequired, TypedDict +from .. import _debug from ..exceptions import UserError -from ..logger import logger +from ..logger import ( + log_tool_action_debug, + log_tool_action_error, + log_tool_action_warning, + logger, +) from ..run_context import RunContextWrapper from ..tool import ToolErrorFunction from ..util._types import MaybeAwaitable +from ._logging import get_mcp_server_log_message, get_mcp_server_log_name from .util import ( HttpClientFactory, MCPToolCustomDataExtractor, @@ -119,10 +126,11 @@ async def _handle_post_request(self, ctx: Any) -> None: try: await super()._handle_post_request(ctx) - except httpx.HTTPError: - logger.warning( + except httpx.HTTPError as exc: + log_tool_action_warning( + logger, "Ignoring initialized notification HTTP failure", - exc_info=True, + exc, ) return @@ -161,7 +169,13 @@ async def _streamablehttp_client_with_transport( async with client: async with anyio.create_task_group() as tg: try: - logger.debug("Connecting to StreamableHTTP endpoint: %s", url) + if _debug.DONT_LOG_TOOL_DATA: + logger.debug("Connecting to StreamableHTTP endpoint") + else: + logger.debug( + "Connecting to StreamableHTTP endpoint: %s", + get_mcp_server_log_name(url), + ) def start_get_stream() -> None: tg.start_soon(transport.handle_get_stream, client, read_stream_writer) @@ -691,12 +705,15 @@ async def _apply_dynamic_tool_filter( if should_include: filtered_tools.append(tool) except Exception as e: - logger.error( - "Error applying tool filter to tool '%s' on server '%s': %s", - tool.name, - self.name, - e, - ) + if _debug.DONT_LOG_TOOL_DATA: + message = "Error applying MCP tool filter" + else: + server_name = get_mcp_server_log_name(self.name) + message = ( + f"Error applying MCP tool filter to tool '{tool.name}' " + f"on server '{server_name}'" + ) + log_tool_action_error(logger, message, e) # On error, exclude the tool for safety continue @@ -818,16 +835,20 @@ async def connect(self): if isinstance(cleanup_error, RuntimeError) and "cancel scope" in str( cleanup_error ): - logger.debug( - "Ignoring cancel scope error during cleanup of MCP server '%s': %s", - self.name, + log_tool_action_debug( + logger, + get_mcp_server_log_message( + "Ignoring cancel scope error during cleanup of MCP server", self + ), cleanup_error, ) else: # Log other cleanup errors but don't raise - original error is more # important - logger.warning( - "Error during cleanup of MCP server '%s': %s", self.name, cleanup_error + log_tool_action_warning( + logger, + get_mcp_server_log_message("Error during cleanup of MCP server", self), + cleanup_error, ) async def list_tools( @@ -1005,7 +1026,11 @@ async def cleanup(self): try: await self.exit_stack.aclose() except asyncio.CancelledError as e: - logger.debug("Cleanup cancelled for MCP server '%s': %s", self.name, e) + log_tool_action_debug( + logger, + get_mcp_server_log_message("Cleanup cancelled for MCP server", self), + e, + ) raise except BaseExceptionGroup as eg: # Extract HTTP errors from ExceptionGroup raised during cleanup @@ -1031,9 +1056,11 @@ async def cleanup(self): raise UserError(error_message) from http_error else: # Normal teardown - log but don't raise - logger.warning( - "HTTP error during cleanup of MCP server '%s': %s", - self.name, + log_tool_action_warning( + logger, + get_mcp_server_log_message( + "HTTP error during cleanup of MCP server", self + ), http_error, ) elif connect_error: @@ -1041,9 +1068,11 @@ async def cleanup(self): error_message += "Could not reach the server." raise UserError(error_message) from connect_error else: - logger.warning( - "Connection error during cleanup of MCP server '%s': %s", - self.name, + log_tool_action_warning( + logger, + get_mcp_server_log_message( + "Connection error during cleanup of MCP server", self + ), connect_error, ) elif timeout_error: @@ -1051,9 +1080,11 @@ async def cleanup(self): error_message += "Connection timeout." raise UserError(error_message) from timeout_error else: - logger.warning( - "Timeout error during cleanup of MCP server '%s': %s", - self.name, + log_tool_action_warning( + logger, + get_mcp_server_log_message( + "Timeout error during cleanup of MCP server", self + ), timeout_error, ) else: @@ -1063,16 +1094,36 @@ async def cleanup(self): for exc in eg.exceptions ) if has_cancel_scope_error: - logger.debug("Ignoring cancel scope error during cleanup: %s", eg) + log_tool_action_debug( + logger, + get_mcp_server_log_message( + "Ignoring cancel scope error during cleanup of MCP server", self + ), + eg, + ) else: - logger.error("Error cleaning up server: %s", eg) + log_tool_action_error( + logger, + get_mcp_server_log_message("Error cleaning up MCP server", self), + eg, + ) except Exception as e: # Suppress RuntimeError about cancel scopes - this is a known issue with the MCP # library when background tasks fail during async generator cleanup if isinstance(e, RuntimeError) and "cancel scope" in str(e): - logger.debug("Ignoring cancel scope error during cleanup: %s", e) + log_tool_action_debug( + logger, + get_mcp_server_log_message( + "Ignoring cancel scope error during cleanup of MCP server", self + ), + e, + ) else: - logger.error("Error cleaning up server: %s", e) + log_tool_action_error( + logger, + get_mcp_server_log_message("Error cleaning up MCP server", self), + e, + ) finally: self.session = None self._get_session_id = None diff --git a/src/agents/mcp/util.py b/src/agents/mcp/util.py index 2cb0a5595b..049b4561ba 100644 --- a/src/agents/mcp/util.py +++ b/src/agents/mcp/util.py @@ -23,7 +23,7 @@ from mcp.shared.exceptions import McpError as _McpError except ImportError: # pragma: no cover – mcp is optional on Python < 3.10 _McpError = None # type: ignore[assignment, misc] -from ..logger import logger +from ..logger import log_tool_action_error, logger from ..run_context import RunContextWrapper from ..strict_schema import ensure_strict_json_schema from ..tool import ( @@ -42,6 +42,7 @@ from ..tracing import FunctionSpanData, get_current_span, mcp_tools_span from ..util._custom_data import maybe_extract_custom_data from ..util._types import MaybeAwaitable +from ._logging import get_mcp_server_log_message, get_mcp_server_log_name if TYPE_CHECKING: ToolOutputItem = ToolOutputTextDict | ToolOutputImageDict @@ -546,7 +547,10 @@ def to_function_tool( schema = ensure_strict_json_schema(copy.deepcopy(schema)) is_strict = True except Exception as e: - logger.info("Error converting MCP schema to strict mode: %s", e) + if _debug.DONT_LOG_TOOL_DATA: + logger.info("Error converting MCP schema to strict mode") + else: + logger.info("Error converting MCP schema to strict mode: %s", e) needs_approval: ( bool | Callable[[RunContextWrapper[Any], dict[str, Any], str], Awaitable[bool]] @@ -671,7 +675,7 @@ async def invoke_mcp_tool( if json_decode_error is not None: error_message = f"Invalid JSON input for tool {tool_name_for_display}" if _debug.DONT_LOG_TOOL_DATA: - logger.debug(error_message) + logger.debug("Invalid JSON input for MCP tool") raise ModelBehaviorError(error_message) else: error_message = f"{error_message}: {input_json}" @@ -684,7 +688,7 @@ async def invoke_mcp_tool( ) if _debug.DONT_LOG_TOOL_DATA: - logger.debug("Invoking MCP tool %s", tool_name_for_display) + logger.debug("Invoking MCP tool") else: logger.debug("Invoking MCP tool %s with input %s", tool_name_for_display, input_json) @@ -725,41 +729,30 @@ async def invoke_mcp_tool( # will surface the message as a structured error result; callers who set # failure_error_function=None will have the error raised as documented. if _debug.DONT_LOG_TOOL_DATA: - logger.warning( - "MCP tool %s on server '%s' returned an error.", - tool_name_for_display, - server.name, - ) + logger.warning("MCP tool returned an error.") else: + server_log_name = get_mcp_server_log_name(server.name) error_text = e.error.message if hasattr(e, "error") and e.error else str(e) logger.warning( "MCP tool %s on server '%s' returned an error: %s", tool_name_for_display, - server.name, + server_log_name, error_text, ) raise - if _debug.DONT_LOG_TOOL_DATA: - logger.error( - "Error invoking MCP tool %s on server '%s': %s", - tool_name_for_display, - server.name, - e.__class__.__name__, - ) - else: - logger.error( - "Error invoking MCP tool %s on server '%s': %s", - tool_name_for_display, - server.name, - e, + log_message = "Error invoking MCP tool" + if not _debug.DONT_LOG_TOOL_DATA: + log_message = get_mcp_server_log_message( + f"Error invoking MCP tool {tool_name_for_display} on server", server ) + log_tool_action_error(logger, log_message, e) raise AgentsException( f"Error invoking MCP tool {tool_name_for_display} on server '{server.name}': {e}" ) from e if _debug.DONT_LOG_TOOL_DATA: - logger.debug("MCP tool %s completed.", tool_name_for_display) + logger.debug("MCP tool completed.") else: logger.debug("MCP tool %s returned %s", tool_name_for_display, result) @@ -811,8 +804,12 @@ async def invoke_mcp_tool( "server": server.name, } else: - logger.warning( - "Current span is not a FunctionSpanData, skipping tool output: %s", current_span - ) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.warning("Current span is not a FunctionSpanData; skipping tool output") + else: + logger.warning( + "Current span is not a FunctionSpanData, skipping tool output: %s", + current_span, + ) return tool_output diff --git a/src/agents/memory/openai_responses_compaction_session.py b/src/agents/memory/openai_responses_compaction_session.py index 2ec40663db..8263a81036 100644 --- a/src/agents/memory/openai_responses_compaction_session.py +++ b/src/agents/memory/openai_responses_compaction_session.py @@ -7,6 +7,7 @@ from openai import AsyncOpenAI from ..items import TResponseInputItem +from ..logger import log_model_and_tool_action_warning from ..models._openai_shared import get_default_openai_client from ..run_internal.items import normalize_input_items_for_api from .openai_conversations_session import OpenAIConversationsSession @@ -273,10 +274,11 @@ async def _restore_underlying_session_items_after_failed_clear( ) -> None: try: current_items = await self._get_all_underlying_session_items() - except Exception: - logger.warning( + except Exception as inspection_error: + log_model_and_tool_action_warning( + logger, "Failed to inspect session history after compaction replacement clear failed.", - exc_info=True, + inspection_error, ) return @@ -299,15 +301,17 @@ async def _restore_underlying_session_items( await self.underlying_session.clear_session() if previous_items: await self.underlying_session.add_items(list(previous_items)) - except Exception: - logger.warning( + except Exception as restore_error: + log_model_and_tool_action_warning( + logger, "Failed to restore session history after compaction replacement failed.", - exc_info=True, + restore_error, ) return - logger.warning( - "Restored previous session history after compaction replacement failed: %s", + log_model_and_tool_action_warning( + logger, + "Restored previous session history after compaction replacement failed", replacement_error, ) diff --git a/src/agents/models/openai_chatcompletions.py b/src/agents/models/openai_chatcompletions.py index 408e8c8ad5..b7f9d8e00a 100644 --- a/src/agents/models/openai_chatcompletions.py +++ b/src/agents/models/openai_chatcompletions.py @@ -25,7 +25,7 @@ from ..exceptions import ModelBehaviorError, UserError from ..handoffs import Handoff from ..items import ModelResponse, TResponseInputItem, TResponseStreamEvent -from ..logger import logger +from ..logger import log_model_action_debug, logger from ..retry import ModelRetryAdvice, ModelRetryAdviceRequest from ..tool import Tool from ..tracing import generation_span @@ -149,7 +149,9 @@ def _consume_background_cleanup_task_result(task: asyncio.Task[Any]) -> None: except asyncio.CancelledError: pass except Exception as exc: - logger.debug("Background stream cleanup failed after cancellation: %s", exc) + log_model_action_debug( + logger, "Background stream cleanup failed after cancellation", exc + ) def _validate_official_openai_input_content_types( self, request_input: str | list[TResponseInputItem] @@ -387,8 +389,10 @@ async def stream_response( await self._maybe_aclose_async_iterator(stream) except Exception as exc: if yielded_terminal_event: - logger.debug( - "Ignoring stream cleanup error after terminal event: %s", exc + log_model_action_debug( + logger, + "Ignoring stream cleanup error after terminal event", + exc, ) else: raise diff --git a/src/agents/models/openai_responses.py b/src/agents/models/openai_responses.py index 55c78d0245..ff17cea4a0 100644 --- a/src/agents/models/openai_responses.py +++ b/src/agents/models/openai_responses.py @@ -50,7 +50,7 @@ from ..exceptions import ModelBehaviorError, UserError from ..handoffs import Handoff from ..items import ItemHelpers, ModelResponse, TResponseInputItem -from ..logger import logger +from ..logger import log_model_action_debug, log_model_action_error, logger from ..model_settings import MCPToolChoice from ..retry import ModelRetryAdvice, ModelRetryAdviceRequest from ..tool import ( @@ -300,7 +300,9 @@ async def _cleanup_after_exhaustion(self) -> None: await self._cleanup_once() except Exception as exc: if self._yielded_terminal_event: - logger.debug("Ignoring stream cleanup error after terminal event: %s", exc) + log_model_action_debug( + logger, "Ignoring stream cleanup error after terminal event", exc + ) return raise @@ -452,7 +454,9 @@ def _consume_background_cleanup_task_result(task: asyncio.Task[Any]) -> None: except asyncio.CancelledError: pass except Exception as exc: - logger.debug("Background stream cleanup failed after cancellation: %s", exc) + log_model_action_debug( + logger, "Background stream cleanup failed after cancellation", exc + ) async def get_response( self, @@ -506,19 +510,16 @@ async def get_response( SpanError( message="Error getting response", data={ - "error": str(e) if tracing.include_data() else e.__class__.__name__, + "error": str(e) + if tracing.include_data() + else "Error details are redacted.", }, ) ) - request_id = getattr(e, "request_id", None) - if _debug.DONT_LOG_MODEL_DATA: - logger.error( - "Error getting response: %s. (request_id: %s)", - e.__class__.__name__, - request_id, - ) - else: - logger.error("Error getting response: %s. (request_id: %s)", e, request_id) + message = "Error getting response" + if not _debug.DONT_LOG_MODEL_DATA: + message = f"{message} (request_id: {getattr(e, 'request_id', None)})" + log_model_action_error(logger, message, e) raise return ModelResponse( @@ -603,8 +604,10 @@ async def stream_response( await self._maybe_aclose_async_iterator(stream) except Exception as exc: if yielded_terminal_event: - logger.debug( - "Ignoring stream cleanup error after terminal event: %s", exc + log_model_action_debug( + logger, + "Ignoring stream cleanup error after terminal event", + exc, ) else: raise @@ -624,14 +627,13 @@ async def stream_response( SpanError( message="Error streaming response", data={ - "error": str(e) if tracing.include_data() else e.__class__.__name__, + "error": str(e) + if tracing.include_data() + else "Error details are redacted.", }, ) ) - if _debug.DONT_LOG_MODEL_DATA: - logger.error("Error streaming response: %s", e.__class__.__name__) - else: - logger.error("Error streaming response: %s", e) + log_model_action_error(logger, "Error streaming response", e) raise @overload diff --git a/src/agents/realtime/agent.py b/src/agents/realtime/agent.py index 38c77619cc..fe2f9e7200 100644 --- a/src/agents/realtime/agent.py +++ b/src/agents/realtime/agent.py @@ -8,6 +8,7 @@ from agents.prompts import Prompt +from .. import _debug from ..agent import AgentBase from ..guardrail import OutputGuardrail from ..handoffs import Handoff @@ -125,6 +126,11 @@ async def get_system_prompt(self, run_context: RunContextWrapper[TContext]) -> s else: return cast(str, self.instructions(run_context, self)) elif self.instructions is not None: - logger.error("Instructions must be a string or a function, got %s", self.instructions) + if _debug.DONT_LOG_MODEL_DATA: + logger.error("Instructions must be a string or a function") + else: + logger.error( + "Instructions must be a string or a function, got %s", self.instructions + ) return None diff --git a/src/agents/realtime/openai_realtime.py b/src/agents/realtime/openai_realtime.py index 7623c7ee18..f36aafffa4 100644 --- a/src/agents/realtime/openai_realtime.py +++ b/src/agents/realtime/openai_realtime.py @@ -199,7 +199,9 @@ def _server_event_validation_summary(error: BaseException) -> str: if isinstance(error, pydantic.ValidationError): return f"{error.error_count()} validation error(s)" - return error.__class__.__name__ + if not _debug.DONT_LOG_MODEL_DATA: + return type(error).__name__ + return "validation failed" def _server_event_identity(event: Any) -> tuple[Any, Any]: diff --git a/src/agents/realtime/session.py b/src/agents/realtime/session.py index 66dc72be5b..0a985c0387 100644 --- a/src/agents/realtime/session.py +++ b/src/agents/realtime/session.py @@ -5,11 +5,13 @@ import inspect import json from collections.abc import AsyncIterator, Sequence +from functools import partial from typing import Any, cast from pydantic import BaseModel from typing_extensions import assert_never +from .. import _debug from .._tool_identity import ( FunctionToolLookupKey, get_function_tool_lookup_key_for_tool, @@ -19,7 +21,12 @@ from ..exceptions import ToolInputGuardrailTripwireTriggered, UserError from ..handoffs import Handoff from ..items import ToolApprovalItem -from ..logger import logger +from ..logger import ( + log_model_action_error, + log_model_and_tool_action_warning, + log_tool_action_error, + logger, +) from ..run_config import ToolErrorFormatterArgs from ..run_context import RunContextWrapper, TContext from ..tool import DEFAULT_APPROVAL_REJECTION_MESSAGE, FunctionTool, Tool, invoke_function_tool @@ -86,6 +93,18 @@ class _RealtimeSessionClosedSentinel: _BACKGROUND_TASK_CANCEL_GRACE_SECONDS = 1.0 +def _guardrail_diagnostic_extra(guardrail: Any) -> dict[str, object]: + try: + return {"guardrail_name": guardrail.get_name()} + except Exception: + try: + guardrail_type = type(guardrail.guardrail_function) + type_name = f"{guardrail_type.__module__}.{guardrail_type.__qualname__}" + except Exception: + type_name = "unknown" + return {"guardrail_type": type_name} + + def _serialize_tool_output(output: Any) -> str: """Serialize structured tool outputs to JSON when possible.""" if isinstance(output, str): @@ -476,8 +495,8 @@ async def on_event(self, event: RealtimeModelEvent) -> None: if new_content: incoming_item = incoming_item.model_copy(update={"content": new_content}) - except Exception: - logger.error("Error merging transcripts", exc_info=True) + except Exception as exc: + log_model_action_error(logger, "Error merging transcripts", exc) pass self._history = self._get_new_history(self._history, incoming_item) @@ -810,18 +829,21 @@ async def _resolve_approval_rejection_message(self, *, tool: FunctionTool, call_ ) message = await maybe_message if inspect.isawaitable(maybe_message) else maybe_message except Exception as exc: - logger.error("Tool error formatter failed for %s: %s", tool.name, exc) + log_tool_action_error(logger, "Tool error formatter failed", exc) return REJECTION_MESSAGE if message is None: return REJECTION_MESSAGE if not isinstance(message, str): - logger.error( - "Tool error formatter returned non-string for %s: %s", - tool.name, - type(message).__name__, - ) + if _debug.DONT_LOG_TOOL_DATA: + logger.error("Tool error formatter returned a non-string value") + else: + logger.error( + "Tool error formatter returned non-string for %s: %s", + tool.name, + type(message).__name__, + ) return REJECTION_MESSAGE return message @@ -1312,13 +1334,12 @@ async def _run_output_guardrails(self, text: str, response_id: str) -> bool: if result.output.tripwire_triggered: triggered_results.append(result) except Exception as exc: - logger.warning( - "Output guardrail %r raised %s: %s; skipping it.", - guardrail.get_name(), - type(exc).__name__, + log_model_and_tool_action_warning( + logger, + "Output guardrail raised an exception; skipping it", exc, + diagnostic_extra=partial(_guardrail_diagnostic_extra, guardrail), ) - logger.debug("Output guardrail failure details.", exc_info=True) continue if triggered_results: @@ -1432,11 +1453,14 @@ def _on_tool_call_task_done(self, task: asyncio.Task[Any]) -> None: return if isinstance(exception, _PendingToolOutputSendError): - logger.warning( - "Realtime tool output send failed for call %s; cached output will be retried", - exception.call_id, - exc_info=exception, - ) + if _debug.DONT_LOG_TOOL_DATA: + logger.warning("Realtime tool output send failed; cached output will be retried") + else: + logger.warning( + "Realtime tool output send failed for call %s; cached output will be retried", + exception.call_id, + exc_info=exception, + ) self._put_event_nowait( RealtimeError( info=self._event_info, @@ -1449,7 +1473,7 @@ def _on_tool_call_task_done(self, task: asyncio.Task[Any]) -> None: ) return - logger.exception("Realtime tool call task failed", exc_info=exception) + log_tool_action_error(logger, "Realtime tool call task failed", exception) if self._stored_exception is None: self._stored_exception = exception diff --git a/src/agents/result.py b/src/agents/result.py index f63a8e7f68..7bccccec91 100644 --- a/src/agents/result.py +++ b/src/agents/result.py @@ -28,7 +28,7 @@ ToolApprovalItem, TResponseInputItem, ) -from .logger import logger +from .logger import log_tool_action_warning, logger from .run_context import RunContextWrapper from .run_internal.items import ( NestedHistoryOwnedItemRef, @@ -661,8 +661,10 @@ async def _cleanup_once() -> None: try: await sandbox_cleanup() except Exception as error: - logger.warning( - "Failed to clean up sandbox resources after streamed run: %s", error + log_tool_action_warning( + logger, + "Failed to clean up sandbox resources after streamed run", + error, ) task = asyncio.create_task(_cleanup_once()) diff --git a/src/agents/run.py b/src/agents/run.py index 04fe9c09a0..bb07bd2554 100644 --- a/src/agents/run.py +++ b/src/agents/run.py @@ -27,7 +27,7 @@ TResponseInputItem, ) from .lifecycle import RunHooks -from .logger import logger +from .logger import log_model_and_tool_action_warning, log_tool_action_warning, logger from .memory import Session from .result import RunResult, RunResultStreaming from .run_config import ( @@ -1606,10 +1606,14 @@ def _finalize_result(result: RunResult) -> RunResult: terminal_metadata=terminal_metadata_for_exception(run_exception), ) except Exception as error: - logger.warning("Failed to enqueue sandbox memory after run: %s", error) + log_model_and_tool_action_warning( + logger, "Failed to enqueue sandbox memory after run", error + ) sandbox_resume_state = await sandbox_runtime.cleanup() except Exception as error: - logger.warning("Failed to clean up sandbox resources after run: %s", error) + log_tool_action_warning( + logger, "Failed to clean up sandbox resources after run", error + ) else: if completed_result is not None: completed_result._sandbox_resume_state = sandbox_resume_state @@ -1619,7 +1623,7 @@ def _finalize_result(result: RunResult) -> RunResult: try: await dispose_resolved_computers(run_context=context_wrapper) except Exception as error: - logger.warning("Failed to dispose computers after run: %s", error) + log_tool_action_warning(logger, "Failed to dispose computers after run", error) if current_span: current_span.finish(reset_current=True) if current_task_span: diff --git a/src/agents/run_internal/model_retry.py b/src/agents/run_internal/model_retry.py index aa41d07e6b..4e37139329 100644 --- a/src/agents/run_internal/model_retry.py +++ b/src/agents/run_internal/model_retry.py @@ -10,7 +10,7 @@ from openai import APIConnectionError, APITimeoutError, BadRequestError from ..items import ModelResponse, TResponseStreamEvent -from ..logger import logger +from ..logger import log_model_action_debug, logger from ..models._retry_runtime import ( get_error_code as _get_error_code, get_request_id as _get_request_id, @@ -246,7 +246,7 @@ async def _close_async_iterator_quietly(iterator: Any | None) -> None: try: await _close_async_iterator(iterator) except Exception as exc: - logger.debug("Ignoring retry stream cleanup error: %s", exc) + log_model_action_debug(logger, "Ignoring retry stream cleanup error", exc) def _get_stream_event_type(event: TResponseStreamEvent) -> str | None: diff --git a/src/agents/run_internal/run_loop.py b/src/agents/run_internal/run_loop.py index fa60d2299e..4873ed542d 100644 --- a/src/agents/run_internal/run_loop.py +++ b/src/agents/run_internal/run_loop.py @@ -9,6 +9,7 @@ import dataclasses as _dc import json from collections.abc import Awaitable, Callable, Mapping +from functools import partial from typing import Any, TypeVar, cast from openai.types.responses import ( @@ -56,7 +57,13 @@ coerce_tool_search_output_raw_item, ) from ..lifecycle import RunHooks -from ..logger import logger +from ..logger import ( + log_model_action_error, + log_model_action_warning, + log_model_and_tool_action_debug, + log_tool_action_warning, + logger, +) from ..memory import Session from ..models._response_terminal import ( response_error_event_failure_error, @@ -270,7 +277,11 @@ async def cleanup_models_after_run(tool_use_tracker: AgentToolUseTracker) -> Non try: await model._cleanup_on_run_end(tool_use_tracker) except Exception as error: - logger.warning("Failed to clean up model resources after run: %s", error) + log_model_action_warning(logger, "Failed to clean up model resources after run", error) + + +def _agent_diagnostic_extra(agent: Agent[Any]) -> dict[str, object]: + return {"agent_name": agent.name} def _should_attach_generic_agent_error(exc: Exception) -> bool: @@ -398,8 +409,8 @@ async def _run_output_guardrails_for_stream( raise except asyncio.CancelledError: raise - except Exception: - logger.error("Unexpected error in output guardrails", exc_info=True) + except Exception as exc: + log_model_action_error(logger, "Unexpected error in output guardrails", exc) raise @@ -1302,13 +1313,16 @@ async def _save_stream_items_without_count( if first_trigger is not None: raise InputGuardrailTripwireTriggered(first_trigger) except Exception as e: - logger.debug( - "Error in streamed_result finalize for agent %s - %s", current_agent.name, e + log_model_and_tool_action_debug( + logger, + "Error finalizing streamed result", + e, + diagnostic_extra=partial(_agent_diagnostic_extra, current_agent), ) try: await dispose_resolved_computers(run_context=context_wrapper) except Exception as error: - logger.warning("Failed to dispose computers after streamed run: %s", error) + log_tool_action_warning(logger, "Failed to dispose computers after streamed run", error) if current_span: current_span.finish(reset_current=True) if current_task_span: diff --git a/src/agents/run_internal/session_persistence.py b/src/agents/run_internal/session_persistence.py index 2c599445e7..b4c98d2747 100644 --- a/src/agents/run_internal/session_persistence.py +++ b/src/agents/run_internal/session_persistence.py @@ -13,9 +13,14 @@ from collections.abc import Sequence from typing import Any, cast +from .. import _debug from ..exceptions import UserError from ..items import HandoffOutputItem, ItemHelpers, RunItem, ToolCallOutputItem, TResponseInputItem -from ..logger import logger +from ..logger import ( + log_model_and_tool_action_debug, + log_model_and_tool_action_warning, + logger, +) from ..memory import ( OpenAIResponsesCompactionArgs, Session, @@ -542,8 +547,9 @@ async def rewind_session_items( len(target_serializations), ) - for i, target in enumerate(target_serializations): - logger.debug("Rewind target %d (first 300 chars): %s", i, target[:300]) + if not (_debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA): + for i, target in enumerate(target_serializations): + logger.debug("Rewind target %d (first 300 chars): %s", i, target[:300]) snapshot_serializations = target_serializations.copy() rewound = await _rewind_session_tail_suffix( @@ -554,7 +560,7 @@ async def rewind_session_items( mismatch_warning=( "Skipping session rewind because the current tail does not match the retry-owned suffix" ), - pop_failure_warning="Failed to rewind session item: %s", + pop_failure_warning="Failed to rewind session item", ) if not rewound: return @@ -571,7 +577,7 @@ async def rewind_session_items( try: latest_items = await session.get_items(limit=1) except Exception as exc: - logger.debug("Failed to peek session items while rewinding: %s", exc) + log_model_and_tool_action_debug(logger, "Failed to peek session items while rewinding", exc) return if not latest_items: @@ -584,7 +590,9 @@ async def rewind_session_items( try: session_items = await session.get_items() except Exception as exc: - logger.debug("Failed to inspect session tail while stripping stray items: %s", exc) + log_model_and_tool_action_debug( + logger, "Failed to inspect session tail while stripping stray items", exc + ) return stray_serializations = _collect_retry_owned_tail_serializations( @@ -609,7 +617,7 @@ async def rewind_session_items( "Skipping stray session cleanup because the current tail no longer matches " "retry-owned conversation items" ), - pop_failure_warning="Failed to strip stray session item: %s", + pop_failure_warning="Failed to strip stray session item", ) @@ -633,7 +641,9 @@ async def wait_for_session_cleanup( try: tail_items = await session.get_items(limit=window) except Exception as exc: - logger.debug("Failed to verify session cleanup (attempt %d): %s", attempt + 1, exc) + log_model_and_tool_action_debug( + logger, f"Failed to verify session cleanup (attempt {attempt + 1})", exc + ) await asyncio.sleep(0.1 * (attempt + 1)) continue @@ -764,7 +774,7 @@ async def _rewind_session_tail_suffix( try: tail_items = await session.get_items(limit=len(expected_serializations)) except Exception as exc: - logger.warning(pop_failure_warning, exc) + log_model_and_tool_action_warning(logger, pop_failure_warning, exc) return False if len(tail_items) != len(expected_serializations): @@ -791,7 +801,7 @@ async def _rewind_session_tail_suffix( result = await result except Exception as exc: await _restore_popped_session_items(session, popped_items) - logger.warning(pop_failure_warning, exc) + log_model_and_tool_action_warning(logger, pop_failure_warning, exc) return False if result is None: @@ -827,7 +837,9 @@ async def _restore_popped_session_items( if inspect.isawaitable(result): await result except Exception as exc: - logger.warning("Failed to restore session items after a rewind mismatch: %s", exc) + log_model_and_tool_action_warning( + logger, "Failed to restore session items after a rewind mismatch", exc + ) def _collect_retry_owned_tail_serializations( diff --git a/src/agents/run_internal/tool_execution.py b/src/agents/run_internal/tool_execution.py index 3eea93d8d6..c38bdfe4e5 100644 --- a/src/agents/run_internal/tool_execution.py +++ b/src/agents/run_internal/tool_execution.py @@ -58,7 +58,7 @@ ToolApprovalItem, ToolCallOutputItem, ) -from ..logger import logger +from ..logger import log_tool_action_error as _log_tool_action_error, logger from ..model_settings import ModelSettings from ..run_config import RunConfig, ToolErrorFormatterArgs from ..run_context import RunContextWrapper @@ -1041,17 +1041,29 @@ def format_shell_error(error: Exception | BaseException | Any) -> str: return repr(error) -def log_tool_action_error(message: str, exc: Exception | BaseException) -> None: +def _tool_name_diagnostic_extra(tool_name: str) -> dict[str, object]: + return {"tool_name": tool_name} + + +def log_tool_action_error( + message: str, + exc: Exception | BaseException, + *, + diagnostic_extra: Callable[[], Mapping[str, object]] | None = None, +) -> None: """Log a tool-action failure without leaking tool data. Tool exceptions can embed tool call arguments or output, so the exception is redacted by default (matching ``_debug.DONT_LOG_TOOL_DATA``). The full exception and traceback are logged only when tool-data logging is explicitly enabled. """ - if _debug.DONT_LOG_TOOL_DATA: - logger.error("%s: %s", message, exc.__class__.__name__) - else: - logger.error("%s: %s", message, exc, exc_info=True) + _log_tool_action_error( + logger, + message, + exc, + stacklevel=4, + diagnostic_extra=diagnostic_extra, + ) async def with_tool_function_span( @@ -1201,18 +1213,25 @@ async def resolve_approval_rejection_message( ) message = await maybe_message if inspect.isawaitable(maybe_message) else maybe_message except Exception as exc: - log_tool_action_error(f"Tool error formatter failed for {tool_name}", exc) + log_tool_action_error( + "Tool error formatter failed", + exc, + diagnostic_extra=functools.partial(_tool_name_diagnostic_extra, tool_name), + ) return REJECTION_MESSAGE if message is None: return REJECTION_MESSAGE if not isinstance(message, str): - logger.error( - "Tool error formatter returned non-string for %s: %s", - tool_name, - type(message).__name__, - ) + if _debug.DONT_LOG_TOOL_DATA: + logger.error("Tool error formatter returned a non-string value") + else: + logger.error( + "Tool error formatter returned non-string for %s: %s", + tool_name, + type(message).__name__, + ) return REJECTION_MESSAGE return message diff --git a/src/agents/run_internal/turn_resolution.py b/src/agents/run_internal/turn_resolution.py index f275f2e857..2f54478e32 100644 --- a/src/agents/run_internal/turn_resolution.py +++ b/src/agents/run_internal/turn_resolution.py @@ -29,6 +29,7 @@ ) from openai.types.responses.response_reasoning_item import ResponseReasoningItem +from .. import _debug from .._mcp_tool_metadata import collect_mcp_list_tools_metadata from .._tool_identity import ( build_function_tool_lookup_map, @@ -72,7 +73,7 @@ coerce_tool_search_output_raw_item, ) from ..lifecycle import RunHooks -from ..logger import logger +from ..logger import log_tool_action_error, logger from ..run_config import RunConfig, ToolErrorFormatterArgs from ..run_context import AgentHookContext, RunContextWrapper, TContext from ..run_error_handlers import RunErrorHandlers @@ -252,18 +253,21 @@ async def _resolve_tool_not_found_message( ) message = await maybe_message if inspect.isawaitable(maybe_message) else maybe_message except Exception as exc: - logger.error("Tool error formatter failed for missing tool %s: %s", tool_name, exc) + log_tool_action_error(logger, "Tool error formatter failed for missing tool", exc) return default_message if message is None: return default_message if not isinstance(message, str): - logger.error( - "Tool error formatter returned non-string for missing tool %s: %s", - tool_name, - type(message).__name__, - ) + if _debug.DONT_LOG_TOOL_DATA: + logger.error("Tool error formatter returned a non-string value for a missing tool") + else: + logger.error( + "Tool error formatter returned non-string for missing tool %s: %s", + tool_name, + type(message).__name__, + ) return default_message return message diff --git a/src/agents/run_state.py b/src/agents/run_state.py index 41c2d6f018..ef9cdc6c76 100644 --- a/src/agents/run_state.py +++ b/src/agents/run_state.py @@ -81,7 +81,7 @@ coerce_tool_search_call_raw_item, coerce_tool_search_output_raw_item, ) -from .logger import logger +from .logger import log_model_and_tool_action_warning, logger from .run_context import RunContextWrapper from .run_internal.items import ( NestedHistoryOwnedItemRef, @@ -3752,7 +3752,9 @@ def _resolve_agent_info( except UserError: raise except Exception as e: - logger.warning("Failed to deserialize item of type %s: %s", item_type, e) + log_model_and_tool_action_warning( + logger, f"Failed to deserialize item of type {item_type}", e + ) continue return result diff --git a/src/agents/sandbox/memory/manager.py b/src/agents/sandbox/memory/manager.py index 28025466dc..9919d8035b 100644 --- a/src/agents/sandbox/memory/manager.py +++ b/src/agents/sandbox/memory/manager.py @@ -10,6 +10,7 @@ from ...exceptions import UserError from ...items import TResponseInputItem +from ...logger import log_model_and_tool_action_error from ...run_config import RunConfig, SandboxRunConfig from ..capabilities.memory import Memory from ..config import MemoryGenerateConfig @@ -150,8 +151,8 @@ async def _worker(self) -> None: if queue_item is _STOP: return await self._process_rollout_file(str(queue_item)) - except Exception: - logger.exception("Sandbox memory worker failed") + except Exception as exc: + log_model_and_tool_action_error(logger, "Sandbox memory worker failed", exc) finally: self._queue.task_done() @@ -227,8 +228,8 @@ async def _run_phase_two(self) -> None: selection=selection, run_config=self._memory_run_config(), ) - except Exception: - logger.exception("Sandbox memory phase 2 failed") + except Exception as exc: + log_model_and_tool_action_error(logger, "Sandbox memory phase 2 failed", exc) return await self._storage.write_phase_two_selection(selected_items=selection.selected) self._pending_phase_two_rollout_ids = [ diff --git a/src/agents/sandbox/runtime.py b/src/agents/sandbox/runtime.py index d273a54411..0378323a63 100644 --- a/src/agents/sandbox/runtime.py +++ b/src/agents/sandbox/runtime.py @@ -9,6 +9,7 @@ from ..agent import Agent from ..exceptions import UserError from ..items import TResponseInputItem +from ..logger import log_model_and_tool_action_warning from ..result import RunResult, RunResultStreaming from ..run_config import RunConfig from ..run_context import RunContextWrapper, TContext @@ -106,8 +107,10 @@ async def _cleanup_and_store() -> None: input_override=_stream_memory_input_override(result), ) except Exception as error: - logger.warning( - "Failed to enqueue sandbox memory after streamed run: %s", error + log_model_and_tool_action_warning( + logger, + "Failed to enqueue sandbox memory after streamed run", + error, ) payload = await self.cleanup() result._sandbox_resume_state = payload diff --git a/src/agents/sandbox/sandboxes/unix_local.py b/src/agents/sandbox/sandboxes/unix_local.py index a6aff578b9..a2bfeac2ba 100644 --- a/src/agents/sandbox/sandboxes/unix_local.py +++ b/src/agents/sandbox/sandboxes/unix_local.py @@ -24,9 +24,11 @@ from collections.abc import Mapping, Sequence from contextlib import suppress from dataclasses import dataclass, field +from functools import partial from pathlib import Path from typing import Literal, cast +from ...logger import log_tool_action_warning from ..errors import ( ExecNonZeroError, ExecTimeoutError, @@ -75,6 +77,10 @@ logger = logging.getLogger(__name__) +def _mount_path_diagnostic_extra(mount_path: Path) -> dict[str, object]: + return {"mount_path": str(mount_path)} + + def _close_fd_quietly(fd: int) -> None: with suppress(OSError): os.close(fd) @@ -1129,12 +1135,13 @@ async def delete(self, session: SandboxSession) -> SandboxSession: for mount_entry, mount_path in inner.state.manifest.ephemeral_mount_targets(): try: await mount_entry.unmount(inner, mount_path, Path("/")) - except Exception: + except Exception as exc: unmount_failed = True - logger.warning( - "Failed to unmount UnixLocal workspace mount before deleting root: %s", - mount_path, - exc_info=True, + log_tool_action_warning( + logger, + "Failed to unmount UnixLocal workspace mount before deleting root", + exc, + diagnostic_extra=partial(_mount_path_diagnostic_extra, mount_path), ) if unmount_failed: return session diff --git a/src/agents/sandbox/session/manager.py b/src/agents/sandbox/session/manager.py index 125765e65b..1248ce19b9 100644 --- a/src/agents/sandbox/session/manager.py +++ b/src/agents/sandbox/session/manager.py @@ -4,6 +4,7 @@ import logging from collections.abc import Sequence +from ...logger import log_tool_action_error from ..errors import OpName from .events import EventPayloadPolicy, SandboxSessionEvent, SandboxSessionFinishEvent from .sinks import ChainedSink, EventSink @@ -104,8 +105,8 @@ async def _run() -> None: if sink.mode == "sync": try: await _run() - except Exception: - self._handle_sink_error(sink, event) + except Exception as exc: + self._handle_sink_error(sink, event, exc) elif sink.mode == "async": if sink.on_error == "raise": await _run() @@ -114,8 +115,8 @@ async def _run() -> None: async def _task() -> None: try: await _run() - except Exception: - self._handle_sink_error(sink, event) + except Exception as exc: + self._handle_sink_error(sink, event, exc) task = asyncio.create_task(_task()) # Track background deliveries so the task is kept alive and can be discarded once done. @@ -126,8 +127,8 @@ async def _task() -> None: async def _task() -> None: try: await _run() - except Exception: - self._handle_sink_error(sink, event, force_no_raise=True) + except Exception as exc: + self._handle_sink_error(sink, event, exc, force_no_raise=True) task = asyncio.create_task(_task()) # Same bookkeeping as async mode, but failures are always swallowed after logging. @@ -146,16 +147,26 @@ async def _deliver_chained(self, sink: EventSink, event: SandboxSessionEvent) -> """ try: await sink.handle(event) - except Exception: + except Exception as exc: force_no_raise = sink.mode == "best_effort" - self._handle_sink_error(sink, event, force_no_raise=force_no_raise) + self._handle_sink_error(sink, event, exc, force_no_raise=force_no_raise) def _handle_sink_error( - self, sink: EventSink, event: SandboxSessionEvent, *, force_no_raise: bool = False + self, + sink: EventSink, + event: SandboxSessionEvent, + exc: Exception, + *, + force_no_raise: bool = False, ) -> None: if force_no_raise or sink.on_error in ("log", "ignore"): if sink.on_error == "log": - logger.exception("sandbox event sink failed (ignored): %s", type(sink).__name__) + log_tool_action_error( + logger, + "Sandbox event sink failed (ignored)", + exc, + diagnostic_extra=lambda: {"sink_type": type(sink).__name__}, + ) return raise RuntimeError( "sandbox event sink failed: " diff --git a/src/agents/tool.py b/src/agents/tool.py index af9a6c3c5c..eb6c0a3645 100644 --- a/src/agents/tool.py +++ b/src/agents/tool.py @@ -54,7 +54,7 @@ from .editor import ApplyPatchEditor, ApplyPatchOperation from .exceptions import ModelBehaviorError, ToolTimeoutError, UserError from .function_schema import DocstringStyle, function_schema -from .logger import logger +from .logger import log_tool_action_warning, logger from .run_context import RunContextWrapper from .strict_schema import ensure_strict_json_schema from .tool_context import ToolContext @@ -885,7 +885,7 @@ async def dispose_resolved_computers(*, run_context: RunContextWrapper[Any]) -> if inspect.isawaitable(result): await result except Exception as exc: - logger.warning("Failed to dispose computer for run context: %s", exc) + log_tool_action_warning(logger, "Failed to dispose computer for run context", exc) @dataclass diff --git a/src/agents/tracing/processors.py b/src/agents/tracing/processors.py index 776939a180..6c68a2673f 100644 --- a/src/agents/tracing/processors.py +++ b/src/agents/tracing/processors.py @@ -13,7 +13,12 @@ import httpx -from ..logger import logger +from .. import _debug +from ..logger import ( + log_model_and_tool_action_error, + log_model_and_tool_action_warning, + logger, +) from .processor_interface import TracingExporter, TracingProcessor from .spans import Span from .traces import Trace @@ -24,6 +29,12 @@ class ConsoleSpanExporter(TracingExporter): def export(self, items: list[Trace | Span[Any]]) -> None: for item in items: + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + if isinstance(item, Trace): + print("[Exporter] Export trace. Trace data is redacted.") + else: + print("[Exporter] Export span. Span data is redacted.") + continue if isinstance(item, Trace): print(f"[Exporter] Export trace_id={item.trace_id}, name={item.name}") else: @@ -173,11 +184,17 @@ def _export_with_deadline(self, items: list[Trace | Span[Any]], deadline: float # If the response is a client error (4xx), we won't retry if 400 <= response.status_code < 500: - logger.error( - "[non-fatal] Tracing client error %s: %s", - response.status_code, - response.text, - ) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.error( + "[non-fatal] Tracing client error %s. Response data is redacted.", + response.status_code, + ) + else: + logger.error( + "[non-fatal] Tracing client error %s: %s", + response.status_code, + response.text, + ) break # For 5xx or other unexpected codes, treat it as transient and retry @@ -186,7 +203,9 @@ def _export_with_deadline(self, items: list[Trace | Span[Any]], deadline: float ) except httpx.RequestError as exc: # Network or other I/O error, we'll retry - logger.warning("[non-fatal] Tracing: request failed: %s", exc) + log_model_and_tool_action_warning( + logger, "[non-fatal] Tracing request failed", exc + ) # If we reach here, we need to retry or give up if attempt >= self.max_retries: @@ -690,10 +709,13 @@ def _export_batches(self, force: bool = False, deadline: float | None = None): else: self._exporter.export(items_to_export) except Exception as exc: - logger.error( - "[non-fatal] Tracing: exporter raised %s; dropping batch of %d items", + log_model_and_tool_action_error( + logger, + ( + "[non-fatal] Tracing exporter failed; " + f"dropping batch of {len(items_to_export)} items" + ), exc, - len(items_to_export), ) diff --git a/src/agents/tracing/provider.py b/src/agents/tracing/provider.py index a5f439dceb..57817642f8 100644 --- a/src/agents/tracing/provider.py +++ b/src/agents/tracing/provider.py @@ -6,11 +6,14 @@ import time import uuid from abc import ABC, abstractmethod +from collections.abc import Callable from datetime import datetime, timezone +from functools import partial from inspect import Parameter, signature from typing import Any, cast -from ..logger import logger +from .. import _debug +from ..logger import log_model_and_tool_action_error, logger from .config import TracingConfig from .processor_interface import TracingProcessor from .scope import Scope @@ -18,7 +21,7 @@ from .traces import NoOpTrace, Trace, TraceImpl -def _safe_debug(message: str) -> None: +def _safe_debug(message: str | Callable[[], str]) -> None: """Best-effort debug logging that tolerates closed streams during shutdown.""" def _has_closed_stream_handler(log: logging.Logger) -> bool: @@ -37,12 +40,24 @@ def _has_closed_stream_handler(log: logging.Logger) -> bool: # Avoid emitting debug logs when any handler already owns a closed stream. if _has_closed_stream_handler(logger): return - logger.debug(message) + logger.debug(message() if callable(message) else message) except Exception: # Avoid noisy shutdown errors when the underlying stream is already closed. return +def _processor_diagnostic_extra(processor: TracingProcessor) -> dict[str, object]: + processor_type = type(processor) + processor_identity = ( + f"{processor_type.__module__}.{processor_type.__qualname__}@{id(processor):x}" + ) + return {"trace_processor": processor_identity} + + +def _processor_shutdown_message(processor: TracingProcessor) -> str: + return f"Shutting down trace processor {processor}" + + def _remaining_timeout(deadline: float | None) -> float | None: if deadline is None: return None @@ -107,7 +122,12 @@ def on_trace_start(self, trace: Trace) -> None: try: processor.on_trace_start(trace) except Exception as e: - logger.error("Error in trace processor %s during on_trace_start: %s", processor, e) + log_model_and_tool_action_error( + logger, + "Error in trace processor during on_trace_start", + e, + diagnostic_extra=partial(_processor_diagnostic_extra, processor), + ) def on_trace_end(self, trace: Trace) -> None: """ @@ -117,7 +137,12 @@ def on_trace_end(self, trace: Trace) -> None: try: processor.on_trace_end(trace) except Exception as e: - logger.error("Error in trace processor %s during on_trace_end: %s", processor, e) + log_model_and_tool_action_error( + logger, + "Error in trace processor during on_trace_end", + e, + diagnostic_extra=partial(_processor_diagnostic_extra, processor), + ) def on_span_start(self, span: Span[Any]) -> None: """ @@ -127,7 +152,12 @@ def on_span_start(self, span: Span[Any]) -> None: try: processor.on_span_start(span) except Exception as e: - logger.error("Error in trace processor %s during on_span_start: %s", processor, e) + log_model_and_tool_action_error( + logger, + "Error in trace processor during on_span_start", + e, + diagnostic_extra=partial(_processor_diagnostic_extra, processor), + ) def on_span_end(self, span: Span[Any]) -> None: """ @@ -137,7 +167,12 @@ def on_span_end(self, span: Span[Any]) -> None: try: processor.on_span_end(span) except Exception as e: - logger.error("Error in trace processor %s during on_span_end: %s", processor, e) + log_model_and_tool_action_error( + logger, + "Error in trace processor during on_span_end", + e, + diagnostic_extra=partial(_processor_diagnostic_extra, processor), + ) def shutdown(self, timeout: float | None = None) -> None: """ @@ -145,7 +180,10 @@ def shutdown(self, timeout: float | None = None) -> None: """ deadline = None if timeout is None else time.monotonic() + timeout for processor in self._processors: - _safe_debug(f"Shutting down trace processor {processor}") + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + _safe_debug("Shutting down trace processor") + else: + _safe_debug(partial(_processor_shutdown_message, processor)) try: processor_timeout = _remaining_timeout(deadline) if processor_timeout is not None and processor_timeout <= 0: @@ -158,7 +196,12 @@ def shutdown(self, timeout: float | None = None) -> None: else: processor.shutdown() except Exception as e: - logger.error("Error shutting down trace processor %s: %s", processor, e) + log_model_and_tool_action_error( + logger, + "Error shutting down trace processor", + e, + diagnostic_extra=partial(_processor_diagnostic_extra, processor), + ) def force_flush(self): """ @@ -168,7 +211,12 @@ def force_flush(self): try: processor.force_flush() except Exception as e: - logger.error("Error flushing trace processor %s: %s", processor, e) + log_model_and_tool_action_error( + logger, + "Error flushing trace processor", + e, + diagnostic_extra=partial(_processor_diagnostic_extra, processor), + ) class TraceProvider(ABC): @@ -337,12 +385,18 @@ def create_trace( """ self._refresh_disabled_flag() if self._disabled or disabled: - logger.debug("Tracing is disabled. Not creating trace %s", name) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.debug("Tracing is disabled. Not creating trace") + else: + logger.debug("Tracing is disabled. Not creating trace %s", name) return NoOpTrace() trace_id = trace_id or self.gen_trace_id() - logger.debug("Creating trace %s with id %s", name, trace_id) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.debug("Creating trace with id %s", trace_id) + else: + logger.debug("Creating trace %s with id %s", name, trace_id) return TraceImpl( name=name, @@ -367,7 +421,10 @@ def create_span( tracing_api_key: str | None = None trace_metadata: dict[str, Any] | None = None if self._disabled or disabled: - logger.debug("Tracing is disabled. Not creating span %s", span_data) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.debug("Tracing is disabled. Not creating span") + else: + logger.debug("Tracing is disabled. Not creating span %s", span_data) return NoOpSpan(span_data) if _is_noop_id(span_id): logger.debug("Span id is no-op, returning NoOpSpan") @@ -383,9 +440,14 @@ def create_span( ) return NoOpSpan(span_data) elif _is_noop_trace(current_trace) or _is_noop_span(current_span): - logger.debug( - "Parent %s or %s is no-op, returning NoOpSpan", current_span, current_trace - ) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.debug("Current trace parent is no-op, returning NoOpSpan") + else: + logger.debug( + "Parent %s or %s is no-op, returning NoOpSpan", + current_span, + current_trace, + ) return NoOpSpan(span_data) parent_id = current_span.span_id if current_span else None @@ -396,7 +458,10 @@ def create_span( elif isinstance(parent, Trace): if _is_noop_trace(parent): - logger.debug("Parent %s is no-op, returning NoOpSpan", parent) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.debug("Parent trace is no-op, returning NoOpSpan") + else: + logger.debug("Parent %s is no-op, returning NoOpSpan", parent) return NoOpSpan(span_data) trace_id = parent.trace_id parent_id = None @@ -405,14 +470,20 @@ def create_span( trace_metadata = getattr(parent, "metadata", None) elif isinstance(parent, Span): if _is_noop_span(parent): - logger.debug("Parent %s is no-op, returning NoOpSpan", parent) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.debug("Parent span is no-op, returning NoOpSpan") + else: + logger.debug("Parent %s is no-op, returning NoOpSpan", parent) return NoOpSpan(span_data) parent_id = parent.span_id trace_id = parent.trace_id tracing_api_key = parent.tracing_api_key trace_metadata = parent.trace_metadata - logger.debug("Creating span %s with id %s", span_data, span_id) + if _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.debug("Creating span with id %s", span_id) + else: + logger.debug("Creating span %s with id %s", span_data, span_id) return SpanImpl( trace_id=trace_id, @@ -433,7 +504,7 @@ def force_flush(self) -> None: try: self._multi_processor.force_flush() except Exception as e: - logger.error("Error flushing trace provider: %s", e) + log_model_and_tool_action_error(logger, "Error flushing trace provider", e) def shutdown(self, timeout: float | None = None) -> None: self._refresh_disabled_flag() @@ -444,4 +515,4 @@ def shutdown(self, timeout: float | None = None) -> None: _safe_debug("Shutting down trace provider") self._multi_processor.shutdown(timeout=timeout) except Exception as e: - logger.error("Error shutting down trace provider: %s", e) + log_model_and_tool_action_error(logger, "Error shutting down trace provider", e) diff --git a/src/agents/util/_error_tracing.py b/src/agents/util/_error_tracing.py index 0bd2d99e90..7f714482a5 100644 --- a/src/agents/util/_error_tracing.py +++ b/src/agents/util/_error_tracing.py @@ -1,5 +1,6 @@ from typing import Any +from .. import _debug from ..logger import logger from ..tracing import Span, SpanError, get_current_span @@ -24,5 +25,7 @@ def attach_error_to_current_span(error: SpanError) -> None: span = get_current_span() if span: attach_error_to_span(span, error) + elif _debug.DONT_LOG_MODEL_DATA or _debug.DONT_LOG_TOOL_DATA: + logger.warning("No active span; trace error was not attached") else: logger.warning("No span to add error %s to", error) diff --git a/src/agents/voice/pipeline.py b/src/agents/voice/pipeline.py index 21220c9921..da2bdceafd 100644 --- a/src/agents/voice/pipeline.py +++ b/src/agents/voice/pipeline.py @@ -5,7 +5,11 @@ from .._config_coercion import coerce_dataclass_config from ..exceptions import UserError -from ..logger import logger +from ..logger import ( + log_model_and_tool_action_error, + log_model_and_tool_action_warning, + logger, +) from ..tracing import TraceCtxManager from .input import AudioInput, StreamedAudioInput from .model import STTModel, TTSModel @@ -109,7 +113,7 @@ async def stream_events(): await output._turn_done() await output._done() except Exception as e: - logger.error("Error processing single turn: %s", e) + log_model_and_tool_action_error(logger, "Error processing single voice turn", e) await output._add_error(e) raise e @@ -135,7 +139,9 @@ async def process_turns(): async for intro_text in self.workflow.on_start(): await output._add_text(intro_text) except Exception as e: - logger.warning("on_start() failed: %s", e) + log_model_and_tool_action_warning( + logger, "Voice workflow on_start failed", e + ) transcription_session = await self._get_stt_model().create_session( audio_input, @@ -150,7 +156,7 @@ async def process_turns(): await output._add_text(text_event) await output._turn_done() except Exception as e: - logger.error("Error processing turns: %s", e) + log_model_and_tool_action_error(logger, "Error processing voice turns", e) await output._add_error(e) raise e finally: diff --git a/src/agents/voice/result.py b/src/agents/voice/result.py index 2f4b24433b..709c829779 100644 --- a/src/agents/voice/result.py +++ b/src/agents/voice/result.py @@ -7,7 +7,7 @@ from typing import Any from ..exceptions import UserError -from ..logger import logger +from ..logger import log_model_action_error, log_model_and_tool_action_error, logger from ..tracing import Span, SpeechGroupSpanData, speech_group_span, speech_span from ..tracing.util import time_iso from ..util._error_tracing import get_trace_error @@ -192,7 +192,7 @@ async def _stream_audio( }, } ) - logger.error("Error streaming audio: %s", e) + log_model_action_error(logger, "Error streaming voice audio", e) # Signal completion for whole session because of error await local_queue.put(VoiceStreamEventLifecycle(event="session_ended")) @@ -308,7 +308,9 @@ async def stream(self) -> AsyncIterator[VoiceStreamEvent]: break if isinstance(event, VoiceStreamEventError): self._stored_exception = event.error - logger.error("Error processing output: %s", event.error) + log_model_and_tool_action_error( + logger, "Error processing voice output", event.error + ) break if event is None: break diff --git a/tests/extensions/experiemental/codex/test_codex_tool.py b/tests/extensions/experiemental/codex/test_codex_tool.py index 9bf650816b..3aeb7db73d 100644 --- a/tests/extensions/experiemental/codex/test_codex_tool.py +++ b/tests/extensions/experiemental/codex/test_codex_tool.py @@ -14,6 +14,7 @@ from openai.types.responses import ResponseFunctionToolCall from pydantic import BaseModel, ConfigDict +import agents._debug as _debug from agents import Agent, function_tool from agents.exceptions import ModelBehaviorError, UserError from agents.extensions.experimental.codex import ( @@ -1802,7 +1803,13 @@ async def test_replaced_codex_tool_preserves_codex_collision_markers() -> None: @pytest.mark.asyncio -async def test_codex_tool_consume_events_with_on_stream_error() -> None: +async def test_codex_tool_consume_events_with_on_stream_error( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", True) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", False) + secret = "SECRET_CODEX_STREAM_PAYLOAD" events = [ { "type": "item.started", @@ -1865,7 +1872,7 @@ async def event_stream(): def on_stream(payload: CodexToolStreamEvent) -> None: callbacks.append(payload.event.type) if payload.event.type == "item.started": - raise RuntimeError("boom") + raise RuntimeError(secret) context = ToolContext( context=None, @@ -1874,20 +1881,22 @@ def on_stream(payload: CodexToolStreamEvent) -> None: tool_arguments="{}", ) - with trace("codex-test"): - response, usage, thread_id = await codex_tool_module._consume_events( - event_stream(), - {"inputs": [{"type": "text", "text": "hello"}]}, - context, - SimpleNamespace(id="thread-1"), - on_stream, - 64, - ) + with caplog.at_level("ERROR", logger="openai.agents"): + with trace("codex-test"): + response, usage, thread_id = await codex_tool_module._consume_events( + event_stream(), + {"inputs": [{"type": "text", "text": "hello"}]}, + context, + SimpleNamespace(id="thread-1"), + on_stream, + 64, + ) assert response == "done" assert usage == Usage(input_tokens=1, cached_input_tokens=0, output_tokens=1) assert thread_id == "thread-1" assert "item.started" in callbacks + assert secret not in caplog.text @pytest.mark.asyncio diff --git a/tests/extensions/memory/test_advanced_sqlite_session.py b/tests/extensions/memory/test_advanced_sqlite_session.py index 2472a8bf12..1e1973ba39 100644 --- a/tests/extensions/memory/test_advanced_sqlite_session.py +++ b/tests/extensions/memory/test_advanced_sqlite_session.py @@ -3,17 +3,19 @@ import asyncio import contextlib import json +import logging import tempfile import threading from pathlib import Path from typing import Any, cast -from unittest.mock import patch +from unittest.mock import Mock, patch import pytest pytest.importorskip("sqlalchemy") # Skip tests if SQLAlchemy is not installed from openai.types.responses.response_usage import InputTokensDetails, OutputTokensDetails +import agents._debug as _debug from agents import Agent, Runner, TResponseInputItem, function_tool from agents.extensions.memory import AdvancedSQLiteSession from agents.result import RunResult @@ -154,6 +156,32 @@ async def test_advanced_session_basic_functionality(agent: Agent): session.close() +@pytest.mark.parametrize("redacted", [True, False]) +async def test_create_branch_logging_respects_model_data_policy(monkeypatch, redacted: bool): + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", redacted) + mock_logger = Mock() + session = AdvancedSQLiteSession( + session_id="advanced_branch_logging", + create_tables=True, + logger=mock_logger, + ) + secret = "SECRET_BRANCH_TURN_CONTENT" + + try: + await session.add_items( + [ + {"role": "user", "content": secret}, + {"role": "assistant", "content": "response"}, + ] + ) + await session.create_branch_from_turn(1, "branch") + + logged = str(mock_logger.debug.call_args) + assert (secret not in logged) is redacted + finally: + session.close() + + async def test_advanced_session_respects_custom_table_names(): """AdvancedSQLiteSession should consistently use configured table names.""" session = AdvancedSQLiteSession( @@ -1438,6 +1466,72 @@ async def test_error_handling_in_usage_tracking(usage_data: Usage): await session.store_run_usage(run_result) +@pytest.mark.parametrize( + ("model_redacted", "tool_redacted"), + [(True, False), (False, True), (False, False)], +) +async def test_usage_tracking_failure_identity_follows_model_data_policy( + usage_data: Usage, + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + model_redacted: bool, + tool_redacted: bool, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + session_id = "SECRET_USAGE_SESSION_ID" + test_logger = logging.getLogger("advanced-sqlite-usage-failure") + session = AdvancedSQLiteSession( + session_id=session_id, + create_tables=True, + logger=test_logger, + ) + secret = "SECRET_USAGE_FAILURE" + run_result = create_mock_run_result(usage_data) + + original_record_factory = logging.getLogRecordFactory() + + def application_record_factory(*args: Any, **kwargs: Any) -> logging.LogRecord: + record = original_record_factory(*args, **kwargs) + record.session_id = "APPLICATION_SESSION_ID" + return record + + logging.setLogRecordFactory(application_record_factory) + try: + with ( + patch.object( + session, + "_update_turn_usage_internal", + side_effect=RuntimeError(secret), + ), + caplog.at_level(logging.ERROR, logger=test_logger.name), + ): + await session.store_run_usage(run_result) + finally: + logging.setLogRecordFactory(original_record_factory) + + record = next( + record + for record in caplog.records + if "Failed to store session usage" in record.getMessage() + ) + assert record.__dict__["session_id"] == "APPLICATION_SESSION_ID" + if model_redacted: + assert record.msg == "%s" + assert record.args == ("Failed to store session usage",) + assert record.exc_info is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert secret not in caplog.text + assert session_id not in caplog.text + else: + assert record.__dict__["openai_agents_diagnostic_context"] == {"session_id": session_id} + assert record.exc_info is not None + assert record.exc_info[1] is not None + assert secret in caplog.text + + session.close() + + async def test_advanced_tool_name_extraction(): """Test advanced tool name extraction for different tool types.""" session_id = "advanced_tool_names_test" diff --git a/tests/extensions/sandbox/test_blaxel.py b/tests/extensions/sandbox/test_blaxel.py index 8f189bcd4d..97d0168ab3 100644 --- a/tests/extensions/sandbox/test_blaxel.py +++ b/tests/extensions/sandbox/test_blaxel.py @@ -3,6 +3,7 @@ import asyncio import io import json +import logging import tarfile import time import uuid @@ -14,6 +15,7 @@ import pytest from pydantic import ValidationError +import agents._debug as _debug from agents.run_config import SandboxRunConfig from agents.sandbox import Manifest, SandboxPathGrant from agents.sandbox.config import DEFAULT_PYTHON_SANDBOX_IMAGE @@ -3539,13 +3541,45 @@ async def test_detach_drive_success(self) -> None: assert sandbox.drives.unmount_calls == ["/mnt/data"] @pytest.mark.asyncio - async def test_detach_drive_error_logged_not_raised(self) -> None: + @pytest.mark.parametrize("redacted", [True, False], ids=["redacted", "diagnostic"]) + async def test_detach_drive_error_logged_not_raised( + self, + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + redacted: bool, + ) -> None: from agents.extensions.sandbox.blaxel.mounts import _detach_drive + mount_path = "/mnt/SECRET_DRIVE_PATH" + error = RuntimeError("SECRET_UNMOUNT_ERROR") sandbox = _FakeSandboxInstance() - sandbox.drives.unmount_error = RuntimeError("unmount failed") + sandbox.drives.unmount_error = error + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + caplog.set_level(logging.WARNING) + # Should not raise; error is logged. - await _detach_drive(sandbox, "/mnt/data") + await _detach_drive(sandbox, mount_path) + + record = next( + record + for record in caplog.records + if "Drive detach failed" in logging.Formatter().format(record) + ) + if redacted: + assert record.msg == "%s" + assert record.args == ("Drive detach failed (non-fatal)",) + assert record.exc_info is None + assert record.exc_text is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert error not in record.__dict__.values() + rendered = logging.Formatter().format(record) + assert mount_path not in rendered + assert "SECRET_UNMOUNT_ERROR" not in rendered + else: + assert record.__dict__["openai_agents_diagnostic_context"] == {"mount_path": mount_path} + assert record.exc_info is not None + assert record.exc_info[1] is error + assert "SECRET_UNMOUNT_ERROR" in logging.Formatter().format(record) @pytest.mark.asyncio async def test_detach_drive_no_drives_api(self) -> None: diff --git a/tests/extensions/sandbox/test_cloudflare.py b/tests/extensions/sandbox/test_cloudflare.py index 84e5ae9f39..c0a32f13de 100644 --- a/tests/extensions/sandbox/test_cloudflare.py +++ b/tests/extensions/sandbox/test_cloudflare.py @@ -50,6 +50,7 @@ def __init__(self, status: int = 200, json_body: Any = None, raw_body: bytes = b self.status = status self._json_body = json_body self._raw_body = raw_body + self.read_calls = 0 async def json(self, *, content_type: str | None = None) -> Any: _ = content_type @@ -58,6 +59,7 @@ async def json(self, *, content_type: str | None = None) -> Any: return json.loads(self._raw_body) async def read(self) -> bytes: + self.read_calls += 1 if self._json_body is not None: return json.dumps(self._json_body).encode() return self._raw_body @@ -1535,31 +1537,33 @@ def delete(self, url: str, **kwargs: Any) -> Any: @pytest.mark.asyncio -async def test_cloudflare_shutdown_logs_delete_response_details( +@pytest.mark.parametrize("redacted", [True, False]) +async def test_cloudflare_shutdown_logs_respect_tool_data_policy( + monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture, + redacted: bool, ) -> None: - """Verify that DELETE response bodies are kept when shutdown cleanup fails.""" + """Verify that DELETE response bodies follow the tool-data logging policy.""" import logging - sess = _make_session( - fake_http=_FakeHttp( - { - "DELETE /v1/sandbox/": _FakeResponse( - status=502, - json_body={ - "error": "pool error: Failed to start container", - "code": "pool_error", - }, - ) - } - ) + monkeypatch.setattr("agents._debug.DONT_LOG_TOOL_DATA", redacted) + + response = _FakeResponse( + status=502, + json_body={ + "error": "pool error: Failed to start container", + "code": "pool_error", + }, ) + sess = _make_session(fake_http=_FakeHttp({"DELETE /v1/sandbox/": response})) with caplog.at_level(logging.DEBUG, logger="agents.extensions.sandbox.cloudflare.sandbox"): await sess._shutdown_backend() - assert any( + has_detail = any( "DELETE /sandbox failed: HTTP 502: pool_error: pool error: Failed to start container" in r.message for r in caplog.records ) + assert has_detail is not redacted + assert response.read_calls == (0 if redacted else 1) diff --git a/tests/extensions/sandbox/test_e2b.py b/tests/extensions/sandbox/test_e2b.py index d6a4ac33fa..f830546517 100644 --- a/tests/extensions/sandbox/test_e2b.py +++ b/tests/extensions/sandbox/test_e2b.py @@ -2189,11 +2189,15 @@ async def test_e2b_stop_terminates_live_pty_sessions() -> None: @pytest.mark.asyncio +@pytest.mark.parametrize("redacted", [True, False]) async def test_e2b_shutdown_logs_pause_failure_and_falls_back_to_kill( + monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture, + redacted: bool, ) -> None: + monkeypatch.setattr("agents._debug.DONT_LOG_TOOL_DATA", redacted) sandbox = _FakeE2BSandbox() - sandbox.pause_error = RuntimeError("pause failed") + sandbox.pause_error = RuntimeError("SECRET_E2B_PAUSE_FAILURE") state = E2BSandboxSessionState( session_id=uuid.uuid4(), manifest=Manifest(root="/workspace"), @@ -2211,12 +2215,24 @@ async def test_e2b_shutdown_logs_pause_failure_and_falls_back_to_kill( assert sandbox.pause_calls == 1 assert sandbox.kill_calls == 1 assert "Failed to pause E2B sandbox on shutdown; falling back to kill." in caplog.text + assert ("SECRET_E2B_PAUSE_FAILURE" not in caplog.text) is redacted + record = caplog.records[-1] + assert ("openai_agents_diagnostic_context" in record.__dict__) is not redacted + if not redacted: + assert record.__dict__["openai_agents_diagnostic_context"] == { + "sandbox_id": sandbox.sandbox_id, + "pause_on_exit": True, + } @pytest.mark.asyncio +@pytest.mark.parametrize("redacted", [True, False]) async def test_e2b_shutdown_logs_kill_failure_after_pause_fallback( + monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture, + redacted: bool, ) -> None: + monkeypatch.setattr("agents._debug.DONT_LOG_TOOL_DATA", redacted) sandbox = _FakeE2BSandbox() sandbox.pause_error = RuntimeError("pause failed") sandbox.kill_error = RuntimeError("kill failed") @@ -2237,10 +2253,23 @@ async def test_e2b_shutdown_logs_kill_failure_after_pause_fallback( assert sandbox.pause_calls == 1 assert sandbox.kill_calls == 1 assert "Failed to kill E2B sandbox after pause fallback failure." in caplog.text + record = caplog.records[-1] + assert ("openai_agents_diagnostic_context" in record.__dict__) is not redacted + if not redacted: + assert record.__dict__["openai_agents_diagnostic_context"] == { + "sandbox_id": sandbox.sandbox_id, + "pause_on_exit": True, + } @pytest.mark.asyncio -async def test_e2b_shutdown_logs_direct_kill_failure(caplog: pytest.LogCaptureFixture) -> None: +@pytest.mark.parametrize("redacted", [True, False]) +async def test_e2b_shutdown_logs_direct_kill_failure( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + redacted: bool, +) -> None: + monkeypatch.setattr("agents._debug.DONT_LOG_TOOL_DATA", redacted) sandbox = _FakeE2BSandbox() sandbox.kill_error = RuntimeError("kill failed") state = E2BSandboxSessionState( @@ -2260,6 +2289,13 @@ async def test_e2b_shutdown_logs_direct_kill_failure(caplog: pytest.LogCaptureFi assert sandbox.pause_calls == 0 assert sandbox.kill_calls == 1 assert "Failed to kill E2B sandbox on shutdown." in caplog.text + record = caplog.records[-1] + assert ("openai_agents_diagnostic_context" in record.__dict__) is not redacted + if not redacted: + assert record.__dict__["openai_agents_diagnostic_context"] == { + "sandbox_id": sandbox.sandbox_id, + "pause_on_exit": False, + } @pytest.mark.asyncio diff --git a/tests/mcp/test_mcp_server_manager.py b/tests/mcp/test_mcp_server_manager.py index ccf026e7ee..f1f769eb6f 100644 --- a/tests/mcp/test_mcp_server_manager.py +++ b/tests/mcp/test_mcp_server_manager.py @@ -1,4 +1,5 @@ import asyncio +import logging from typing import Any, cast import pytest @@ -12,7 +13,9 @@ Tool as MCPTool, ) +from agents import _debug from agents.mcp import MCPServer, MCPServerManager +from agents.mcp._logging import get_mcp_server_log_name from agents.run_context import RunContextWrapper @@ -121,6 +124,21 @@ async def read_resource(self, uri: str) -> ReadResourceResult: return ReadResourceResult(contents=[]) +class SensitiveNamedServer(FlakyServer): + def __init__(self, name: str) -> None: + super().__init__(failures=1) + self._name = name + self.name_reads = 0 + + @property + def name(self) -> str: + self.name_reads += 1 + return self._name + + async def connect(self) -> None: + raise RuntimeError("SECRET_MCP_CONNECT_ERROR") + + class CleanupAwareServer(MCPServer): def __init__(self) -> None: super().__init__() @@ -172,6 +190,84 @@ async def read_resource(self, uri: str) -> ReadResourceResult: return ReadResourceResult(contents=[]) +@pytest.mark.parametrize( + ("name", "expected"), + [ + ("ordinary-server", "ordinary-server"), + ( + "sse: https://user:password@example.test/events?token=secret#fragment", + "sse: https://example.test/events", + ), + ( + "streamable_http: https://example.test/mcp?token=secret", + "streamable_http: https://example.test/mcp", + ), + ( + "streamable_http: https://user:password@example.test:8443/mcp?token=secret", + "streamable_http: https://example.test:8443/mcp", + ), + ("streamable_http: https://[::1]:8000/mcp", "streamable_http: https://[::1]:8000/mcp"), + ( + "streamable-http: https://example.test/mcp#secret", + "streamable-http: https://example.test/mcp", + ), + ( + "streamable_http: https://user:password@[invalid/mcp?token=secret", + "streamable_http: ", + ), + ( + "streamable_http: https://user:password/mcp?token=secret", + "streamable_http: ", + ), + ("https://user:password@example.test/mcp?token=secret", "https://example.test/mcp"), + ("https://user:password@[invalid/mcp?token=secret", ""), + ("stdio: python server.py?token=secret", "stdio: python server.py?token=secret"), + ], +) +def test_get_mcp_server_log_name(name: str, expected: str) -> None: + assert get_mcp_server_log_name(name) == expected + + +@pytest.mark.asyncio +@pytest.mark.parametrize("redacted", [True, False]) +@pytest.mark.parametrize( + ("server_name", "diagnostic_sentinel", "always_hidden"), + [ + ( + "streamable_http: https://SECRET_CREDENTIAL@example.test/" + "SECRET_MCP_PATH?token=SECRET_MCP_QUERY#SECRET_MCP_FRAGMENT", + "SECRET_MCP_PATH", + ("SECRET_CREDENTIAL", "SECRET_MCP_QUERY", "SECRET_MCP_FRAGMENT"), + ), + ( + "SECRET_CUSTOM_MCP_SERVER_NAME", + "SECRET_CUSTOM_MCP_SERVER_NAME", + (), + ), + ], +) +async def test_manager_sanitizes_url_derived_server_names_in_failure_logs( + monkeypatch, + caplog, + redacted: bool, + server_name: str, + diagnostic_sentinel: str, + always_hidden: tuple[str, ...], +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + server = SensitiveNamedServer(server_name) + manager = MCPServerManager([server]) + + with caplog.at_level(logging.ERROR, logger="openai.agents"): + await manager.connect_all() + + assert (diagnostic_sentinel not in caplog.text) is redacted + assert server.name_reads == (0 if redacted else 1) + for sentinel in always_hidden: + assert sentinel not in caplog.text + assert ("SECRET_MCP_CONNECT_ERROR" not in caplog.text) is redacted + + class CancelledServer(MCPServer): def __init__(self) -> None: super().__init__() diff --git a/tests/mcp/test_mcp_util.py b/tests/mcp/test_mcp_util.py index 7ddf9f9068..e1a06f17eb 100644 --- a/tests/mcp/test_mcp_util.py +++ b/tests/mcp/test_mcp_util.py @@ -677,7 +677,7 @@ async def test_mcp_invoke_bad_json_errors(caplog: pytest.LogCaptureFixture): with pytest.raises(ModelBehaviorError): await MCPUtil.invoke_mcp_tool(server, tool, ctx, "not_json") - assert "Invalid JSON input for tool test_tool_1" in caplog.text + assert "Invalid JSON input for MCP tool" in caplog.text @pytest.mark.asyncio @@ -807,7 +807,7 @@ async def test_mcp_invocation_crash_causes_error(caplog: pytest.LogCaptureFixtur with pytest.raises(AgentsException): await MCPUtil.invoke_mcp_tool(server, tool, ctx, "") - assert "Error invoking MCP tool test_tool_1" in caplog.text + assert "Error invoking MCP tool" in caplog.text class SecretCrashingFakeMCPServer(FakeMCPServer): @@ -837,15 +837,17 @@ async def test_mcp_invocation_crash_redacts_error_when_dont_log_tool_data( caplog.set_level(logging.DEBUG) monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", True) - server = SecretCrashingFakeMCPServer() - server.add_tool("test_tool_1", {}) + server = SecretCrashingFakeMCPServer(server_name="SECRET_CUSTOM_MCP_SERVER") + server.add_tool("SECRET_MCP_TOOL_NAME", {}) ctx = RunContextWrapper(context=None) - tool = MCPTool(name="test_tool_1", inputSchema={}) + tool = MCPTool(name="SECRET_MCP_TOOL_NAME", inputSchema={}) with pytest.raises(AgentsException): await MCPUtil.invoke_mcp_tool(server, tool, ctx, "") - assert "Error invoking MCP tool test_tool_1" in caplog.text + assert "Error invoking MCP tool" in caplog.text + assert "SECRET_CUSTOM_MCP_SERVER" not in caplog.text + assert "SECRET_MCP_TOOL_NAME" not in caplog.text assert "SECRET_CRASH_123" not in caplog.text @@ -856,7 +858,12 @@ async def test_mcp_invocation_crash_includes_error_when_tool_logging_enabled( caplog.set_level(logging.DEBUG) monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", False) - server = SecretCrashingFakeMCPServer() + server = SecretCrashingFakeMCPServer( + server_name=( + "streamable_http: https://SECRET_CREDENTIAL@example.test/" + "SECRET_MCP_PATH?token=SECRET_MCP_QUERY" + ) + ) server.add_tool("test_tool_1", {}) ctx = RunContextWrapper(context=None) tool = MCPTool(name="test_tool_1", inputSchema={}) @@ -865,6 +872,9 @@ async def test_mcp_invocation_crash_includes_error_when_tool_logging_enabled( await MCPUtil.invoke_mcp_tool(server, tool, ctx, "") assert "SECRET_CRASH_123" in caplog.text + assert "SECRET_MCP_PATH" in caplog.text + assert "SECRET_CREDENTIAL" not in caplog.text + assert "SECRET_MCP_QUERY" not in caplog.text @pytest.mark.asyncio @@ -874,15 +884,17 @@ async def test_mcp_tool_returned_error_redacts_message_when_dont_log_tool_data( caplog.set_level(logging.DEBUG) monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", True) - server = McpErrorFakeMCPServer() - server.add_tool("test_tool_1", {}) + server = McpErrorFakeMCPServer(server_name="SECRET_CUSTOM_MCP_SERVER") + server.add_tool("SECRET_MCP_TOOL_NAME", {}) ctx = RunContextWrapper(context=None) - tool = MCPTool(name="test_tool_1", inputSchema={}) + tool = MCPTool(name="SECRET_MCP_TOOL_NAME", inputSchema={}) with pytest.raises(McpError): await MCPUtil.invoke_mcp_tool(server, tool, ctx, "") - assert "MCP tool test_tool_1 on server" in caplog.text + assert "MCP tool returned an error" in caplog.text + assert "SECRET_CUSTOM_MCP_SERVER" not in caplog.text + assert "SECRET_MCP_TOOL_NAME" not in caplog.text assert "SECRET_MCP_123" not in caplog.text diff --git a/tests/mcp/test_tool_filtering.py b/tests/mcp/test_tool_filtering.py index 0127df806c..3da58756a6 100644 --- a/tests/mcp/test_tool_filtering.py +++ b/tests/mcp/test_tool_filtering.py @@ -9,6 +9,7 @@ import pytest from mcp import Tool as MCPTool +import agents._debug as _debug from agents import Agent from agents.mcp import ToolFilterContext, create_static_tool_filter from agents.run_context import RunContextWrapper @@ -181,6 +182,38 @@ def error_prone_filter(context: ToolFilterContext, tool: MCPTool) -> bool: assert {t.name for t in tools} == {"good_tool", "another_good_tool"} +@pytest.mark.asyncio +@pytest.mark.parametrize("redacted", [True, False]) +async def test_dynamic_filter_error_logging_preserves_identity_only_in_diagnostic_mode( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + redacted: bool, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + server = FakeMCPServer( + server_name=( + "streamable_http: https://SECRET_CREDENTIAL@example.test/" + "SECRET_SERVER_PATH?token=SECRET_QUERY" + ) + ) + server.add_tool("SECRET_TOOL_NAME", {}) + + def failing_filter(context: ToolFilterContext, tool: MCPTool) -> bool: + raise ValueError("SECRET_FILTER_ERROR") + + server.tool_filter = failing_filter + + with caplog.at_level("ERROR", logger="openai.agents"): + tools = await server.list_tools(create_test_context(), create_test_agent()) + + assert tools == [] + assert "SECRET_CREDENTIAL" not in caplog.text + assert "SECRET_QUERY" not in caplog.text + assert ("SECRET_TOOL_NAME" in caplog.text) is not redacted + assert ("SECRET_SERVER_PATH" in caplog.text) is not redacted + assert ("SECRET_FILTER_ERROR" in caplog.text) is not redacted + + # === Integration Tests === diff --git a/tests/memory/test_openai_responses_compaction_session.py b/tests/memory/test_openai_responses_compaction_session.py index fe893cf88a..16b7ce8718 100644 --- a/tests/memory/test_openai_responses_compaction_session.py +++ b/tests/memory/test_openai_responses_compaction_session.py @@ -8,6 +8,7 @@ import pytest +import agents._debug as _debug from agents import Agent, Runner from agents.items import TResponseInputItem from agents.memory import ( @@ -706,9 +707,12 @@ async def clear_session(self) -> None: assert failing_session.add_calls == 1 @pytest.mark.asyncio + @pytest.mark.parametrize("redacted", [True, False]) async def test_run_compaction_reraises_replacement_error_when_restore_fails( - self, caplog: pytest.LogCaptureFixture + self, monkeypatch, caplog: pytest.LogCaptureFixture, redacted: bool ) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) history: list[TResponseInputItem] = [ cast(TResponseInputItem, {"type": "message", "role": "user", "content": "original"}), ] @@ -730,7 +734,7 @@ async def add_items(self, items: list[TResponseInputItem]) -> None: if self.add_calls == 1: await super().add_items(items[:1]) raise RuntimeError("replacement failed") - raise RuntimeError("restore failed") + raise RuntimeError("SECRET_COMPACTION_RESTORE_FAILURE") async def clear_session(self) -> None: self.clear_calls += 1 @@ -758,6 +762,7 @@ async def clear_session(self) -> None: assert ( "Failed to restore session history after compaction replacement failed." in caplog.text ) + assert ("SECRET_COMPACTION_RESTORE_FAILURE" not in caplog.text) is redacted assert failing_session.clear_calls == 2 assert failing_session.add_calls == 2 diff --git a/tests/realtime/test_agent.py b/tests/realtime/test_agent.py index 7ac5cbe359..bc2a4c408c 100644 --- a/tests/realtime/test_agent.py +++ b/tests/realtime/test_agent.py @@ -1,6 +1,7 @@ from __future__ import annotations from typing import Any +from unittest.mock import patch import pytest @@ -29,6 +30,29 @@ def _instructions(ctx, agt) -> str: assert instructions == "Dynamic" +@pytest.mark.asyncio +@pytest.mark.parametrize("redacted", [True, False]) +async def test_mutated_invalid_instructions_respect_model_data_policy( + monkeypatch, redacted: bool +) -> None: + class SensitiveInstructions: + def __str__(self) -> str: + return "SECRET_REALTIME_INSTRUCTIONS" + + __repr__ = __str__ + + agent = RealtimeAgent(name="test") + agent.instructions = SensitiveInstructions() # type: ignore[assignment] + monkeypatch.setattr("agents.realtime.agent._debug.DONT_LOG_MODEL_DATA", redacted) + + with patch("agents.realtime.agent.logger") as mock_logger: + prompt = await agent.get_system_prompt(RunContextWrapper(context=None)) + + assert prompt is None + logged = str(mock_logger.error.call_args) + assert ("SECRET_REALTIME_INSTRUCTIONS" not in logged) is redacted + + def test_post_init_rejects_invalid_field_types() -> None: with pytest.raises(TypeError, match="RealtimeAgent name must be a string"): RealtimeAgent(name=1) # type: ignore[arg-type] diff --git a/tests/realtime/test_session.py b/tests/realtime/test_session.py index 3211f2358d..8d69916505 100644 --- a/tests/realtime/test_session.py +++ b/tests/realtime/test_session.py @@ -1,6 +1,7 @@ import asyncio import dataclasses import json +import logging import threading from typing import Any, cast from unittest.mock import AsyncMock, Mock, PropertyMock, patch @@ -8,6 +9,7 @@ import pytest from pydantic import BaseModel, ConfigDict +import agents._debug as _debug from agents.exceptions import ToolTimeoutError, UserError from agents.guardrail import GuardrailFunctionOutput, OutputGuardrail from agents.handoffs import Handoff @@ -576,6 +578,7 @@ class _FakeAudio: @pytest.mark.asyncio async def test_item_updated_merge_exception_path_logs_error(monkeypatch): + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", True) model = _DummyModel() agent = RealtimeAgent(name="agent") session = RealtimeSession(model, agent, None) @@ -594,8 +597,7 @@ async def test_item_updated_merge_exception_path_logs_error(monkeypatch): with patch("agents.realtime.session.logger") as mock_logger: await session.on_event(RealtimeModelItemUpdatedEvent(item=incoming)) - # error branch should be hit - assert mock_logger.error.called + mock_logger.error.assert_called_once_with("%s", "Error merging transcripts", stacklevel=3) @pytest.mark.asyncio @@ -3119,6 +3121,31 @@ async def test_reject_pending_tool_call_uses_run_level_formatter( for ev in events ) + @pytest.mark.asyncio + async def test_rejection_formatter_error_is_redacted( + self, monkeypatch, mock_model, mock_agent, mock_function_tool + ): + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", True) + + def fail_formatter(_args): + raise ValueError("SECRET_REALTIME_TOOL_FORMATTER") + + session = RealtimeSession( + mock_model, + mock_agent, + None, + run_config={"tool_error_formatter": fail_formatter}, + ) + + with patch("agents.realtime.session.logger") as mock_logger: + message = await session._resolve_approval_rejection_message( + tool=mock_function_tool, + call_id="call_reject_error", + ) + + assert message + mock_logger.error.assert_called_once_with("%s", "Tool error formatter failed", stacklevel=3) + @pytest.mark.asyncio async def test_reject_pending_tool_call_prefers_explicit_message( self, mock_model, mock_agent, mock_function_tool @@ -3491,6 +3518,96 @@ def guardrail_func(context, agent, output): return OutputGuardrail(guardrail_function=guardrail_func, name="safe_guardrail") + @pytest.mark.parametrize( + ("model_redacted", "tool_redacted"), + [(True, False), (False, True), (False, False)], + ids=["model_redacted", "tool_redacted", "diagnostic"], + ) + @pytest.mark.asyncio + async def test_output_guardrail_failure_follows_both_data_policies( + self, + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + mock_model: RealtimeModel, + model_redacted: bool, + tool_redacted: bool, + ) -> None: + error = RuntimeError("SECRET_REALTIME_GUARDRAIL_ERROR") + + async def failing_guardrail(context, agent, output): + _ = context, agent, output + raise error + + guardrail = OutputGuardrail( + guardrail_function=failing_guardrail, + name="SECRET_REALTIME_GUARDRAIL_NAME", + ) + agent = RealtimeAgent(name="agent", output_guardrails=[guardrail]) + session = RealtimeSession(mock_model, agent, None) + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + + with caplog.at_level(logging.DEBUG, logger="openai.agents"): + triggered = await session._run_output_guardrails("model text", "response-id") + + assert triggered is False + records = [ + record + for record in caplog.records + if "Output guardrail raised an exception" in record.getMessage() + ] + assert len(records) == 1 + record = records[0] + redacted = model_redacted or tool_redacted + if redacted: + assert record.msg == "%s" + assert record.args == ("Output guardrail raised an exception; skipping it",) + assert record.exc_info is None + assert record.exc_text is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert error not in record.__dict__.values() + rendered = logging.Formatter().format(record) + assert "SECRET_REALTIME_GUARDRAIL_ERROR" not in rendered + assert "SECRET_REALTIME_GUARDRAIL_NAME" not in rendered + else: + context = record.__dict__["openai_agents_diagnostic_context"] + assert context == {"guardrail_name": "SECRET_REALTIME_GUARDRAIL_NAME"} + assert record.exc_info is not None + assert record.exc_info[1] is error + assert "SECRET_REALTIME_GUARDRAIL_ERROR" in logging.Formatter().format(record) + + @pytest.mark.asyncio + async def test_output_guardrail_failure_tolerates_missing_callable_name( + self, + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + mock_model: RealtimeModel, + ) -> None: + class _FailingGuardrailCallable: + async def __call__(self, context, agent, output): + _ = context, agent, output + raise RuntimeError("SECRET_UNNAMED_GUARDRAIL_ERROR") + + guardrail = OutputGuardrail(guardrail_function=_FailingGuardrailCallable()) + agent = RealtimeAgent(name="agent", output_guardrails=[guardrail]) + session = RealtimeSession(mock_model, agent, None) + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", False) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", False) + + with caplog.at_level(logging.WARNING, logger="openai.agents"): + triggered = await session._run_output_guardrails("model text", "response-id") + + assert triggered is False + records = [ + record + for record in caplog.records + if "Output guardrail raised an exception" in record.getMessage() + ] + assert len(records) == 1 + context = records[0].__dict__["openai_agents_diagnostic_context"] + assert context["guardrail_type"].endswith("._FailingGuardrailCallable") + assert records[0].exc_info is not None + @pytest.mark.asyncio async def test_transcript_delta_triggers_guardrail_at_threshold( self, mock_model, mock_agent, triggered_guardrail diff --git a/tests/sandbox/test_memory.py b/tests/sandbox/test_memory.py index c917dacd6d..fa6c3d4bca 100644 --- a/tests/sandbox/test_memory.py +++ b/tests/sandbox/test_memory.py @@ -2,6 +2,7 @@ import io import json +import logging from dataclasses import dataclass from datetime import datetime from pathlib import Path @@ -12,6 +13,7 @@ from openai.types.responses.response_output_message import ResponseOutputMessage from openai.types.responses.response_reasoning_item import ResponseReasoningItem +import agents._debug as _debug import agents.sandbox.capabilities.memory as memory_module import agents.sandbox.memory.manager as memory_manager_module import agents.sandbox.memory.phase_one as phase_one_module @@ -32,7 +34,7 @@ ToolApprovalItem, TResponseOutputItem, ) -from agents.result import RunResultStreaming +from agents.result import RunResult, RunResultStreaming from agents.run import _sandbox_memory_input from agents.run_context import RunContextWrapper from agents.sandbox import ( @@ -1495,15 +1497,31 @@ async def test_sandbox_memory_unregisters_manager_on_session_close() -> None: await client.delete(session) +@pytest.mark.parametrize("streamed", [False, True], ids=["non_streamed", "streamed"]) +@pytest.mark.parametrize( + ("model_redacted", "tool_redacted"), + [(True, False), (False, True), (False, False)], + ids=["model_redacted", "tool_redacted", "diagnostic"], +) @pytest.mark.asyncio -async def test_sandbox_memory_enqueue_failure_still_cleans_up_owned_session( +async def test_sandbox_memory_enqueue_failure_follows_both_data_policies( monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + streamed: bool, + model_redacted: bool, + tool_redacted: bool, ) -> None: + secret = "SECRET_SANDBOX_MEMORY_PAYLOAD" + error = RuntimeError(secret) + async def _raise_write_rollout(*args: Any, **kwargs: Any) -> Path: _ = args, kwargs - raise RuntimeError("write_rollout failed") + raise error monkeypatch.setattr(memory_manager_module, "write_rollout", _raise_write_rollout) + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + caplog.set_level(logging.WARNING) client = _DeleteTrackingUnixLocalSandboxClient() agent = SandboxAgent( @@ -1513,16 +1531,40 @@ async def _raise_write_rollout(*args: Any, **kwargs: Any) -> Path: capabilities=[_memory_config()], ) - result = await Runner.run( - agent, - "hello", - run_config=RunConfig(sandbox=SandboxRunConfig(client=client)), - ) + run_config = RunConfig(sandbox=SandboxRunConfig(client=client)) + result: RunResult | RunResultStreaming + if streamed: + result = Runner.run_streamed(agent, "hello", run_config=run_config) + async for _ in result.stream_events(): + pass + expected_message = "Failed to enqueue sandbox memory after streamed run" + else: + result = await Runner.run(agent, "hello", run_config=run_config) + expected_message = "Failed to enqueue sandbox memory after run" assert result.final_output == "done" assert len(client.deleted_roots) == 1 assert not client.deleted_roots[0].exists() + record = next( + record + for record in caplog.records + if expected_message in logging.Formatter().format(record) + ) + redacted = model_redacted or tool_redacted + if redacted: + assert record.msg == "%s" + assert record.args == (expected_message,) + assert record.exc_info is None + assert record.exc_text is None + assert error not in record.__dict__.values() + assert secret not in logging.Formatter().format(record) + else: + assert record.args == (expected_message, error) + assert record.exc_info is not None + assert record.exc_info[1] is error + assert secret in logging.Formatter().format(record) + @pytest.mark.asyncio async def test_sandbox_memory_marks_interrupted_runs_in_phase_one_prompt() -> None: diff --git a/tests/sandbox/test_runtime.py b/tests/sandbox/test_runtime.py index 9f46ef02cc..0a76aed396 100644 --- a/tests/sandbox/test_runtime.py +++ b/tests/sandbox/test_runtime.py @@ -3,6 +3,7 @@ import asyncio import io import json +import logging import os import re import shutil @@ -18,6 +19,7 @@ from openai.types.responses.response_output_item import LocalShellCall, LocalShellCallAction from openai.types.responses.response_reasoning_item import ResponseReasoningItem, Summary +import agents._debug as _debug import agents.sandbox.runtime_agent_preparation as runtime_agent_preparation_module from agents import Agent, AgentHooks, LocalShellTool, RunHooks, Runner, function_tool from agents.exceptions import InputGuardrailTripwireTriggered, UserError @@ -2115,14 +2117,17 @@ async def _fake_unmount( assert order == [root / "outer" / "child", root / "outer"] +@pytest.mark.parametrize("redacted", [True, False], ids=["redacted", "diagnostic"]) @pytest.mark.asyncio async def test_unix_local_client_delete_skips_rmtree_when_unmount_fails( monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + redacted: bool, ) -> None: client = UnixLocalSandboxClient() manifest = _unix_local_manifest( entries={ - "remote": S3Mount( + "SECRET_REMOTE_MOUNT": S3Mount( bucket="bucket", mount_strategy=InContainerMountStrategy(pattern=MountpointMountPattern()), ), @@ -2139,7 +2144,7 @@ async def _failing_unmount( base_dir: Path, ) -> None: _ = (self, session, dest, base_dir) - raise RuntimeError("busy") + raise RuntimeError("SECRET_UNMOUNT_ERROR") def _fake_rmtree(path: Path, ignore_errors: bool = False) -> None: _ = (path, ignore_errors) @@ -2148,12 +2153,34 @@ def _fake_rmtree(path: Path, ignore_errors: bool = False) -> None: monkeypatch.setattr(S3Mount, "unmount", _failing_unmount) monkeypatch.setattr(shutil, "rmtree", _fake_rmtree) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + caplog.set_level(logging.WARNING) await client.delete(session) assert rmtree_called is False assert workspace_root.exists() + record = next( + record + for record in caplog.records + if "Failed to unmount UnixLocal workspace mount" in logging.Formatter().format(record) + ) + mount_path = str(workspace_root / "SECRET_REMOTE_MOUNT") + if redacted: + assert record.msg == "%s" + assert record.args == ("Failed to unmount UnixLocal workspace mount before deleting root",) + assert record.exc_info is None + assert record.exc_text is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert mount_path not in logging.Formatter().format(record) + assert "SECRET_UNMOUNT_ERROR" not in logging.Formatter().format(record) + else: + assert record.__dict__["openai_agents_diagnostic_context"] == {"mount_path": mount_path} + assert record.exc_info is not None + assert record.exc_info[1] is not None + assert "SECRET_UNMOUNT_ERROR" in logging.Formatter().format(record) + shutil.rmtree(workspace_root, ignore_errors=True) diff --git a/tests/sandbox/test_session_manager.py b/tests/sandbox/test_session_manager.py index 67891b74c8..a6f5c6d70f 100644 --- a/tests/sandbox/test_session_manager.py +++ b/tests/sandbox/test_session_manager.py @@ -1,11 +1,13 @@ from __future__ import annotations import asyncio +import logging import uuid from pathlib import Path import pytest +import agents._debug as _debug from agents.sandbox.manifest import Manifest from agents.sandbox.runtime_session_manager import SandboxRuntimeSessionManager from agents.sandbox.sandboxes.unix_local import ( @@ -193,6 +195,54 @@ async def handle(self, event: SandboxSessionEvent) -> None: await instrumentation.emit(event) +@pytest.mark.parametrize("redacted", [True, False], ids=["redacted", "diagnostic"]) +@pytest.mark.asyncio +async def test_logged_sink_failure_conditionally_includes_sink_type( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + redacted: bool, +) -> None: + class _FailingLogSink(_EventSink): + async def handle(self, event: SandboxSessionEvent) -> None: + _ = event + raise RuntimeError("SECRET_SINK_ERROR") + + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + caplog.set_level(logging.ERROR) + instrumentation = Instrumentation(sinks=[_FailingLogSink(mode="sync", on_error="log")]) + event = SandboxSessionFinishEvent( + session_id=uuid.uuid4(), + seq=1, + op="running", + span_id="span_running", + ok=True, + duration_ms=0.0, + ) + + await instrumentation.emit(event) + + record = next( + record + for record in caplog.records + if "Sandbox event sink failed" in logging.Formatter().format(record) + ) + if redacted: + assert record.msg == "%s" + assert record.args == ("Sandbox event sink failed (ignored)",) + assert record.exc_info is None + assert record.exc_text is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert "_FailingLogSink" not in logging.Formatter().format(record) + assert "SECRET_SINK_ERROR" not in logging.Formatter().format(record) + else: + assert record.__dict__["openai_agents_diagnostic_context"] == { + "sink_type": "_FailingLogSink" + } + assert record.exc_info is not None + assert record.exc_info[1] is not None + assert "SECRET_SINK_ERROR" in logging.Formatter().format(record) + + def test_session_manager_uses_custom_snapshot_spec_without_resolving_default( monkeypatch: pytest.MonkeyPatch, ) -> None: diff --git a/tests/test_agent_as_tool.py b/tests/test_agent_as_tool.py index c5cc123034..3872bbb8f6 100644 --- a/tests/test_agent_as_tool.py +++ b/tests/test_agent_as_tool.py @@ -13,6 +13,7 @@ from openai.types.responses.response_function_tool_call import ResponseFunctionToolCall from pydantic import BaseModel, Field +import agents._debug as _debug from agents import ( Agent, AgentBase, @@ -2404,10 +2405,21 @@ async def _invoke_tool() -> Any: @pytest.mark.asyncio +@pytest.mark.parametrize( + ("model_redacted", "tool_redacted"), + [(True, False), (False, True), (False, False)], +) async def test_agent_as_tool_streaming_handler_exception_does_not_fail_call( monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + model_redacted: bool, + tool_redacted: bool, ) -> None: - agent = Agent(name="handler_error_agent") + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + agent_name = "SECRET_HANDLER_ERROR_AGENT" + agent = Agent(name=agent_name) + secret = "SECRET_AGENT_STREAM_PAYLOAD" class DummyStreamingResult: def __init__(self) -> None: @@ -2427,7 +2439,7 @@ async def stream_events(self): ) def bad_handler(event: AgentToolStreamEvent) -> None: - raise RuntimeError("boom") + raise RuntimeError(secret) tool_call = ResponseFunctionToolCall( id="call_bad", @@ -2450,9 +2462,27 @@ def bad_handler(event: AgentToolStreamEvent) -> None: tool_call=tool_call, ) - output = await tool.on_invoke_tool(tool_context, '{"input": "go"}') + with caplog.at_level("ERROR", logger="openai.agents"): + output = await tool.on_invoke_tool(tool_context, '{"input": "go"}') assert output == "ok" + record = next( + record + for record in caplog.records + if "Error while handling an agent tool on_stream event" in record.getMessage() + ) + if model_redacted or tool_redacted: + assert record.msg == "%s" + assert record.args == ("Error while handling an agent tool on_stream event",) + assert record.exc_info is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert secret not in caplog.text + assert agent_name not in caplog.text + else: + assert record.__dict__["openai_agents_diagnostic_context"] == {"agent_name": agent_name} + assert record.exc_info is not None + assert record.exc_info[1] is not None + assert secret in caplog.text @pytest.mark.asyncio diff --git a/tests/test_agent_runner.py b/tests/test_agent_runner.py index 12160d886e..ab6485045d 100644 --- a/tests/test_agent_runner.py +++ b/tests/test_agent_runner.py @@ -17,6 +17,7 @@ from openai.types.responses.response_reasoning_item import ResponseReasoningItem, Summary from typing_extensions import TypedDict +import agents._debug as _debug from agents import ( Agent, GuardrailFunctionOutput, @@ -2779,6 +2780,45 @@ async def test_rewind_handles_id_stripped_sessions() -> None: assert session.saved_items == [] +@pytest.mark.asyncio +@pytest.mark.parametrize("redacted", [True, False]) +async def test_rewind_debug_logging_respects_model_and_tool_policies( + monkeypatch, redacted: bool +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + secret = "SECRET_REWIND_SESSION_CONTENT" + session = IdStrippingSession() + item = cast( + TResponseInputItem, + {"id": "message-1", "type": "message", "role": "user", "content": secret}, + ) + await session.add_items([item]) + + with patch("agents.run_internal.session_persistence.logger") as mock_logger: + await rewind_session_items(session, [item]) + + logged = str(mock_logger.debug.call_args_list) + assert (secret not in logged) is redacted + + +@pytest.mark.asyncio +async def test_rewind_failure_uses_placeholder_free_shared_logger_message() -> None: + class FailingTailSession(SimpleListSession): + async def get_items(self, limit: int | None = None) -> list[TResponseInputItem]: + raise RuntimeError("tail failure") + + item = cast(TResponseInputItem, {"type": "message", "role": "user", "content": "hi"}) + session = FailingTailSession(history=[item]) + + with patch( + "agents.run_internal.session_persistence.log_model_and_tool_action_warning" + ) as mock_warning: + await rewind_session_items(session, [item]) + + assert mock_warning.call_args.args[1] == "Failed to rewind session item" + + @pytest.mark.asyncio async def test_rewind_skips_mismatched_tail_suffix() -> None: target = cast(TResponseInputItem, {"type": "message", "role": "user", "content": "target"}) diff --git a/tests/test_agent_runner_streamed.py b/tests/test_agent_runner_streamed.py index 85b0c56bc5..b2f9e6e027 100644 --- a/tests/test_agent_runner_streamed.py +++ b/tests/test_agent_runner_streamed.py @@ -2,6 +2,7 @@ import asyncio import json +import logging from typing import Any, cast import httpx @@ -17,6 +18,7 @@ from openai.types.responses.response_reasoning_item import ResponseReasoningItem, Summary from typing_extensions import TypedDict +import agents._debug as _debug from agents import ( Agent, GuardrailFunctionOutput, @@ -1188,6 +1190,72 @@ def guardrail_function( pass +@pytest.mark.parametrize( + ("model_redacted", "tool_redacted"), + [(True, False), (False, True), (False, False)], + ids=["model_redacted", "tool_redacted", "diagnostic"], +) +@pytest.mark.asyncio +async def test_streamed_finalizer_failure_follows_both_data_policies( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + model_redacted: bool, + tool_redacted: bool, +) -> None: + async def safe_guardrail( + context: RunContextWrapper[Any], agent: Agent[Any], input: Any + ) -> GuardrailFunctionOutput: + _ = context, agent, input + return GuardrailFunctionOutput(output_info=None, tripwire_triggered=False) + + error = RuntimeError("SECRET_STREAM_FINALIZER_ERROR") + + async def fail_finalizer(_result: Any) -> bool: + raise error + + monkeypatch.setattr( + run_loop, + "input_guardrail_tripwire_triggered_for_stream", + fail_finalizer, + ) + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + agent_name = "SECRET_STREAM_AGENT_NAME" + agent = Agent( + name=agent_name, + input_guardrails=[InputGuardrail(guardrail_function=safe_guardrail)], + model=FakeModel(initial_output=[get_text_message("done")]), + ) + + with caplog.at_level(logging.DEBUG, logger="openai.agents"): + result = Runner.run_streamed(agent, input="user_message") + async for _ in result.stream_events(): + pass + + assert result.final_output == "done" + record = next( + record + for record in caplog.records + if "Error finalizing streamed result" in record.getMessage() + ) + redacted = model_redacted or tool_redacted + if redacted: + assert record.msg == "%s" + assert record.args == ("Error finalizing streamed result",) + assert record.exc_info is None + assert record.exc_text is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + rendered = logging.Formatter().format(record) + assert agent_name not in rendered + assert "SECRET_STREAM_FINALIZER_ERROR" not in rendered + else: + context = record.__dict__["openai_agents_diagnostic_context"] + assert context == {"agent_name": agent_name} + assert record.exc_info is not None + assert record.exc_info[1] is error + assert "SECRET_STREAM_FINALIZER_ERROR" in logging.Formatter().format(record) + + @pytest.mark.asyncio async def test_input_guardrail_streamed_does_not_save_assistant_message_to_session(): async def guardrail_function( diff --git a/tests/test_computer_tool_lifecycle.py b/tests/test_computer_tool_lifecycle.py index 860dcef9b7..bbb0e04baf 100644 --- a/tests/test_computer_tool_lifecycle.py +++ b/tests/test_computer_tool_lifecycle.py @@ -1,6 +1,7 @@ from __future__ import annotations import asyncio +import logging from typing import Any, cast from unittest.mock import AsyncMock @@ -11,6 +12,7 @@ ResponseComputerToolCall, ) +import agents._debug as _debug from agents import ( Agent, ComputerProvider, @@ -68,6 +70,32 @@ def drag(self, path: list[tuple[int, int]]) -> None: return None +@pytest.mark.asyncio +@pytest.mark.parametrize("redacted", [True, False]) +async def test_dispose_computer_failure_respects_tool_data_policy( + monkeypatch, caplog, redacted: bool +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + + async def dispose(**_kwargs: Any) -> None: + raise RuntimeError("SECRET_COMPUTER_DISPOSE_FAILURE") + + tool = ComputerTool( + computer=ComputerProvider[FakeComputer]( + create=AsyncMock(return_value=FakeComputer()), + dispose=dispose, + ) + ) + ctx = RunContextWrapper(context=None) + await resolve_computer(tool=tool, run_context=ctx) + + with caplog.at_level(logging.WARNING, logger="openai.agents"): + await dispose_resolved_computers(run_context=ctx) + + assert "Failed to dispose computer for run context" in caplog.text + assert ("SECRET_COMPUTER_DISPOSE_FAILURE" not in caplog.text) is redacted + + def _make_message(text: str) -> ResponseOutputMessage: return ResponseOutputMessage( id="msg-1", diff --git a/tests/test_error_logging_redaction.py b/tests/test_error_logging_redaction.py index 5942e6cd5b..4f08056915 100644 --- a/tests/test_error_logging_redaction.py +++ b/tests/test_error_logging_redaction.py @@ -9,8 +9,15 @@ from __future__ import annotations import logging +import pickle +import threading +from logging.handlers import QueueHandler +from pathlib import Path +from queue import SimpleQueue +from typing import Any from unittest.mock import patch +import httpx import pytest from openai import AsyncOpenAI @@ -23,16 +30,111 @@ RunContextWrapper, trace, ) +from agents.logger import ( + log_model_action_debug, + log_model_action_error, + log_model_action_warning, + log_model_and_tool_action_debug, + log_model_and_tool_action_error, + log_model_and_tool_action_warning, + log_tool_action_debug, + log_tool_action_error as log_shared_tool_action_error, + log_tool_action_warning, +) from agents.run_internal.tool_execution import ( log_tool_action_error, resolve_approval_rejection_message, ) +from agents.tracing.processor_interface import TracingProcessor +from agents.tracing.provider import SynchronousMultiTracingProcessor +from agents.tracing.spans import Span +from agents.tracing.traces import Trace _SECRET = "super secret prompt content" +class _RecordingHandler(logging.Handler): + def __init__(self) -> None: + super().__init__() + self.records: list[logging.LogRecord] = [] + + def emit(self, record: logging.LogRecord) -> None: + self.records.append(record) + + +class _HostileException(Exception): + def __str__(self) -> str: + raise AssertionError("redacted logging inspected __str__") + + def __repr__(self) -> str: + raise AssertionError("redacted logging inspected __repr__") + + def __getattribute__(self, name: str): + if name in {"__class__", "__traceback__"}: + raise AssertionError(f"redacted logging inspected {name}") + return super().__getattribute__(name) + + +class _TruthinessException(Exception): + def __init__(self, *, truthy: bool) -> None: + super().__init__("diagnostic failure") + self.truthy = truthy + self.bool_calls = 0 + + def __bool__(self) -> bool: + self.bool_calls += 1 + if self.truthy: + raise AssertionError("logging inspected exception truthiness") + return False + + +class _FailingTracingProcessor(TracingProcessor): + def __init__(self) -> None: + self.str_calls = 0 + self.lock = threading.Lock() + + def __str__(self) -> str: + self.str_calls += 1 + return "SECRET_TRACE_PROCESSOR_ID" + + def _fail(self) -> None: + raise ValueError(_SECRET) + + def on_trace_start(self, trace: Trace) -> None: + self._fail() + + def on_trace_end(self, trace: Trace) -> None: + self._fail() + + def on_span_start(self, span: Span[Any]) -> None: + self._fail() + + def on_span_end(self, span: Span[Any]) -> None: + self._fail() + + def shutdown(self) -> None: + self._fail() + + def force_flush(self) -> None: + self._fail() + + +def _emit_shared_error_for_location(test_logger, helper) -> None: + helper(test_logger, "Fixed operational message", ValueError("failure")) + + +def _emit_tool_execution_error_for_location() -> None: + log_tool_action_error("Fixed operational message", ValueError("failure")) + + def _responses_model() -> OpenAIResponsesModel: - return OpenAIResponsesModel(model="test-model", openai_client=AsyncOpenAI(api_key="test")) + return OpenAIResponsesModel( + model="test-model", + openai_client=AsyncOpenAI( + api_key="test", + http_client=httpx.AsyncClient(trust_env=False), + ), + ) @pytest.mark.allow_call_model_methods @@ -63,7 +165,8 @@ async def raise_fetch(*args, **kwargs): mock_logger.error.assert_called_once() logged = str(mock_logger.error.call_args) assert _SECRET not in logged - assert "ValueError" in logged + assert "ValueError" not in logged + assert "Error getting response" in logged @pytest.mark.allow_call_model_methods @@ -124,7 +227,8 @@ async def raise_fetch(*args, **kwargs): mock_logger.error.assert_called_once() logged = str(mock_logger.error.call_args) assert _SECRET not in logged - assert "ValueError" in logged + assert "ValueError" not in logged + assert "Error streaming response" in logged def test_log_tool_action_error_redacts_by_default(monkeypatch) -> None: @@ -134,13 +238,261 @@ def test_log_tool_action_error_redacts_by_default(monkeypatch) -> None: log_tool_action_error("Shell executor failed", ValueError("rm -rf /secret/path")) mock_logger.error.assert_called_once() - logged = str(mock_logger.error.call_args) - assert "/secret/path" not in logged - assert "ValueError" in logged + assert mock_logger.error.call_args.args == ("%s", "Shell executor failed") # No traceback either, since it can embed the same sensitive data. assert mock_logger.error.call_args.kwargs.get("exc_info") in (None, False) +@pytest.mark.parametrize( + ("helper", "model_flag", "tool_flag"), + [ + (log_model_action_error, True, False), + (log_model_action_debug, True, False), + (log_model_action_warning, True, False), + (log_tool_action_debug, False, True), + (log_shared_tool_action_error, False, True), + (log_tool_action_warning, False, True), + (log_model_and_tool_action_error, True, False), + (log_model_and_tool_action_error, False, True), + (log_model_and_tool_action_debug, True, False), + (log_model_and_tool_action_warning, False, True), + ], +) +def test_shared_error_helpers_do_not_inspect_or_attach_redacted_exceptions( + monkeypatch, + helper, + model_flag: bool, + tool_flag: bool, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_flag) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_flag) + test_logger = logging.Logger("sensitive-logging-redacted") + handler = _RecordingHandler() + test_logger.addHandler(handler) + hostile = _HostileException() + + helper(test_logger, "Fixed operational message", hostile) + + assert len(handler.records) == 1 + record = handler.records[0] + assert record.msg == "%s" + assert record.args == ("Fixed operational message",) + assert record.exc_info is None + assert record.exc_text is None + assert hostile not in record.__dict__.values() + assert logging.Formatter().format(record) == "Fixed operational message" + + +def test_shared_error_helper_preserves_diagnostics_when_enabled(monkeypatch) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", False) + test_logger = logging.Logger("sensitive-logging-diagnostic") + handler = _RecordingHandler() + test_logger.addHandler(handler) + error = ValueError(_SECRET) + + log_shared_tool_action_error(test_logger, "Tool failed", error) + + record = handler.records[0] + assert isinstance(record.args, tuple) + assert error in record.args + assert record.exc_info is not None + assert record.exc_info[1] is error + assert _SECRET in logging.Formatter().format(record) + + +@pytest.mark.parametrize( + "helper", + [log_shared_tool_action_error, log_tool_action_warning], +) +@pytest.mark.parametrize("truthy", [False, True], ids=["falsey", "hostile_bool"]) +def test_shared_error_helpers_do_not_evaluate_exception_truthiness( + monkeypatch, + helper, + truthy: bool, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", False) + test_logger = logging.Logger("sensitive-logging-exception-truthiness") + handler = _RecordingHandler() + test_logger.addHandler(handler) + error = _TruthinessException(truthy=truthy) + + try: + raise error + except _TruthinessException: + helper(test_logger, "Tool failed", error) + + record = handler.records[0] + assert error.bool_calls == 0 + assert record.exc_info is not None + assert record.exc_info[0] is type(error) + assert record.exc_info[1] is error + assert record.exc_info[2] is error.__traceback__ + + +@pytest.mark.parametrize("redacted", [True, False]) +def test_shared_error_helper_conditionally_attaches_diagnostic_extra( + monkeypatch, redacted: bool +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + test_logger = logging.Logger("sensitive-logging-diagnostic-extra") + handler = _RecordingHandler() + test_logger.addHandler(handler) + extra_calls = 0 + + def diagnostic_extra() -> dict[str, object]: + nonlocal extra_calls + extra_calls += 1 + return {"sandbox_id": _SECRET} + + log_tool_action_warning( + test_logger, + "Tool failed", + ValueError("failure"), + diagnostic_extra=diagnostic_extra, + ) + + record = handler.records[0] + assert extra_calls == (0 if redacted else 1) + assert ("openai_agents_diagnostic_context" in record.__dict__) is not redacted + if not redacted: + assert record.__dict__["openai_agents_diagnostic_context"] == {"sandbox_id": _SECRET} + + +def test_shared_error_helper_ignores_diagnostic_extra_failure(monkeypatch) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", False) + test_logger = logging.Logger("sensitive-logging-diagnostic-extra-failure") + handler = _RecordingHandler() + test_logger.addHandler(handler) + error = RuntimeError("original failure") + + def diagnostic_extra() -> dict[str, object]: + raise AttributeError("metadata failure") + + log_tool_action_warning( + test_logger, + "Tool failed", + error, + diagnostic_extra=diagnostic_extra, + ) + + record = handler.records[0] + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert record.exc_info is not None + assert record.exc_info[1] is error + assert "original failure" in logging.Formatter().format(record) + + +@pytest.mark.parametrize( + "operation", + [ + "on_trace_start", + "on_trace_end", + "on_span_start", + "on_span_end", + "force_flush", + "shutdown", + ], +) +@pytest.mark.parametrize( + ("model_redacted", "tool_redacted"), + [(True, False), (False, True), (False, False)], +) +def test_trace_processor_failure_identity_follows_both_data_policies( + monkeypatch, + operation: str, + model_redacted: bool, + tool_redacted: bool, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + test_logger = logging.Logger("sensitive-logging-trace-processor", level=logging.DEBUG) + test_logger.propagate = False + handler = _RecordingHandler() + test_logger.addHandler(handler) + failing = _FailingTracingProcessor() + multi = SynchronousMultiTracingProcessor() + multi.add_tracing_processor(failing) + + with patch("agents.tracing.provider.logger", test_logger): + if operation.startswith(("on_trace", "on_span")): + getattr(multi, operation)(object()) + else: + getattr(multi, operation)() + + record = next(record for record in handler.records if record.levelno == logging.ERROR) + redacted = model_redacted or tool_redacted + if redacted: + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert failing not in record.__dict__.values() + assert record.exc_info is None + assert _SECRET not in logging.Formatter().format(record) + assert failing.str_calls == 0 + else: + processor_identity = record.__dict__["openai_agents_diagnostic_context"]["trace_processor"] + assert isinstance(processor_identity, str) + assert type(failing).__module__ in processor_identity + assert type(failing).__qualname__ in processor_identity + assert f"{id(failing):x}" in processor_identity + prepared = QueueHandler(SimpleQueue()).prepare(record) + pickle.dumps(prepared) + assert record.exc_info is not None + assert record.exc_info[1] is not None + assert _SECRET in logging.Formatter().format(record) + + +@pytest.mark.parametrize( + "helper", + [log_shared_tool_action_error, log_tool_action_warning], +) +def test_shared_error_helpers_preserve_direct_caller_location(monkeypatch, helper) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", True) + test_logger = logging.Logger("sensitive-logging-location") + handler = _RecordingHandler() + test_logger.addHandler(handler) + + _emit_shared_error_for_location(test_logger, helper) + + record = handler.records[0] + assert Path(record.pathname).resolve() == Path(__file__).resolve() + assert record.funcName == "_emit_shared_error_for_location" + + +def test_tool_execution_error_helper_preserves_external_caller_location(monkeypatch) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", True) + test_logger = logging.Logger("sensitive-logging-wrapped-location") + handler = _RecordingHandler() + test_logger.addHandler(handler) + + with patch("agents.run_internal.tool_execution.logger", test_logger): + _emit_tool_execution_error_for_location() + + record = handler.records[0] + assert Path(record.pathname).resolve() == Path(__file__).resolve() + assert record.funcName == "_emit_tool_execution_error_for_location" + + +def test_shared_error_helper_drops_exception_chains_and_notes(monkeypatch) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", True) + test_logger = logging.Logger("sensitive-logging-chain") + handler = _RecordingHandler() + test_logger.addHandler(handler) + cause = ValueError(f"{_SECRET} cause") + error = RuntimeError(f"{_SECRET} outer") + error.__cause__ = cause + if hasattr(error, "add_note"): + error.add_note(f"{_SECRET} note") + else: + error.__notes__ = [f"{_SECRET} note"] + + log_model_action_error(test_logger, "Model failed", error) + + record = handler.records[0] + assert record.exc_info is None + assert record.exc_text is None + assert error not in record.__dict__.values() + assert _SECRET not in logging.Formatter().format(record) + + def test_log_tool_action_error_logs_full_when_tool_data_enabled(monkeypatch) -> None: monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", False) @@ -150,7 +502,11 @@ def test_log_tool_action_error_logs_full_when_tool_data_enabled(monkeypatch) -> mock_logger.error.assert_called_once() logged = str(mock_logger.error.call_args) assert "/secret/path" in logged - assert mock_logger.error.call_args.kwargs.get("exc_info") is True + exc_info = mock_logger.error.call_args.kwargs.get("exc_info") + assert isinstance(exc_info, tuple) + assert exc_info[0] is ValueError + assert isinstance(exc_info[1], ValueError) + assert exc_info[2] is None @pytest.mark.asyncio @@ -161,16 +517,24 @@ async def test_approval_rejection_formatter_error_redacts_exception(monkeypatch, def boom(_args): raise ValueError("formatter blew up SECRET_FMT_123") + tool_name = "SECRET_FORMATTER_TOOL_NAME" result = await resolve_approval_rejection_message( context_wrapper=RunContextWrapper(context=None), run_config=RunConfig(tool_error_formatter=boom), tool_type="function", - tool_name="my_tool", + tool_name=tool_name, call_id="call_1", ) assert isinstance(result, str) and result - assert "Tool error formatter failed for my_tool" in caplog.text + record = next( + record for record in caplog.records if "Tool error formatter failed" in record.getMessage() + ) + assert record.msg == "%s" + assert record.args == ("Tool error formatter failed",) + assert record.exc_info is None + assert "openai_agents_diagnostic_context" not in record.__dict__ + assert tool_name not in caplog.text assert "SECRET_FMT_123" not in caplog.text @@ -184,12 +548,18 @@ async def test_approval_rejection_formatter_error_logs_full_when_enabled( def boom(_args): raise ValueError("formatter blew up SECRET_FMT_123") + tool_name = "diagnostic_tool" await resolve_approval_rejection_message( context_wrapper=RunContextWrapper(context=None), run_config=RunConfig(tool_error_formatter=boom), tool_type="function", - tool_name="my_tool", + tool_name=tool_name, call_id="call_1", ) + record = next( + record for record in caplog.records if "Tool error formatter failed" in record.getMessage() + ) + assert record.__dict__["openai_agents_diagnostic_context"] == {"tool_name": tool_name} + assert record.exc_info is not None assert "SECRET_FMT_123" in caplog.text diff --git a/tests/test_trace_processor.py b/tests/test_trace_processor.py index c0d8898599..ae34114a30 100644 --- a/tests/test_trace_processor.py +++ b/tests/test_trace_processor.py @@ -12,9 +12,10 @@ import httpx import pytest +import agents._debug as _debug from agents.tracing import flush_traces, get_trace_provider from agents.tracing.processor_interface import TracingExporter, TracingProcessor -from agents.tracing.processors import BackendSpanExporter, BatchTraceProcessor +from agents.tracing.processors import BackendSpanExporter, BatchTraceProcessor, ConsoleSpanExporter from agents.tracing.provider import DefaultTraceProvider, TraceProvider from agents.tracing.span_data import AgentSpanData from agents.tracing.spans import Span, SpanImpl @@ -45,6 +46,20 @@ def get_trace(processor: TracingProcessor) -> TraceImpl: ) +@pytest.mark.parametrize("redacted", [True, False]) +def test_console_span_exporter_respects_data_policy(monkeypatch, capsys, redacted: bool) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + span = get_span(mock_processor()) + span.span_data.name = "SECRET_CONSOLE_SPAN" + + ConsoleSpanExporter().export([span]) + + output = capsys.readouterr().out + assert ("SECRET_CONSOLE_SPAN" not in output) is redacted + assert "Export span" in output + + @pytest.fixture def mocked_exporter(): exporter = MagicMock() @@ -438,17 +453,31 @@ def test_backend_span_exporter_2xx_success(mock_client): @patch("httpx.Client") -def test_backend_span_exporter_4xx_client_error(mock_client): - mock_response = MagicMock() - mock_response.status_code = 400 - mock_response.text = "Bad Request" +@pytest.mark.parametrize("redacted", [True, False]) +def test_backend_span_exporter_4xx_client_error(mock_client, monkeypatch, caplog, redacted: bool): + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + + class Response: + status_code = 400 + text_reads = 0 + + @property + def text(self) -> str: + self.text_reads += 1 + return "SECRET_TRACE_RESPONSE_BODY" + + mock_response = Response() mock_client.return_value.post.return_value = mock_response exporter = BackendSpanExporter(api_key="test_key") - exporter.export([get_span(mock_processor())]) + with caplog.at_level(logging.ERROR, logger="openai.agents"): + exporter.export([get_span(mock_processor())]) # 4xx should not be retried mock_client.return_value.post.assert_called_once() + assert ("SECRET_TRACE_RESPONSE_BODY" not in caplog.text) is redacted + assert mock_response.text_reads == (0 if redacted else 1) exporter.close() diff --git a/tests/tracing/test_tracing_env_disable.py b/tests/tracing/test_tracing_env_disable.py index aa2fd93f20..e49b11ea2f 100644 --- a/tests/tracing/test_tracing_env_disable.py +++ b/tests/tracing/test_tracing_env_disable.py @@ -1,5 +1,8 @@ import logging +import pytest + +import agents._debug as _debug from agents.tracing.provider import DefaultTraceProvider from agents.tracing.scope import Scope from agents.tracing.span_data import AgentSpanData @@ -17,6 +20,25 @@ def test_env_read_on_first_use(monkeypatch): assert isinstance(trace, NoOpTrace) +@pytest.mark.parametrize("redacted", [True, False]) +def test_disabled_span_logging_respects_data_policy(monkeypatch, caplog, redacted: bool): + class SensitiveAgentSpanData(AgentSpanData): + def __repr__(self) -> str: + return "SECRET_SPAN_NAME" + + monkeypatch.setenv("OPENAI_AGENTS_DISABLE_TRACING", "1") + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", redacted) + provider = DefaultTraceProvider() + + with caplog.at_level(logging.DEBUG, logger="openai.agents"): + span = provider.create_span(SensitiveAgentSpanData(name="agent")) + + assert isinstance(span, NoOpSpan) + assert ("SECRET_SPAN_NAME" not in caplog.text) is redacted + assert "Tracing is disabled. Not creating span" in caplog.text + + def test_env_cached_after_first_use(monkeypatch): """Env flag is cached after the first trace and later env changes do not flip it.""" monkeypatch.setenv("OPENAI_AGENTS_DISABLE_TRACING", "0") diff --git a/tests/voice/test_pipeline.py b/tests/voice/test_pipeline.py index d6f97bb0eb..45db259929 100644 --- a/tests/voice/test_pipeline.py +++ b/tests/voice/test_pipeline.py @@ -1,6 +1,7 @@ from __future__ import annotations import asyncio +import logging from dataclasses import dataclass, field from typing import Any @@ -8,6 +9,7 @@ import numpy.typing as npt import pytest +import agents._debug as _debug from agents import trace from tests.testing_processor import fetch_events, fetch_span_errors @@ -437,10 +439,24 @@ async def run(self, _: str): yield "out_1" +class _FailingWorkflow(FakeWorkflow): + def __init__(self, error: BaseException): + super().__init__() + self.error = error + + async def run(self, _: str): + raise self.error + yield "" # pragma: no cover + + class _OnStartYieldThenFailWorkflow(FakeWorkflow): + def __init__(self, outputs: list[list[str]], error: BaseException | None = None): + super().__init__(outputs) + self.error = error or RuntimeError("boom") + async def on_start(self): yield "intro" - raise RuntimeError("boom") + raise self.error @pytest.mark.asyncio @@ -493,3 +509,140 @@ async def test_voicepipeline_multi_turn_on_start_exception_does_not_abort() -> N assert events[-1] == "session_ended" assert "error" not in events + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + ("model_redacted", "tool_redacted", "redacted"), + [ + (True, False, True), + (False, True, True), + (False, False, False), + ], +) +async def test_voice_on_start_errors_apply_model_and_tool_logging_policies( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + model_redacted: bool, + tool_redacted: bool, + redacted: bool, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + cause = ValueError("SECRET_VOICE_ON_START_TOOL_PAYLOAD") + error = RuntimeError("Voice startup failed") + error.__cause__ = cause + pipeline = VoicePipeline( + workflow=_OnStartYieldThenFailWorkflow([["out_1"]], error), + stt_model=FakeSTT(["first"]), + tts_model=FakeTTS(), + ) + streamed_audio_input = await FakeStreamedAudioInput.get(count=1) + caplog.set_level(logging.WARNING, logger="openai.agents") + + result = await pipeline.run(streamed_audio_input) + events, _ = await extract_events(result) + + assert events[-1] == "session_ended" + records = [ + record + for record in caplog.records + if record.name == "openai.agents" + and ( + record.msg + in { + "Voice workflow on_start failed", + "Voice workflow on_start failed: %s", + } + or ( + isinstance(record.args, tuple) + and record.args + and record.args[0] == "Voice workflow on_start failed" + ) + ) + ] + assert len(records) == 1 + record = records[0] + if redacted: + assert record.msg == "%s" + assert record.args == ("Voice workflow on_start failed",) + assert record.exc_info is None + assert record.exc_text is None + assert error not in record.__dict__.values() + assert cause not in record.__dict__.values() + assert "SECRET_VOICE_ON_START_TOOL_PAYLOAD" not in logging.Formatter().format(record) + else: + assert record.msg == "%s: %s" + assert isinstance(record.args, tuple) + assert error in record.args + assert record.exc_info is not None + assert record.exc_info[1] is error + assert "SECRET_VOICE_ON_START_TOOL_PAYLOAD" in logging.Formatter().format(record) + + +@pytest.mark.asyncio +@pytest.mark.parametrize("streamed", [False, True]) +@pytest.mark.parametrize( + ("model_redacted", "tool_redacted", "redacted"), + [ + (True, False, True), + (False, True, True), + (False, False, False), + ], +) +async def test_voice_workflow_errors_apply_model_and_tool_logging_policies( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + streamed: bool, + model_redacted: bool, + tool_redacted: bool, + redacted: bool, +) -> None: + monkeypatch.setattr(_debug, "DONT_LOG_MODEL_DATA", model_redacted) + monkeypatch.setattr(_debug, "DONT_LOG_TOOL_DATA", tool_redacted) + error = RuntimeError("SECRET_VOICE_TOOL_PAYLOAD") + pipeline = VoicePipeline( + workflow=_FailingWorkflow(error), + stt_model=FakeSTT(["first"]), + tts_model=FakeTTS(), + ) + audio_input = ( + await FakeStreamedAudioInput.get(count=1) + if streamed + else AudioInput(buffer=np.zeros(2, dtype=np.int16)) + ) + caplog.set_level(logging.ERROR, logger="openai.agents") + + result = await pipeline.run(audio_input) + with pytest.raises(RuntimeError, match="SECRET_VOICE_TOOL_PAYLOAD"): + await extract_events(result) + assert result.text_generation_task is not None + assert result.text_generation_task.exception() is error + + expected_pipeline_message = ( + "Error processing voice turns" if streamed else "Error processing single voice turn" + ) + records = [ + record + for record in caplog.records + if record.name == "openai.agents" + and isinstance(record.args, tuple) + and record.args + and record.args[0] in {expected_pipeline_message, "Error processing voice output"} + ] + assert len(records) == 2 + for record in records: + if redacted: + assert record.msg == "%s" + assert record.args in { + (expected_pipeline_message,), + ("Error processing voice output",), + } + assert record.exc_info is None + assert "SECRET_VOICE_TOOL_PAYLOAD" not in logging.Formatter().format(record) + else: + assert record.msg == "%s: %s" + assert isinstance(record.args, tuple) + assert error in record.args + assert record.exc_info is not None + assert record.exc_info[1] is error