diff --git a/CLAUDE.md b/CLAUDE.md index 90c4a6cc..4829cb2f 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -100,7 +100,7 @@ See `CODESTYLE.md` for full details. Key rules: - **Types**: Always add type hints. Use modern generics: `list[str]`, `dict[str, int]`, `str | None`. - **Data containers**: Use Pydantic `BaseModel` (not `@dataclass`) for value objects; use `model_config = ConfigDict(frozen=True)` when immutability is wanted. - **Visibility**: `_` prefix for all internal attributes/methods. -- **Logging**: Use `logging` module; never `print()`. +- **Logging**: Use `logging` module; never `print()`. Logs carry structure, not content — never log message bodies, tool-call arguments, response bodies, header values, or URL query strings at any level. Route payload detail through `common.payload_logging.log_payload` (gated by `LOG_PAYLOADS`) and sanitize URLs with `common.url_classification.sanitize_url_for_log`. See `CODESTYLE.md` §9. - **Imports**: stdlib → third-party → local, explicit only (no `*` imports). ## Testing diff --git a/CODESTYLE.md b/CODESTYLE.md index 48229c0f..3ac1afcf 100644 --- a/CODESTYLE.md +++ b/CODESTYLE.md @@ -177,8 +177,9 @@ Pick the level from what the record *means for the service*, not from how it rea ### Content rule (metadata over payload) -- Records at **every** level (DEBUG included) carry structure, not content: roles, counts/sizes, durations, tool/skill/deployment/model names, identifiers, statuses/outcomes, error codes and types, MIME types, HTTP status codes, header **names**, and URLs stripped to scheme/host/path. -- Never log message bodies, tool-call argument values, tool/LLM response bodies, attachment content, header **values**, or URL query strings/fragments. The rule is an allowlist: when in doubt, a value is content. (Payload debugging is gated behind the `LOG_PAYLOADS` switch — delivered by #436.) +- Records at **every** level (DEBUG included) carry structure, not content: roles, counts/sizes, durations, tool/skill/deployment/model names, identifiers, statuses/outcomes, error codes and types, MIME types, HTTP status codes, header **names**, and URLs stripped to scheme/host/path (use `common.url_classification.sanitize_url_for_log`). +- Never log message bodies, tool-call argument values, tool/LLM response bodies, attachment content, header **values**, or URL query strings/fragments. The rule is an allowlist: when in doubt, a value is content. This includes exception messages our own code raises — keep response bodies off them (e.g. `ToolErrorException.__str__` is structural; the body stays on the `error_message` attribute for the LLM/user channels). +- Payload debugging is gated behind the `LOG_PAYLOADS` switch: emit an unconditional structure summary, then pass the payload through `common.payload_logging.log_payload` (a no-op unless `LOG_PAYLOADS=true`, truncating each field). Never log payload content unconditionally. - Lifecycle-skeleton records use `common.lifecycle_logging.format_event` — a stable prefix plus `key=value` fields — so structured output (#438) and request ids (#439) can enrich them later without rewording. --- diff --git a/README.md b/README.md index 5d93d8ee..5279e986 100644 --- a/README.md +++ b/README.md @@ -136,6 +136,8 @@ Controls which tool-execution stages are surfaced in the DIAL UI for each app. S | `LOG_DATE_FORMAT` | `%Y-%m-%d %H:%M:%S` | No | `strftime`-style format for the `%(asctime)s` field | | `LOG_LEVEL` | `INFO` | No | Root logger level (all loggers except quickapp) | | `QUICKAPP_LOG_LEVEL` | `INFO` | No | Log level for quickapp loggers | +| `LOG_PAYLOADS` | `false` | No | Emit payload content (message bodies, tool-call arguments, tool/LLM response bodies) at DEBUG. When `false`, no payload content is logged at **any** level and the payload-capable third-party loggers (`openai`/`httpx`/`httpcore`) are capped at INFO. **Local development only** — see [Payload Logging](#payload-logging). | +| `LOG_PAYLOADS_MAX_LENGTH` | `2000` | No | Per-field character cap applied to each payload value when `LOG_PAYLOADS=true`; longer values are truncated. Inert when `LOG_PAYLOADS=false`. | | **Agent** | | | | | `DEFAULT_AGENT_MAX_ITERATIONS` | `15` | No | Maximum number of orchestrator iterations (`-1` for infinite) | | `DEFAULT_ORCHESTRATOR_DEPLOYMENT_ID` | — | No | Default DIAL deployment id used as the orchestrator model when a QuickApp manifest omits `orchestrator.deployment`. Also surfaces as the JSON-schema `default` for that field so DIAL Core can pre-fill new manifests. Apps can override per-app. | @@ -233,6 +235,25 @@ not strictly valid JSON. For guaranteed-valid structured logs, plug in a dedicat +#### Payload Logging + +By policy, logs carry **structure** — roles, counts, sizes, names, ids, statuses, durations, HTTP codes, +header **names**, and URLs stripped to scheme/host/path — and never **content**: message bodies, tool-call +argument values, tool/LLM response bodies, attachment content, header **values**, or URL query strings. This +holds at every level, DEBUG included, so raising verbosity during an incident never brings conversation +content into the logs. + +`LOG_PAYLOADS=true` is the single, explicit exception: it re-enables the payload-bearing DEBUG records (message +context, tool-call arguments, raw responses), each field truncated to `LOG_PAYLOADS_MAX_LENGTH`, and lifts the +INFO cap on the wire-level third-party loggers (`openai`, `httpx`, `httpcore`). Forwarded header **values** are +never logged, even with the switch on. The switch is additive to the level — content appears only when +`QUICKAPP_LOG_LEVEL=DEBUG` **and** `LOG_PAYLOADS=true`. + +> [!CAUTION] +> `LOG_PAYLOADS` is intended for **local development only**. It writes conversation content and wire-level +> third-party payloads to the log pipeline (including any OTLP export). Do **not** enable it in shared or +> production environments. + ## Local Development ### Pre-requisites diff --git a/docs/agent.md b/docs/agent.md index a5837d48..e88f7182 100644 --- a/docs/agent.md +++ b/docs/agent.md @@ -136,6 +136,15 @@ request did during an incident without raising verbosity or exposing conversatio Events are formatted by `common.lifecycle_logging.format_event` as a stable prefix plus `key=value` fields. A handled tool failure produces exactly one `WARNING` (the failure) plus the fallback and completion `INFO` events; an unhandled failure adds the single `ERROR` (with `error_reference`) owned by `_QuickAppCompletion`. + +**Content rule.** At every level (DEBUG included) records carry structure — roles, counts, sizes, names, ids, +statuses, durations, header **names**, and URLs stripped to scheme/host/path — never message bodies, tool-call +arguments, response bodies, header values, or URL query strings. Payload dumps in the agent loop and toolsets +emit an unconditional structure summary and route the payload through `common.payload_logging.log_payload`, +which is a no-op (and truncates) unless `LOG_PAYLOADS=true`. The switch also lifts the INFO cap that +`LoggingConfig` otherwise applies to the wire-level third-party loggers (`openai`/`httpx`/`httpcore`), so +raising a log level alone never brings payloads into the pipeline. + Level semantics, the single-writer ERROR rule, and the content policy live in `CODESTYLE.md` §9 and [`docs/designs/log_levels_and_content_policy.md`](designs/log_levels_and_content_policy.md). diff --git a/docs/designs/log_levels_and_content_policy.md b/docs/designs/log_levels_and_content_policy.md index 1c20c4b4..94e680cf 100644 --- a/docs/designs/log_levels_and_content_policy.md +++ b/docs/designs/log_levels_and_content_policy.md @@ -1,7 +1,8 @@ # Design: Log Levels & Content Policy -- **Status:** Approved +- **Status:** Implemented - **Approved:** 2026-07-14 +- **Implemented:** 2026-07-17 ([#435](https://github.com/epam/ai-dial-quickapps-backend/issues/435) lifecycle skeleton + level rebalance; [#436](https://github.com/epam/ai-dial-quickapps-backend/issues/436) content rule + payload switch) - **Issue:** [#434](https://github.com/epam/ai-dial-quickapps-backend/issues/434) (epic [#441](https://github.com/epam/ai-dial-quickapps-backend/issues/441)) - **Dependencies:** - None. Informed by the logging review of 2026-07-13. Gates the implementation issues diff --git a/src/quickapp/common/chat_completion_stream/handler.py b/src/quickapp/common/chat_completion_stream/handler.py index 87446db1..8e9455fd 100644 --- a/src/quickapp/common/chat_completion_stream/handler.py +++ b/src/quickapp/common/chat_completion_stream/handler.py @@ -31,6 +31,7 @@ ChatStreamAccumulator, ensure_attachment_url_or_data, ) +from quickapp.common.payload_logging import log_payload logger = logging.getLogger(__name__) @@ -178,8 +179,9 @@ def _stream_stage_delta( if stage is None: if not stage_name: logger.warning( - "Skipping stage delta propagation because stage name is missing: %s", delta + "Skipping stage delta propagation because stage name is missing (index=%s)", idx ) + log_payload(logger, "Stage delta with missing name: %s", delta) return try: stage = dest.create_stage(stage_name) @@ -258,23 +260,28 @@ def _close_all_streaming_stages( @staticmethod def _log_stream_accumulator(result: ChatStreamAccumulator) -> None: - logger.debug("===================") - logger.debug(" ---- Captured values:") - logger.debug(" ----- text llm response: %s", result.content) - if result.tool_calls: - logger.debug(" ------ tool_calls:") - for tool in result.tool_calls: - logger.debug(" -------- %s - %s - %s", tool.name, tool.arguments, tool) + tool_calls = result.tool_calls # property rebuilds a list on each access + logger.debug( + "LLM response accumulated: content_length=%d, tool_calls=%s, attachments=%d, " + "stages=%d, state_keys=%s, usage=%s", + len(result.content), + [tool.name for tool in tool_calls] if tool_calls else [], + len(result.attachments), + len(result.stages), + list(result.state) if result.state else [], + ( + f"{result.usage.prompt_tokens}/{result.usage.completion_tokens}" + if result.usage + else None + ), + ) + if result.content: + log_payload(logger, "LLM response content: %s", result.content) + for tool in tool_calls or []: + log_payload(logger, "LLM tool call args (%s): %s", tool.name, tool.arguments) if result.attachments: - logger.debug(" ------ attachments: %s", result.attachments) + log_payload(logger, "LLM response attachments: %s", result.attachments) if result.stages: - logger.debug(" ------ stages: %s", result.stages) + log_payload(logger, "LLM response stages: %s", result.stages) if result.state: - logger.debug(" ------ state: %s", result.state) - if result.usage: - logger.debug( - " ------ usage: prompt_tokens=%s completion_tokens=%s", - result.usage.prompt_tokens, - result.usage.completion_tokens, - ) - logger.debug("===================") + log_payload(logger, "LLM response state: %s", result.state) diff --git a/src/quickapp/common/exceptions/tool_error.py b/src/quickapp/common/exceptions/tool_error.py index 24fa0515..a66899b4 100644 --- a/src/quickapp/common/exceptions/tool_error.py +++ b/src/quickapp/common/exceptions/tool_error.py @@ -1,7 +1,24 @@ class ToolErrorException(Exception): - """Raised when a tool call returns an error.""" + """Raised when a tool call returns an error. + + The exception *message* (``str(e)``, used in logs and tracebacks) carries only + structure — the content rule (issue #436) keeps the tool response body out of the log + pipeline. The body stays available on the :attr:`error_message` attribute, which the + fallback machinery may forward to the LLM (``forward_tool_error_message``, #408) and + the error resolver may surface to the user; neither is a log channel. + + The structural string form is owned here so no subclass can accidentally embed the + body: subclasses set :attr:`tool_kind` (the human label) and the base builds the + message. ``str(e)`` returns this message (the sole ``Exception`` arg), so logs and + tracebacks never carry the body. + """ + + tool_kind = "Tool" def __init__(self, tool_name: str, error_message: str): - super().__init__(f"Tool '{tool_name}' returned an error: {error_message}") + super().__init__( + f"{self.tool_kind} '{tool_name}' returned an error " + f"(content_length={len(error_message)})" + ) self.tool_name = tool_name self.error_message = error_message diff --git a/src/quickapp/common/payload_logging.py b/src/quickapp/common/payload_logging.py new file mode 100644 index 00000000..fe4c4266 --- /dev/null +++ b/src/quickapp/common/payload_logging.py @@ -0,0 +1,81 @@ +"""The payload-debugging switch (content policy, design #434 / issue #436). + +The content rule (enforced everywhere else, see ``common.lifecycle_logging``) keeps +message bodies, tool-call arguments, and response payloads out of the logs at every +level. This module is the single, deliberate exception: the one place allowed to render +payload content, and only behind the ``LOG_PAYLOADS`` opt-in, with each field truncated. + +Because ``LoggingSettings`` is consumed once at startup and not kept in the DI graph +(``LoggingConfig`` applies it and discards it), the switch state lives here as module-level +config, set once by ``LoggingConfig`` via :func:`configure_payload_logging`. Callers read it +through :func:`payloads_enabled` / :func:`log_payload` without touching settings. The module +takes primitives rather than ``LoggingSettings`` so ``common`` stays free of a ``config`` +import. +""" + +import logging +from collections import Counter +from collections.abc import Iterable, Mapping +from typing import Any + +_DEFAULT_MAX_LENGTH = 2000 +_TRUNCATION_MARKER = "…[truncated]" + +_enabled = False +_max_length = _DEFAULT_MAX_LENGTH + + +def configure_payload_logging(enabled: bool, max_length: int) -> None: + """Apply the ``LOG_PAYLOADS`` / ``LOG_PAYLOADS_MAX_LENGTH`` settings. + + Called once at startup by ``LoggingConfig``. Tests may call it directly (and should + restore the defaults afterwards). + """ + global _enabled, _max_length + _enabled = enabled + _max_length = max_length + + +def payloads_enabled() -> bool: + """Whether payload-bearing records may be emitted (``LOG_PAYLOADS=true``).""" + return _enabled + + +def _truncate(value: Any) -> str: + """Render ``value`` as a string capped at the configured max length. + + Longer values are cut and marked with an ellipsis so a truncated payload is never + mistaken for the whole thing. + """ + text = value if isinstance(value, str) else str(value) + if len(text) <= _max_length: + return text + return text[:_max_length] + _TRUNCATION_MARKER + + +def log_payload(logger: logging.Logger, msg: str, *args: Any) -> None: + """Emit a payload-bearing DEBUG record, but only when ``LOG_PAYLOADS`` is on. + + Each ``%s`` argument is truncated to the configured cap. A no-op (nothing is rendered + or emitted) when the switch is off, so callers can pair it with an unconditional + structure summary without guarding it themselves. + """ + if not _enabled: + return + logger.debug(msg, *(_truncate(arg) for arg in args)) + + +def summarize_roles(messages: Iterable[Any]) -> Counter[str]: + """Count messages by ``role`` — a structure summary that carries no message bodies. + + Handles both message objects (``message.role``) and serialized message dicts + (``message["role"]``); a missing role falls under ``"unknown"``. The resulting + ``Counter`` renders as ``Counter({role: count})``. + """ + + def _role(message: Any) -> str: + if isinstance(message, Mapping): + return str(message.get("role") or "unknown") + return str(getattr(message, "role", None) or "unknown") + + return Counter(_role(message) for message in messages) diff --git a/src/quickapp/common/staged_base_tool.py b/src/quickapp/common/staged_base_tool.py index 9eb3c815..f08a9adb 100644 --- a/src/quickapp/common/staged_base_tool.py +++ b/src/quickapp/common/staged_base_tool.py @@ -10,6 +10,7 @@ from quickapp.common.abstract.base_tool_argument_transformer import ToolArgumentTransformer from quickapp.common.base_stage_wrapper import BaseStageWrapper from quickapp.common.lifecycle_logging import format_duration, format_event +from quickapp.common.payload_logging import log_payload from quickapp.common.stage_close_registry import ( DeferredStageCloseRegistry, ImmediateStageCloseRegistry, @@ -198,7 +199,13 @@ async def _run_in_stage_report_success( if matches_type(a.type, attachment_cfg.propagate_types_to_choice): result.propagate_to_choice.append(a) result.attachments = filtered - logger.debug(f"Tool call {tool_call_id} finished with result {result}") + logger.debug( + "Tool call %s finished: content_length=%d, attachments=%d", + tool_call_id, + len(result.content) if result.content else 0, + len(result.attachments) if result.attachments else 0, + ) + log_payload(logger, "Tool call %s result: %s", tool_call_id, result) logger.info( format_event( "Tool call completed", diff --git a/src/quickapp/common/state_holder.py b/src/quickapp/common/state_holder.py index 4651c660..f22d5faf 100644 --- a/src/quickapp/common/state_holder.py +++ b/src/quickapp/common/state_holder.py @@ -6,6 +6,8 @@ from aidial_sdk.chat_completion import Attachment, ToolCall from pydantic import BaseModel, Field, PrivateAttr +from quickapp.common.payload_logging import log_payload + logger = logging.getLogger(__name__) @@ -17,11 +19,13 @@ class StateHolder(BaseModel): _file_metadata_dict: dict[str, FileMetadata] = PrivateAttr(default_factory=dict) def add_state(self, key: str, value: Any) -> None: - logger.debug(f"Added state [{key}]={value}") + logger.debug("Added state [%s] (type=%s)", key, type(value).__name__) + log_payload(logger, "Added state [%s]=%s", key, value) self._state[key] = value def get_state(self) -> dict[str, Any]: - logger.debug(f"Read state {self._state}") + logger.debug("Read state keys: %s", list(self._state)) + log_payload(logger, "Read state: %s", self._state) return self._state def get_file_data(self, url: str | None = None, key: str | None = None) -> bytes | None: diff --git a/src/quickapp/common/tool_fallback/applicable_mixin.py b/src/quickapp/common/tool_fallback/applicable_mixin.py index 2aef30b7..22cf0e6f 100644 --- a/src/quickapp/common/tool_fallback/applicable_mixin.py +++ b/src/quickapp/common/tool_fallback/applicable_mixin.py @@ -1,3 +1,4 @@ +from quickapp.common.exceptions.tool_error import ToolErrorException from quickapp.config.tools.tool_fallback import ToolFallbackStrategyModel, TriggerOn, TriggerOnType @@ -11,17 +12,27 @@ def _is_applicable(strategy_config: ToolFallbackStrategyModel, error: Exception) return False return True + @staticmethod + def _matchable_text(error: Exception) -> str: + # Match trigger_on against the real tool error body (error_message), not the + # structural str(e): the exception's string form carries no response body under + # the content rule (#436), but trigger matching must still see the error text. + if isinstance(error, ToolErrorException): + return error.error_message + return str(error) + @staticmethod def _is_applicable_by_trigger_on(trigger_on: TriggerOn, error: Exception) -> bool: + text = ApplicableStrategyMixin._matchable_text(error) if trigger_on.type == TriggerOnType.contains: return ( - trigger_on.value in str(error) + trigger_on.value in text if trigger_on.case_sensitive - else trigger_on.value.lower() in str(error).lower() + else trigger_on.value.lower() in text.lower() ) else: return ( - trigger_on.value == str(error) + trigger_on.value == text if trigger_on.case_sensitive - else trigger_on.value.lower() == str(error).lower() + else trigger_on.value.lower() == text.lower() ) diff --git a/src/quickapp/common/url_classification.py b/src/quickapp/common/url_classification.py index 824a3f39..0a520b1c 100644 --- a/src/quickapp/common/url_classification.py +++ b/src/quickapp/common/url_classification.py @@ -1,7 +1,7 @@ import re from enum import Enum from functools import lru_cache -from urllib.parse import urlsplit +from urllib.parse import urlsplit, urlunsplit from quickapp.common.exceptions import InvalidToolCallParameterException @@ -58,6 +58,25 @@ def classify_url(url: str, dial_base_url: str) -> UrlScheme: return UrlScheme.EXTERNAL +def sanitize_url_for_log(url: str) -> str: + """Strip a URL to scheme, host, and path for logging (content rule, issue #436). + + Query strings and fragments — where signed-URL tokens live — are dropped, along with + any userinfo (``user:pass@``). A relative DIAL path (``files/...``) has no scheme or + host and is returned with only its query/fragment removed. A URL that cannot be parsed + falls back to the substring before the first ``?`` / ``#``. + """ + if not url: + return url + try: + split = urlsplit(url) + except ValueError: + return url.split("?", 1)[0].split("#", 1)[0] + host = split.hostname or "" + netloc = f"{host}:{split.port}" if split.port else host + return urlunsplit((split.scheme, netloc, split.path, "", "")) + + def unsupported_scheme_error(url: str, parameter_name: str) -> InvalidToolCallParameterException: """Build the canonical "URL scheme not supported" exception. @@ -68,7 +87,7 @@ def unsupported_scheme_error(url: str, parameter_name: str) -> InvalidToolCallPa return InvalidToolCallParameterException( parameter_name=parameter_name, message=( - f"URL scheme not supported: {url}. " + f"URL scheme not supported: {sanitize_url_for_log(url)}. " "Only DIAL file paths (e.g. files/bucket/foo.pdf) and " "http(s) URLs are accepted." ), diff --git a/src/quickapp/config/logging_config.py b/src/quickapp/config/logging_config.py index f5894f56..2624a375 100644 --- a/src/quickapp/config/logging_config.py +++ b/src/quickapp/config/logging_config.py @@ -8,6 +8,7 @@ # caller's import order. import aidial_sdk # noqa: F401 +from quickapp.common.payload_logging import configure_payload_logging from quickapp.config.logging_settings import LoggingSettings # Loggers whose levels LoggingConfig pins explicitly. They carry no handlers of @@ -26,11 +27,28 @@ "aidial_sdk", ) +# Third-party loggers that emit payload content at DEBUG (openai logs full +# chat-completion request bodies; httpx/httpcore log wire-level detail). They are capped +# at INFO unless the payload switch is on, so raising LOG_LEVEL alone never brings their +# payloads into the pipeline (design #434 / issue #436). +PAYLOAD_CAPPED_LOGGERS: tuple[str, ...] = ("openai", "httpx", "httpcore") + + +def _cap_at_info(level_name: str) -> str: + """Return ``level_name`` unless it is more verbose than INFO, in which case ``INFO``. + + Only ever raises the floor to INFO — an already-restrictive level (WARNING/ERROR) is + left untouched. + """ + numeric = logging.getLevelNamesMapping().get(level_name.upper(), logging.INFO) + return "INFO" if numeric < logging.INFO else level_name + class LoggingConfig: def __init__(self, settings: LoggingSettings) -> None: self._settings = settings logging.config.dictConfig(self._get_logging_config()) + configure_payload_logging(settings.log_payloads, settings.log_payloads_max_length) def _formatter_kwargs(self) -> dict: return { @@ -39,15 +57,18 @@ def _formatter_kwargs(self) -> dict: "use_colors": True, } + def _level_for(self, name: str) -> str: + if name == "quickapp": + return self._settings.quickapp_log_level + if name in PAYLOAD_CAPPED_LOGGERS and not self._settings.log_payloads: + return _cap_at_info(self._settings.log_level) + return self._settings.log_level + def _get_logging_config(self) -> dict: per_logger_config = { name: { "handlers": [], - "level": ( - self._settings.quickapp_log_level - if name == "quickapp" - else self._settings.log_level - ), + "level": self._level_for(name), # Must stay explicit: dictConfig leaves `propagate` untouched # when the key is absent, and the uvicorn CLI's default config # (applied before ours in production) sets it to False — diff --git a/src/quickapp/config/logging_settings.py b/src/quickapp/config/logging_settings.py index 7c68376d..c09aea29 100644 --- a/src/quickapp/config/logging_settings.py +++ b/src/quickapp/config/logging_settings.py @@ -18,3 +18,11 @@ class LoggingSettings(BaseSettings): log_date_format: str = Field(default=_DEFAULT_LOG_DATE_FORMAT, alias="LOG_DATE_FORMAT") log_level: str = Field(default="INFO", alias="LOG_LEVEL") quickapp_log_level: str = Field(default="INFO", alias="QUICKAPP_LOG_LEVEL") + + # Payload-debugging switch (content policy, design #434 / issue #436). When false + # (default), content-bearing records are not emitted at any level, and the + # payload-capable third-party loggers (openai/httpx/httpcore) are capped at INFO. When + # true, those records are emitted at DEBUG with each field truncated. Local development + # only — must not be enabled in shared environments. + log_payloads: bool = Field(default=False, alias="LOG_PAYLOADS") + log_payloads_max_length: int = Field(default=2000, alias="LOG_PAYLOADS_MAX_LENGTH") diff --git a/src/quickapp/core/agent/_chat_completion_config_builder.py b/src/quickapp/core/agent/_chat_completion_config_builder.py index ad231eb0..5fa32045 100644 --- a/src/quickapp/core/agent/_chat_completion_config_builder.py +++ b/src/quickapp/core/agent/_chat_completion_config_builder.py @@ -8,6 +8,7 @@ from quickapp.common import RESPONSE_FORMAT, ForwardedHeaders from quickapp.common.abstract.base_transformer import PreInvocationTransformer +from quickapp.common.payload_logging import log_payload, payloads_enabled, summarize_roles from quickapp.common.presentation_settings import PresentationSettings from quickapp.config.application import ApplicationConfig from quickapp.core.agent._tool_choice_holder import _ToolChoiceHolder @@ -49,7 +50,8 @@ def build(self, messages: list[Message]) -> dict[str, Any]: } if self.__response_format: - logger.debug("Setting response format: %s", self.__response_format) + logger.debug("Setting response format (type=%s)", type(self.__response_format).__name__) + log_payload(logger, "Response format: %s", self.__response_format) if hasattr(self.__response_format, "model_dump"): payload["response_format"] = self.__response_format.model_dump( exclude_none=True, mode="json" @@ -73,7 +75,24 @@ def build(self, messages: list[Message]) -> dict[str, Any]: chat_completion_config.update(payload) if logger.isEnabledFor(logging.DEBUG): logger.debug( - "Chat completion config: %s", json.dumps(chat_completion_config, ensure_ascii=False) + "Chat completion config: messages=%d, roles=%s, tools=%d, response_format=%s, " + "model=%s, forwarded_headers=%s", + len(prepared_messages), + summarize_roles(prepared_messages), + len(self.__tools), + "response_format" in chat_completion_config, + chat_completion_config.get("model"), + # Header NAMES only — forwarded X-* header values are never logged, even + # under the payload switch (they may carry auth-adjacent material). + list(self.__forwarded_headers or []), + ) + # Guard the (potentially large) serialization: log_payload no-ops when the switch + # is off, but its json.dumps argument would otherwise still run every request. + # The dump excludes extra_headers entirely — header values are never emitted. + if payloads_enabled(): + loggable = {k: v for k, v in chat_completion_config.items() if k != "extra_headers"} + log_payload( + logger, "Chat completion config: %s", json.dumps(loggable, ensure_ascii=False) ) return chat_completion_config diff --git a/src/quickapp/core/agent/orchestrator.py b/src/quickapp/core/agent/orchestrator.py index ada26407..a47d0269 100644 --- a/src/quickapp/core/agent/orchestrator.py +++ b/src/quickapp/core/agent/orchestrator.py @@ -25,11 +25,13 @@ from quickapp.common.exceptions import OrchestratorExceedMaxIterationsException from quickapp.common.lifecycle_logging import format_duration, format_event from quickapp.common.messages_mixin import MessagesMixin +from quickapp.common.payload_logging import log_payload, summarize_roles from quickapp.common.perf_timer.perf_timer import PerformanceTimer from quickapp.common.presentation_settings import PresentationSettings from quickapp.common.request_async_close_registry import RequestAsyncCloseRegistry from quickapp.common.stage_close_registry import DeferredStageCloseRegistry from quickapp.common.state_holder import StateHolder +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.config.application import ApplicationConfig from quickapp.core.agent.assistant_invoker import AssistantInvoker from quickapp.core.agent.models import STATE_KEY_ORCHESTRATOR, TOOL_EXECUTION_HISTORY @@ -39,6 +41,19 @@ logger = logging.getLogger(__name__) +def _log_messages(label: str, messages: list[Message]) -> None: + """Log a message list as structure (count + role histogram) plus a gated payload.""" + if logger.isEnabledFor(logging.DEBUG): + logger.debug("%s: count=%d, roles=%s", label, len(messages), summarize_roles(messages)) + log_payload(logger, f"{label}: %s", messages) + + +def _log_tool_calls(label: str, tool_calls: list[AccumulatedToolCall]) -> None: + """Log tool calls as structure (names) plus a gated payload (arguments).""" + logger.debug("%s: %s", label, [tc.name for tc in tool_calls]) + log_payload(logger, f"{label}: %s", tool_calls) + + @inject class Orchestrator: @@ -129,7 +144,9 @@ async def _persisting_state(self) -> AsyncIterator[None]: await self.__usage_statistics_service.process_usage_statistics( self.__usage_statistics_list ) - logger.debug(f"State holder: {self.__state_holder.get_state()}") + state = self.__state_holder.get_state() + logger.debug("State holder keys: %s", list(state)) + log_payload(logger, "State holder: %s", state) if exc_to_reraise is not None: raise exc_to_reraise @@ -201,7 +218,7 @@ async def _run_iteration(self) -> bool: ) ) self.__perf_timer.add_milestone(period, "assistant_response_received") - logger.debug("Message from agent: %s", self.__messages_context.messages) + _log_messages("Message from agent", self.__messages_context.messages) if not tool_calls: self.__perf_timer.stop_period(period) @@ -223,17 +240,19 @@ async def _run_iteration(self) -> bool: return False self.__perf_timer.stop_period(period) - logger.debug("Message from context: %s", self.__messages_context.messages) + _log_messages("Message from context", self.__messages_context.messages) return True async def _execute_internal_tool_calls(self, tool_calls: list[AccumulatedToolCall]) -> None: self.__total_tool_calls += len(tool_calls) - logger.debug("Agent requests internal tool calls: %s", tool_calls) + _log_tool_calls("Agent requests internal tool calls", tool_calls) tool_call_results = await self.__tool_executor.execute(tool_calls) if not tool_call_results: - raise RuntimeError(f"Tool call(s) {tool_calls} doesn't return any result.") + names = [tc.name for tc in tool_calls] + raise RuntimeError(f"Tool call(s) {names} doesn't return any result.") - logger.debug("Tool call results: %s", tool_call_results) + logger.debug("Tool call results: count=%d", len(tool_call_results)) + log_payload(logger, "Tool call results: %s", tool_call_results) for tool_call_result in tool_call_results: tool_call_result_message = tool_call_result.to_tool_message() self.__messages_context.append_message(tool_call_result_message) @@ -241,7 +260,9 @@ async def _execute_internal_tool_calls(self, tool_calls: list[AccumulatedToolCal url = attachment.url if url is not None: if url in self.__propagated_attachment_urls: - logger.debug("Skipping duplicate attachment URL %s", url) + logger.debug( + "Skipping duplicate attachment URL %s", sanitize_url_for_log(url) + ) continue self.__propagated_attachment_urls.add(url) self.__choice.add_attachment(**attachment.model_dump(exclude={"index"})) @@ -253,7 +274,7 @@ def _surface_external_tool_calls( ) -> None: self.__total_tool_calls += len(tool_calls) self.__completion_kind = "external_tool_calls" - logger.debug("Surfacing external tool calls to client: %s", tool_calls) + _log_tool_calls("Surfacing external tool calls to client", tool_calls) for tc in tool_calls: self.__choice.create_function_tool_call(tc.id, tc.name, tc.arguments) self.__perf_timer.stop_period(period) diff --git a/src/quickapp/core/agent/tool_executor.py b/src/quickapp/core/agent/tool_executor.py index f317766f..9df0a576 100644 --- a/src/quickapp/core/agent/tool_executor.py +++ b/src/quickapp/core/agent/tool_executor.py @@ -11,6 +11,7 @@ ToolCallResultProcessor, ) from quickapp.common.chat_completion_stream.tool_call import AccumulatedToolCall +from quickapp.common.payload_logging import log_payload from quickapp.common.perf_timer.perf_timer import PerformanceTimer logger = logging.getLogger(__name__) @@ -40,7 +41,8 @@ async def execute(self, tool_call_list: list[AccumulatedToolCall]) -> list[ToolC if tool is None: continue args = json.loads(tc.arguments) - logger.debug(f"Making tool calls: {tc.name} with args:{args}") + logger.debug("Making tool call: %s", tc.name) + log_payload(logger, "Making tool call: %s with args: %s", tc.name, args) tasks.append(tool.arun(tool_call_id=tc.id, **args)) valid_calls.append(tc) diff --git a/src/quickapp/core/application/_exception_message_resolver.py b/src/quickapp/core/application/_exception_message_resolver.py index 98f6504c..27a5794b 100644 --- a/src/quickapp/core/application/_exception_message_resolver.py +++ b/src/quickapp/core/application/_exception_message_resolver.py @@ -282,14 +282,17 @@ def _resolve_tool_error(e: ToolErrorException) -> ResolvedError | None: - If it wraps an httpx cause, delegate to the cause's resolution so the caller gets the appropriate HTTP-specific message (e.g. permission-denied, timeout). - - If there is no cause, expose the tool error text directly (contains tool name). + - If there is no cause, expose the tool error text directly. Built from + ``error_message`` rather than ``str(e)``: the exception's string form is structural + by the content rule (issue #436), while this user-facing message keeps the real text. - If the cause is something other than an httpx error, return None to fall through to the generic fallback. """ if isinstance(e.__cause__, httpx.HTTPError): return resolve_exception(e.__cause__) if e.__cause__ is None: - return _compose(str(e), False, ErrorDetails()) + message = f"{e.tool_kind} '{e.tool_name}' returned an error: {e.error_message}" + return _compose(message, False, ErrorDetails()) return None diff --git a/src/quickapp/dial_core_services/_interactive_login_service.py b/src/quickapp/dial_core_services/_interactive_login_service.py index 15565ca2..6f7688a7 100644 --- a/src/quickapp/dial_core_services/_interactive_login_service.py +++ b/src/quickapp/dial_core_services/_interactive_login_service.py @@ -11,6 +11,7 @@ from quickapp.common._di_types import CLIENT_CHANNEL_HEADER from quickapp.common.dial_settings import DialSettings from quickapp.common.lifecycle_logging import format_duration, format_event +from quickapp.common.payload_logging import log_payload from quickapp.dial_core_services._interactive_login_settings import InteractiveLoginSettings from quickapp.dial_core_services._login_result import LoginResult @@ -131,7 +132,10 @@ def _parse_batch_response( try: entries = json.loads(data) except (json.JSONDecodeError, TypeError): - logger.exception("Failed to parse interactive login response: %s", data) + logger.exception( + "Failed to parse interactive login response (length=%d)", len(data) if data else 0 + ) + log_payload(logger, "Interactive login response body: %s", data) return {tid: LoginResult.ERROR for tid in toolset_dial_ids} if not isinstance(entries, list): diff --git a/src/quickapp/dial_core_services/attachment_service.py b/src/quickapp/dial_core_services/attachment_service.py index 852be5d6..d074be03 100644 --- a/src/quickapp/dial_core_services/attachment_service.py +++ b/src/quickapp/dial_core_services/attachment_service.py @@ -6,6 +6,7 @@ from aidial_sdk.chat_completion import Attachment from injector import inject +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.common.utils import generate_attachment_filename logger = logging.getLogger(__name__) @@ -28,7 +29,10 @@ def __init__(self, dial_client: AsyncDial): async def upload_attachment_to_core(self, attachment: Attachment) -> Attachment: logger.debug( - f"Uploading attachment: {attachment.title}, url: {attachment.url}, data present: {attachment.data is not None}" + "Uploading attachment: %s, url: %s, data present: %s", + attachment.title, + sanitize_url_for_log(attachment.url) if attachment.url else None, + attachment.data is not None, ) if attachment.url is None and attachment.data: try: @@ -41,7 +45,11 @@ async def upload_attachment_to_core(self, attachment: Attachment) -> Attachment: # Use URL instead of data for uploaded attachment. attachment.data = None attachment.url = metadata.url - logger.debug(f"Uploaded attachment {attachment_name} to {attachment.url}") + logger.debug( + "Uploaded attachment %s to %s", + attachment_name, + sanitize_url_for_log(attachment.url), + ) except Exception: logger.exception( "Exception during uploading attachment to DIAL. Original attachment left in place." diff --git a/src/quickapp/dial_core_services/dial_downloader.py b/src/quickapp/dial_core_services/dial_downloader.py index a87f2194..21126d9c 100644 --- a/src/quickapp/dial_core_services/dial_downloader.py +++ b/src/quickapp/dial_core_services/dial_downloader.py @@ -4,6 +4,7 @@ from aidial_client.types.metadata import FileMetadata from injector import inject +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.shared.config_resolvers.file_loading_size_limit_resolver import ( FileLoadingSizeLimitResolver, ) @@ -35,7 +36,7 @@ def __init__( self.__content_size_limit: int = size_limit_resolver.resolve() async def fetch(self, file_url: str) -> tuple[bytes, FileMetadata]: - logger.debug("Downloading DIAL file: %s", file_url) + logger.debug("Downloading DIAL file: %s", sanitize_url_for_log(file_url)) metadata = await self.__dial_client.files.get_metadata(file_url) size = metadata.content_length or 0 if size > self.__content_size_limit: diff --git a/src/quickapp/dial_core_services/dial_file_service.py b/src/quickapp/dial_core_services/dial_file_service.py index e6e09e91..3eeefd88 100644 --- a/src/quickapp/dial_core_services/dial_file_service.py +++ b/src/quickapp/dial_core_services/dial_file_service.py @@ -10,6 +10,7 @@ from pydantic import BaseModel, ConfigDict from quickapp.common.state_holder import StateHolder +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.shared.config_resolvers.file_loading_size_limit_resolver import ( FileLoadingSizeLimitResolver, ) @@ -68,12 +69,13 @@ async def _get_metadata(self, url: str) -> FileMetadata: self._reraise_404_as_not_found(e) async def download_file(self, file_url: str) -> tuple[bytes, FileMetadata | None]: - logger.debug(f"File url to download url:{file_url}") + safe_url = sanitize_url_for_log(file_url) + logger.debug("File url to download: %s", safe_url) file_data = self.__state_holder.get_file_data(url=file_url) if file_data is not None: return file_data, self.__state_holder.get_file_metadata(file_url) try: - logger.debug(f"Downloading file:{file_url}") + logger.debug("Downloading file: %s", safe_url) metadata = await self._get_metadata(file_url) size = metadata.content_length or 0 if size > self.__content_size_limit: @@ -83,7 +85,7 @@ async def download_file(self, file_url: str) -> tuple[bytes, FileMetadata | None file_data = await (await self.__dial_client.files.download(file_url)).aget_content() self.__state_holder.store_file_data(file_url, file_data, metadata) except Exception as e: - logger.error("Failed to download: %s", file_url, exc_info=True) + logger.error("Failed to download: %s", safe_url, exc_info=True) raise e return file_data, metadata @@ -193,7 +195,10 @@ async def grant_permissions_to_files( self, files_to_share: list[str], dial_toolset_id: str ) -> None: try: - logger.debug(f"Granting permissions to files: {files_to_share}") + logger.debug( + "Granting permissions to files: %s", + [sanitize_url_for_log(f) for f in files_to_share], + ) await self.__dial_client.resource_permissions.grant( resources=files_to_share, receiver=dial_toolset_id, diff --git a/src/quickapp/dial_deployment_tooling/base_deployment_tool.py b/src/quickapp/dial_deployment_tooling/base_deployment_tool.py index 3fd336c1..6cbeec4c 100644 --- a/src/quickapp/dial_deployment_tooling/base_deployment_tool.py +++ b/src/quickapp/dial_deployment_tooling/base_deployment_tool.py @@ -16,6 +16,7 @@ from quickapp.common.abstract.base_tool_argument_transformer import ToolArgumentTransformer from quickapp.common.base_stage_wrapper import BaseStageWrapper from quickapp.common.messages_mixin import MessagesMixin +from quickapp.common.payload_logging import log_payload from quickapp.common.perf_timer.perf_timer import PerformanceTimer from quickapp.common.utils import to_plain_dict from quickapp.config.dial_deployment import DialDeploymentParameters @@ -215,7 +216,8 @@ async def _pre_process_params(self, **kwargs: Any) -> dict[str, Any]: # Standard params override defaults as flat keys prepared.update(other_kwargs) - logger.debug(f"Pre-processed tool parameters: {prepared}") + logger.debug("Pre-processed tool parameters: keys=%s", list(prepared)) + log_payload(logger, "Pre-processed tool parameters: %s", prepared) return prepared diff --git a/src/quickapp/dial_files_tooling/_path_argument_transformer.py b/src/quickapp/dial_files_tooling/_path_argument_transformer.py index 9cf4a207..fa71b2af 100644 --- a/src/quickapp/dial_files_tooling/_path_argument_transformer.py +++ b/src/quickapp/dial_files_tooling/_path_argument_transformer.py @@ -4,6 +4,7 @@ from injector import inject from quickapp.common.abstract.base_tool_argument_transformer import ToolArgumentTransformer +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.dial_files_tooling._home_path_resolver import _HomePathResolver logger = logging.getLogger(__name__) @@ -39,6 +40,11 @@ async def transform(self, kwargs: dict[str, Any]) -> dict[str, Any]: # home dir, or when the appdata namespace cannot be resolved. relative = await self._home_resolver.to_display_path(value) if relative != value: - logger.debug("Relativized argument %s: %s -> %s", name, value, relative) + logger.debug( + "Relativized argument %s: %s -> %s", + name, + sanitize_url_for_log(value), + sanitize_url_for_log(relative), + ) kwargs[name] = relative return kwargs diff --git a/src/quickapp/file_transfer/_file_argument_transformer.py b/src/quickapp/file_transfer/_file_argument_transformer.py index 37060390..e3a3c41e 100644 --- a/src/quickapp/file_transfer/_file_argument_transformer.py +++ b/src/quickapp/file_transfer/_file_argument_transformer.py @@ -6,6 +6,8 @@ from quickapp.common.abstract.base_tool_argument_transformer import ToolArgumentTransformer from quickapp.common.exceptions import InvalidToolCallParameterException from quickapp.common.file_reference_pattern import FILE_PATTERN +from quickapp.common.payload_logging import log_payload +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.file_transfer._file_loader_service import FileLoaderService from quickapp.file_transfer._file_prefix_handlers import FilePrefixHandlers @@ -40,8 +42,10 @@ async def transform(self, kwargs: dict[str, Any]) -> dict[str, Any]: async def _resolve_value_and_log(self, key: str, value: str) -> str: resolved_value = await self._resolve_value(key, value) if resolved_value is not value: - logger.debug( - "Argument %s resolved to new value (original: %s, resolved: %s)", + logger.debug("Argument %s resolved (resolved_length=%d)", key, len(resolved_value)) + log_payload( + logger, + "Argument %s resolved (original: %s, resolved: %s)", key, value, resolved_value, @@ -60,7 +64,7 @@ async def _resolve_value(self, key: str, value: str) -> str: logger.debug( "Detected 'base64' prefix for key %s (url: %s) - placeholder handling", key, - file_url_part, + sanitize_url_for_log(file_url_part), ) return await FilePrefixHandlers.handle_base64( file_url_part, self.__file_service, parameter_name=key @@ -69,22 +73,21 @@ async def _resolve_value(self, key: str, value: str) -> str: logger.debug( "Detected 'url' prefix for key %s (url: %s) - placeholder handling", key, - file_url_part, + sanitize_url_for_log(file_url_part), ) return file_url_part elif detected_prefix == "text": logger.debug( - "Detected 'text' prefix for key %s (text: %s) - placeholder handling", + "Detected 'text' prefix for key %s (url: %s) - placeholder handling", key, - file_url_part, + sanitize_url_for_log(file_url_part), ) return await FilePrefixHandlers.handle_text( file_url_part, self.__file_service, parameter_name=key ) else: - logger.warning( - "Detected file reference without prefix for key %s (value: %s)", key, value - ) + logger.warning("Detected file reference without prefix for key %s", key) + log_payload(logger, "File reference without prefix for key %s: %s", key, value) raise InvalidToolCallParameterException( parameter_name=key, message="Missing required file prefix (base64::, url::, text::)", diff --git a/src/quickapp/file_transfer/_file_prefix_handlers.py b/src/quickapp/file_transfer/_file_prefix_handlers.py index 1199eb6f..56863d6e 100644 --- a/src/quickapp/file_transfer/_file_prefix_handlers.py +++ b/src/quickapp/file_transfer/_file_prefix_handlers.py @@ -2,6 +2,7 @@ import logging from quickapp.common.exceptions import InvalidToolCallParameterException +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.file_transfer._file_loader_service import FileLoaderService logger = logging.getLogger(__name__) @@ -27,7 +28,10 @@ async def handle_base64( try: content = bytes(content) except Exception: - logger.exception("Failed to coerce downloaded content to bytes for %s", file_url) + logger.exception( + "Failed to coerce downloaded content to bytes for %s", + sanitize_url_for_log(file_url), + ) raise InvalidToolCallParameterException( parameter_name=parameter_name, message="Downloaded content is not bytes and cannot be converted to base64.", @@ -44,7 +48,10 @@ async def handle_text( try: content_bytes = bytes(content_bytes) except Exception: - logger.exception("Failed to coerce downloaded content to bytes for %s", file_url) + logger.exception( + "Failed to coerce downloaded content to bytes for %s", + sanitize_url_for_log(file_url), + ) raise InvalidToolCallParameterException( parameter_name=parameter_name, message="Downloaded content is not bytes and cannot be converted to text.", @@ -52,15 +59,16 @@ async def handle_text( for sig, desc in _BINARY_SIGNATURES: if content_bytes.startswith(sig): + safe_url = sanitize_url_for_log(file_url) logger.warning( "Downloaded file %s appears to be binary (%s); 'text' prefix is invalid for binary files", - file_url, + safe_url, desc, ) raise InvalidToolCallParameterException( parameter_name=parameter_name, message=( - f"File at {file_url} appears to be binary ({desc}). " + f"File at {safe_url} appears to be binary ({desc}). " "Use `file:base64::...` or `file:URL::...` instead of `file:text::...`." ), ) diff --git a/src/quickapp/mcp_tooling/_mcp_tool.py b/src/quickapp/mcp_tooling/_mcp_tool.py index 0c3f8788..34087d76 100644 --- a/src/quickapp/mcp_tooling/_mcp_tool.py +++ b/src/quickapp/mcp_tooling/_mcp_tool.py @@ -10,10 +10,11 @@ from quickapp.common.base_stage_wrapper import BaseStageWrapper from quickapp.common.dial_settings import DialSettings from quickapp.common.exceptions import InvalidToolCallParameterException +from quickapp.common.payload_logging import log_payload from quickapp.common.perf_timer.perf_timer import PerformanceTimer from quickapp.common.state_holder import StateHolder from quickapp.common.tool_timeout_utils import translate_timeout -from quickapp.common.url_classification import UrlScheme, classify_url +from quickapp.common.url_classification import UrlScheme, classify_url, sanitize_url_for_log from quickapp.common.utils import generate_attachment_filename, matches_type from quickapp.config.application import StageDisplayLevel from quickapp.config.tools.mcp import MCPTool @@ -124,7 +125,7 @@ def _collect_dial_url_files(self, kwargs: dict[str, Any]) -> list[str]: parameter_name=key, message=( f"Parameter `{key}` requires a DIAL file but received an " - f"unsupported URL: {candidate}." + f"unsupported URL: {sanitize_url_for_log(candidate)}." ), ) files_to_share.extend(candidates) @@ -176,7 +177,8 @@ async def _run_in_stage_async( *args: Any, **kwargs: Any, ) -> ToolCallResult: - logger.debug(f"MCP tool called with {kwargs}") + logger.debug("MCP tool called with args: keys=%s", list(kwargs)) + log_payload(logger, "MCP tool called with args: %s", kwargs) timeout = self.__timeout_resolver.resolve() # Wrap the outer body: anyio task groups can raise BaseExceptionGroup, which @@ -215,13 +217,14 @@ async def _run_in_stage_async( tool_content = "\n\n".join(filter(None, text_parts)) # Detect-and-raise only; the StagedBaseTool choke point owns the failure - # WARNING, so this stays at DEBUG (ownership rule). Body stripped by #436. + # WARNING, so this stays at DEBUG (ownership rule). Structure only — the + # response body and structuredContent are not logged (content rule, #436). if getattr(tool_call_result, "isError", False): logger.debug( - "MCP tool '%s' returned isError=True; error: %s; structuredContent: %s", + "MCP tool '%s' returned isError=True; content_length=%d, structured_content=%s", self.__tool.name, - tool_content, - getattr(tool_call_result, "structuredContent", None), + len(tool_content), + getattr(tool_call_result, "structuredContent", None) is not None, ) raise MCPToolErrorException(self.__tool.name, tool_content) diff --git a/src/quickapp/mcp_tooling/_mcp_tool_error_exception.py b/src/quickapp/mcp_tooling/_mcp_tool_error_exception.py index 0b41fc81..9bf82cca 100644 --- a/src/quickapp/mcp_tooling/_mcp_tool_error_exception.py +++ b/src/quickapp/mcp_tooling/_mcp_tool_error_exception.py @@ -2,7 +2,11 @@ class MCPToolErrorException(ToolErrorException): - """Raised when an MCP tool call returns isError=True.""" + """Raised when an MCP tool call returns isError=True. - def __str__(self) -> str: - return f"MCP tool '{self.tool_name}' returned an error: {self.error_message}" + Inherits the base's structural ``__str__`` (no response body) so the failure's + log/traceback records honor the content rule; the body stays on ``error_message`` for + the LLM/user channels. + """ + + tool_kind = "MCP tool" diff --git a/src/quickapp/rest_api_tooling/_rest_api_tool.py b/src/quickapp/rest_api_tooling/_rest_api_tool.py index 58ec6fe6..87a86a9b 100644 --- a/src/quickapp/rest_api_tooling/_rest_api_tool.py +++ b/src/quickapp/rest_api_tooling/_rest_api_tool.py @@ -120,7 +120,11 @@ async def _run_in_stage_async( title = generate_attachment_filename( mime_type, base_filename=self._tool_config.open_ai_tool.function.name ) - logger.debug(f"Attachment: {title}, Tool Config: {self._tool_config}") + logger.debug( + "Building attachment %s for REST tool %s", + title, + self._tool_config.open_ai_tool.function.name, + ) attachment = Attachment(title=title, type=mime_type, data=response.text) attachment = await self.__dial_attachment_service.upload_attachment_to_core( attachment diff --git a/src/quickapp/rest_api_tooling/_rest_api_tool_error_exception.py b/src/quickapp/rest_api_tooling/_rest_api_tool_error_exception.py index d52cb44c..c9be44d6 100644 --- a/src/quickapp/rest_api_tooling/_rest_api_tool_error_exception.py +++ b/src/quickapp/rest_api_tooling/_rest_api_tool_error_exception.py @@ -2,7 +2,10 @@ class RestApiToolErrorException(ToolErrorException): - """Raised when a REST API tool call returns a non-success HTTP status.""" + """Raised when a REST API tool call returns a non-success HTTP status. - def __str__(self) -> str: - return f"REST API tool '{self.tool_name}' returned an error: {self.error_message}" + Inherits the base's structural ``__str__``; the (already status-only) ``error_message`` + stays available for the LLM/user channels. + """ + + tool_kind = "REST API tool" diff --git a/src/quickapp/shared/external_fetch/external_url_fetcher.py b/src/quickapp/shared/external_fetch/external_url_fetcher.py index d7f14f41..a6d2a759 100644 --- a/src/quickapp/shared/external_fetch/external_url_fetcher.py +++ b/src/quickapp/shared/external_fetch/external_url_fetcher.py @@ -12,6 +12,7 @@ from injector import inject from pydantic import BaseModel, ConfigDict +from quickapp.common.url_classification import sanitize_url_for_log from quickapp.common.utils import filename_from_url_path, sanitize_filename from quickapp.shared.config_resolvers.file_loading_size_limit_resolver import ( FileLoadingSizeLimitResolver, @@ -361,5 +362,7 @@ async def fetch(self, url: str) -> FetchedBytes: except httpx.TimeoutException as exc: raise ExternalFetchError(reason="timeout", url=url, detail=str(exc)) from exc except httpx.HTTPError as exc: - logger.debug("External fetch failed for %s", url, exc_info=True) + logger.debug( + "External fetch failed for %s", sanitize_url_for_log(url), exc_info=True + ) raise ExternalFetchError(reason="transport", url=url, detail=str(exc)) from exc diff --git a/src/tests/unit_tests/application_tests/test_exception_message_resolver.py b/src/tests/unit_tests/application_tests/test_exception_message_resolver.py index 45fd3abf..4a89f704 100644 --- a/src/tests/unit_tests/application_tests/test_exception_message_resolver.py +++ b/src/tests/unit_tests/application_tests/test_exception_message_resolver.py @@ -10,6 +10,7 @@ ToolsetForbiddenException, ToolsetNotFoundException, ) +from quickapp.mcp_tooling._mcp_tool_error_exception import MCPToolErrorException def _make_httpx_request() -> httpx.Request: @@ -309,7 +310,20 @@ def test_details_carried_on_resolved_error(self) -> None: def test_tool_error_without_cause_uses_tool_error_message(self) -> None: e = ToolErrorException("some_tool", "public tool error") - assert "some_tool" in _resolve(e).lower() + resolved = _resolve(e) + assert "some_tool" in resolved.lower() + # The user message is built from error_message, not the structural str(e). + assert "public tool error" in resolved + assert "content_length" not in resolved + + def test_mcp_tool_error_without_cause_surfaces_body_not_structural_str(self) -> None: + # str(e) is structural for logs; the user-facing message keeps the real MCP text + # and the "MCP tool" label (tool_kind), not the generic "Tool". + e = MCPToolErrorException("mcp_tool", "the real mcp error text") + resolved = _resolve(e) + assert "the real mcp error text" in resolved + assert "MCP tool" in resolved + assert "content_length" not in resolved def test_tool_error_with_non_http_cause_uses_generic_fallback(self) -> None: e = ToolErrorException("rest_tool", "public tool error") diff --git a/src/tests/unit_tests/common/test_payload_logging.py b/src/tests/unit_tests/common/test_payload_logging.py new file mode 100644 index 00000000..eab8199f --- /dev/null +++ b/src/tests/unit_tests/common/test_payload_logging.py @@ -0,0 +1,91 @@ +"""Tests for the payload-debugging switch (common.payload_logging, issue #436).""" + +import logging +from types import SimpleNamespace + +import pytest + +from quickapp.common.payload_logging import ( + _truncate, + configure_payload_logging, + log_payload, + payloads_enabled, + summarize_roles, +) + + +@pytest.fixture(autouse=True) +def reset_payload_config(): + """The switch is module-global; restore the (off) defaults after each test.""" + yield + configure_payload_logging(enabled=False, max_length=2000) + + +class TestConfigureAndEnabled: + def test_disabled_by_default(self): + assert payloads_enabled() is False + + def test_configure_toggles_enabled(self): + configure_payload_logging(enabled=True, max_length=50) + assert payloads_enabled() is True + + +class TestTruncate: + def test_short_value_unchanged(self): + configure_payload_logging(enabled=True, max_length=10) + assert _truncate("hello") == "hello" + + def test_value_at_cap_not_truncated(self): + configure_payload_logging(enabled=True, max_length=5) + assert _truncate("abcde") == "abcde" + + def test_long_value_truncated_with_marker(self): + configure_payload_logging(enabled=True, max_length=5) + result = _truncate("abcdefghij") + assert result.startswith("abcde") + assert "abcdefghij" not in result + assert len(result) > len("abcde") # a marker was appended + + def test_non_string_is_stringified(self): + configure_payload_logging(enabled=True, max_length=100) + assert _truncate({"a": 1}) == "{'a': 1}" + + +class TestLogPayload: + def test_noop_when_disabled(self, caplog): + configure_payload_logging(enabled=False, max_length=2000) + logger = logging.getLogger("quickapp.test.payload") + with caplog.at_level(logging.DEBUG, logger="quickapp.test.payload"): + log_payload(logger, "message body: %s", "secret user content") + assert caplog.records == [] + + def test_emits_and_truncates_when_enabled(self, caplog): + configure_payload_logging(enabled=True, max_length=4) + logger = logging.getLogger("quickapp.test.payload") + with caplog.at_level(logging.DEBUG, logger="quickapp.test.payload"): + log_payload(logger, "body: %s", "abcdefgh") + assert len(caplog.records) == 1 + rendered = caplog.records[0].getMessage() + assert "abcd" in rendered + assert "abcdefgh" not in rendered + + +class TestSummarizeRoles: + def test_counts_object_roles(self): + messages = [ + SimpleNamespace(role="user"), + SimpleNamespace(role="assistant"), + SimpleNamespace(role="user"), + ] + counts = summarize_roles(messages) + assert counts["user"] == 2 + assert counts["assistant"] == 1 + + def test_counts_dict_roles(self): + counts = summarize_roles([{"role": "system"}, {"role": "user"}]) + assert counts["system"] == 1 + assert counts["user"] == 1 + + def test_missing_role_falls_under_unknown(self): + counts = summarize_roles([{"content": "x"}, object()]) + assert counts["unknown"] == 2 diff --git a/src/tests/unit_tests/common/test_tool_error.py b/src/tests/unit_tests/common/test_tool_error.py new file mode 100644 index 00000000..452fb6e0 --- /dev/null +++ b/src/tests/unit_tests/common/test_tool_error.py @@ -0,0 +1,47 @@ +"""The tool-error exceptions keep their string form structural (content rule, #436) +while preserving the body on ``error_message`` for the LLM/user channels (#408).""" + +from quickapp.common.exceptions.tool_error import ToolErrorException +from quickapp.common.tool_fallback.utils import compose_tool_error_fallback_message +from quickapp.mcp_tooling._mcp_tool_error_exception import MCPToolErrorException +from quickapp.rest_api_tooling._rest_api_tool_error_exception import RestApiToolErrorException + +_BODY = "detailed tool response body that must never leak into logs" + + +class TestStructuralMessage: + def test_base_str_omits_body(self): + e = ToolErrorException("my_tool", _BODY) + assert _BODY not in str(e) + assert f"content_length={len(_BODY)}" in str(e) + + def test_mcp_str_omits_body_but_names_tool(self): + e = MCPToolErrorException("mcp_tool", _BODY) + rendered = str(e) + assert _BODY not in rendered + assert "mcp_tool" in rendered + assert f"content_length={len(_BODY)}" in rendered + + +class TestBodyPreservedForNonLogChannels: + def test_base_keeps_error_message_and_tool_name(self): + e = ToolErrorException("my_tool", _BODY) + assert e.error_message == _BODY + assert e.tool_name == "my_tool" + + def test_mcp_keeps_error_message(self): + assert MCPToolErrorException("mcp_tool", _BODY).error_message == _BODY + + def test_forwarding_to_llm_still_carries_body(self): + e = MCPToolErrorException("mcp_tool", _BODY) + message = compose_tool_error_fallback_message( + instructions="Try a different approach.", + error=e, + forward_tool_error_message=True, + ) + assert _BODY in message + + def test_rest_error_message_is_status_only(self): + # REST's error_message is already a status string (no body); left as-is. + e = RestApiToolErrorException("rest_tool", "HTTP error 500 while calling REST API tool.") + assert e.error_message == "HTTP error 500 while calling REST API tool." diff --git a/src/tests/unit_tests/common/test_url_classification.py b/src/tests/unit_tests/common/test_url_classification.py index 0765e940..99a66c32 100644 --- a/src/tests/unit_tests/common/test_url_classification.py +++ b/src/tests/unit_tests/common/test_url_classification.py @@ -1,6 +1,6 @@ import pytest -from quickapp.common.url_classification import UrlScheme, classify_url +from quickapp.common.url_classification import UrlScheme, classify_url, sanitize_url_for_log DIAL_URL = "https://dial.example.com" @@ -77,3 +77,26 @@ def test_unsupported_or_malformed_classify_as_unsupported(url: str): def test_dial_base_url_without_host_treats_http_url_as_external(): assert classify_url("https://example.com/x", "not-a-real-url") == UrlScheme.EXTERNAL + + +class TestSanitizeUrlForLog: + def test_strips_query_string_and_fragment(self): + url = "https://host.example.com/path/to/file.pdf?sig=SECRET&exp=123#frag" + assert sanitize_url_for_log(url) == "https://host.example.com/path/to/file.pdf" + + def test_strips_userinfo(self): + url = "https://user:password@host.example.com/path?token=x" + assert sanitize_url_for_log(url) == "https://host.example.com/path" + + def test_preserves_port(self): + url = "https://host.example.com:8443/path?q=1" + assert sanitize_url_for_log(url) == "https://host.example.com:8443/path" + + def test_relative_dial_path_preserved_without_query(self): + assert sanitize_url_for_log("files/bucket/foo.pdf?token=x") == "files/bucket/foo.pdf" + + def test_relative_dial_path_without_query_unchanged(self): + assert sanitize_url_for_log("files/bucket/foo.pdf") == "files/bucket/foo.pdf" + + def test_empty_string_returned_as_is(self): + assert sanitize_url_for_log("") == "" diff --git a/src/tests/unit_tests/config_tests/test_logging_config.py b/src/tests/unit_tests/config_tests/test_logging_config.py index 9237884a..a22671f8 100644 --- a/src/tests/unit_tests/config_tests/test_logging_config.py +++ b/src/tests/unit_tests/config_tests/test_logging_config.py @@ -6,8 +6,14 @@ import pytest import uvicorn.logging +from quickapp.common import payload_logging +from quickapp.common.payload_logging import configure_payload_logging from quickapp.config._otel_aware_formatter import OtelAwareFormatter -from quickapp.config.logging_config import MANAGED_LOGGER_NAMES, LoggingConfig +from quickapp.config.logging_config import ( + MANAGED_LOGGER_NAMES, + PAYLOAD_CAPPED_LOGGERS, + LoggingConfig, +) from quickapp.config.logging_settings import LoggingSettings @@ -65,6 +71,7 @@ def reset_logging_state(): ) ) saved_factory = logging.getLogRecordFactory() + saved_payloads = (payload_logging.payloads_enabled(), payload_logging._max_length) yield @@ -74,6 +81,8 @@ def reset_logging_state(): logger.setLevel(level) logger.propagate = propagate logger.filters = filters + # LoggingConfig mutates the module-global payload switch; restore it too. + configure_payload_logging(*saved_payloads) class TestOtelAwareFormatter: @@ -259,3 +268,52 @@ def test_quickapp_level_pin_filters_debug(self, monkeypatch, reset_logging_state logging.getLogger("quickapp.x").debug("filtered-out") assert recorder.records == [] + + +class TestThirdPartyPayloadCap: + """openai/httpx/httpcore emit payloads at DEBUG; they must stay capped at INFO + unless the LOG_PAYLOADS switch is on, regardless of LOG_LEVEL (issue #436).""" + + @pytest.mark.parametrize("name", PAYLOAD_CAPPED_LOGGERS) + def test_capped_at_info_when_payloads_disabled(self, name, monkeypatch, reset_logging_state): + monkeypatch.setenv("LOG_LEVEL", "DEBUG") + monkeypatch.delenv("LOG_PAYLOADS", raising=False) + + LoggingConfig(LoggingSettings()) + + assert logging.getLogger(name).level == logging.INFO + + @pytest.mark.parametrize("name", PAYLOAD_CAPPED_LOGGERS) + def test_uncapped_when_payloads_enabled(self, name, monkeypatch, reset_logging_state): + monkeypatch.setenv("LOG_LEVEL", "DEBUG") + monkeypatch.setenv("LOG_PAYLOADS", "true") + + LoggingConfig(LoggingSettings()) + + assert logging.getLogger(name).level == logging.DEBUG + + def test_cap_never_lowers_a_more_restrictive_level(self, monkeypatch, reset_logging_state): + monkeypatch.setenv("LOG_LEVEL", "WARNING") + monkeypatch.delenv("LOG_PAYLOADS", raising=False) + + LoggingConfig(LoggingSettings()) + + assert logging.getLogger("openai").level == logging.WARNING + + def test_non_capped_managed_logger_follows_log_level(self, monkeypatch, reset_logging_state): + monkeypatch.setenv("LOG_LEVEL", "DEBUG") + monkeypatch.delenv("LOG_PAYLOADS", raising=False) + + LoggingConfig(LoggingSettings()) + + # aidial_sdk is managed but not payload-capped -> tracks LOG_LEVEL. + assert logging.getLogger("aidial_sdk").level == logging.DEBUG + + def test_logging_config_configures_payload_switch(self, monkeypatch, reset_logging_state): + monkeypatch.setenv("LOG_PAYLOADS", "true") + monkeypatch.setenv("LOG_PAYLOADS_MAX_LENGTH", "77") + + LoggingConfig(LoggingSettings()) + + assert payload_logging.payloads_enabled() is True + assert payload_logging._max_length == 77 diff --git a/src/tests/unit_tests/config_tests/test_logging_settings.py b/src/tests/unit_tests/config_tests/test_logging_settings.py new file mode 100644 index 00000000..c96773c0 --- /dev/null +++ b/src/tests/unit_tests/config_tests/test_logging_settings.py @@ -0,0 +1,24 @@ +"""Tests for the LOG_PAYLOADS settings (LoggingSettings, issue #436).""" + +from quickapp.config.logging_settings import LoggingSettings + + +class TestPayloadSettings: + def test_defaults(self, monkeypatch): + monkeypatch.delenv("LOG_PAYLOADS", raising=False) + monkeypatch.delenv("LOG_PAYLOADS_MAX_LENGTH", raising=False) + + settings = LoggingSettings() + + assert settings.log_payloads is False + assert settings.log_payloads_max_length == 2000 + + def test_log_payloads_parsed_from_env(self, monkeypatch): + monkeypatch.setenv("LOG_PAYLOADS", "true") + + assert LoggingSettings().log_payloads is True + + def test_max_length_parsed_from_env(self, monkeypatch): + monkeypatch.setenv("LOG_PAYLOADS_MAX_LENGTH", "50") + + assert LoggingSettings().log_payloads_max_length == 50