diff --git a/CODESTYLE.md b/CODESTYLE.md index f05cc5e4..48229c0f 100644 --- a/CODESTYLE.md +++ b/CODESTYLE.md @@ -158,6 +158,29 @@ def __init__(self, ..., agent_settings: AgentSettings) -> None: - **Use the logging module**: Use Python’s `logging` (e.g. `logger.info`, `logger.debug`, `logger.exception`) instead of `print()` for production behavior. Configure log levels appropriately (e.g. via `LoggingSettings` / `QUICKAPP_LOG_LEVEL`). - **Graceful error handling**: Use exceptions where appropriate. Avoid silent failures; log or re-raise with clear messages so issues are visible and debuggable. +### Level semantics + +Pick the level from what the record *means for the service*, not from how it reads while developing (design: [`docs/designs/log_levels_and_content_policy.md`](docs/designs/log_levels_and_content_policy.md)): + +| Level | Meaning | Examples | +|---|---|---| +| **DEBUG** | Developer diagnostics: control flow, intermediate values, structure summaries. Verbose, not a narrative. | State-holder summaries, routine rejections/skips, perf reports | +| **INFO** | The operational narrative: startup/config summaries plus the per-request lifecycle skeleton. Metadata-only, low bounded volume per request. | Request received, model call, tool executed, fallback applied, request completed | +| **WARNING** | Something unexpected happened and the service handled it; the request continues, possibly degraded. | Stream recovery applied, unsupported content block tolerated, tool failure handed to a fallback, deprecated config | +| **ERROR** | A failure that affected the request outcome or cost the service functionality; each occurrence is worth investigating. | Unhandled request exception (with `error_reference`), toolset init failure surfaced to the user | + +### Single-writer rule for ERROR (and WARNING) + +- A failure is logged at **ERROR exactly once**, by the layer that *owns its final handling*. In the request path that owner is `_QuickAppCompletion` (the `error_reference` record). +- A layer that hands a failure onward — to a fallback strategy, a recovery policy, or by (re-)raising for an upstream handler — logs at **WARNING or not at all**, never ERROR. `StagedBaseTool` (the tool choke point) writes the single WARNING for a tool failure; layers beneath it that merely detect and raise (e.g. `_MCPTool`) stay at DEBUG. +- One failure gets **one salient record per severity** — do not re-log the same failure as it propagates up. + +### 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.) +- 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. + --- ## 10. Linters and formatters diff --git a/docs/agent.md b/docs/agent.md index ecb2f0aa..a5837d48 100644 --- a/docs/agent.md +++ b/docs/agent.md @@ -118,6 +118,29 @@ The orchestrator is retrieved from the DI container and its invoke method is cal --- +## Logging + +At `INFO`, one request emits a compact, metadata-only **lifecycle skeleton** — enough to reconstruct what a +request did during an incident without raising verbosity or exposing conversation content: + +| Event | Owner | +|---|---| +| `Request received` (deployment, message/attachment counts) | `_QuickAppCompletion` | +| `Request initialized` (tool counts per type, skills, contexts) | `_QuickAppCompletion` | +| `Interactive login requested` / `resolved` (toolsets, per-toolset outcome, duration) | `InteractiveLoginService` | +| `Model call completed` (iteration, deployment, duration, finish, requested tools, token usage) | `Orchestrator` | +| `Tool call completed` (tool, tool_call_id, duration, outcome) | `StagedBaseTool` | +| `Fallback applied` (tool_call_id, strategy) | `FallbackProcessor` | +| `Request completed` (outcome, iterations, tool calls, duration, `error_reference` on failure) | `_QuickAppCompletion` | + +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`. +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). + +--- + ## Agent Loop (Orchestrator) The orchestrator implements an iterative agent loop that continues until the LLM produces a final response without tool diff --git a/src/quickapp/common/lifecycle_logging.py b/src/quickapp/common/lifecycle_logging.py new file mode 100644 index 00000000..cc059252 --- /dev/null +++ b/src/quickapp/common/lifecycle_logging.py @@ -0,0 +1,39 @@ +"""Formatting for the INFO request-lifecycle skeleton (design #434, issue #435). + +The request skeleton is written as a stable message ``prefix`` followed by +``key=value`` fields rather than free prose, so later work — JSON output (#438) +and request-scoped ids (#439) — can lift the same fields into structured +attributes without rewording the events. + +Only structural metadata belongs in these records (roles, counts, sizes, +durations, names, ids, statuses); never message bodies, tool-call arguments, or +other payload content (the content rule, delivered by #436). +""" + +from collections.abc import Mapping +from typing import Any + + +def _render(value: Any) -> str: + if isinstance(value, Mapping): + return "{" + ", ".join(f"{k}: {v}" for k, v in value.items()) + "}" + if isinstance(value, (list, tuple, set)): + return "[" + ", ".join(str(v) for v in value) + "]" + return str(value) + + +def format_event(prefix: str, **fields: Any) -> str: + """Render a lifecycle event as ``": key=value, ..."``. + + Fields whose value is ``None`` are omitted, so callers can pass optional + fields (e.g. token usage) unconditionally. Lists and maps render as + structure (``[a, b]`` / ``{k: v}``) — the login result map is structure, + not content. + """ + parts = [f"{key}={_render(value)}" for key, value in fields.items() if value is not None] + return f"{prefix}: {', '.join(parts)}" if parts else prefix + + +def format_duration(seconds: float) -> str: + """Format an elapsed duration for a lifecycle field (e.g. ``2.10s``).""" + return f"{seconds:.2f}s" diff --git a/src/quickapp/common/staged_base_tool.py b/src/quickapp/common/staged_base_tool.py index ff01c429..9eb3c815 100644 --- a/src/quickapp/common/staged_base_tool.py +++ b/src/quickapp/common/staged_base_tool.py @@ -1,5 +1,6 @@ import logging import sys +import time from abc import ABC, abstractmethod from typing import Any @@ -8,11 +9,13 @@ 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.stage_close_registry import ( DeferredStageCloseRegistry, ImmediateStageCloseRegistry, ) from quickapp.config.application import StageDisplayLevel +from quickapp.config.tools.base import BaseOpenAITool from quickapp.config.tools.base import BaseTool as _BaseToolConfig from quickapp.config.tools.tool_fallback import RetryStrategyModel @@ -122,12 +125,13 @@ async def arun( async def __run_tool_body( self, tool_call_id: str, stage_wrapper: BaseStageWrapper, *args: Any, **kwargs: Any ) -> ToolCallResult: + # The failure WARNING is written by _run_in_stage_report_success; here we only + # translate it into stage UI and a fallback result (hands-onward layer). try: return await self._run_in_stage_report_success( tool_call_id, stage_wrapper, *args, **kwargs ) except InvalidToolCallParameterException as e: - logger.exception("Invalid parameter detected while running tool") stage_wrapper.add_exception(e) return FallbackProcessor.process_fallback( [ @@ -139,7 +143,6 @@ async def __run_tool_body( e, ) except Exception as e: - logger.exception("Error occurred while running tool") fallback = self._tool_config.fallback_configuration if fallback.display_error_in_stage or isinstance(e, ToolTimeoutError): stage_wrapper.add_exception(e) @@ -154,6 +157,13 @@ async def _pre_process_params(self, **kwargs: Any) -> dict[str, Any]: kwargs = await transformer.transform(kwargs) return kwargs + def _resolve_tool_name(self) -> str: + """Best-effort tool name for lifecycle logging (the OpenAI function name, + falling back to a set ``name`` attribute or the class name).""" + if isinstance(self._tool_config, BaseOpenAITool): + return self._tool_config.open_ai_tool.function.name + return getattr(self, "name", None) or type(self).__name__ + async def _run_in_stage_report_success( self, tool_call_id: str, @@ -161,14 +171,17 @@ async def _run_in_stage_report_success( *args: Any, **kwargs: Any, ) -> ToolCallResult: - params = await self._pre_process_params(**kwargs) + tool_name = self._resolve_tool_name() timer_name = f"tool_{tool_call_id}" if stage_wrapper: - # TODO: filter params ro remove attachment_urls if it's empty - stage_wrapper.add_parameters(params) timer_name = f"tool_{stage_wrapper.name}_{tool_call_id}" + start = time.perf_counter() + self.__perf_timer.start_period(timer_name, 3) try: - self.__perf_timer.start_period(timer_name, 3) + params = await self._pre_process_params(**kwargs) + if stage_wrapper: + # TODO: filter params ro remove attachment_urls if it's empty + stage_wrapper.add_parameters(params) result: ToolCallResult = await self._run_in_stage_async( stage_wrapper, tool_call_id, *args, **params ) @@ -186,7 +199,30 @@ async def _run_in_stage_report_success( result.propagate_to_choice.append(a) result.attachments = filtered logger.debug(f"Tool call {tool_call_id} finished with result {result}") - + logger.info( + format_event( + "Tool call completed", + tool=tool_name, + tool_call_id=tool_call_id, + duration=format_duration(time.perf_counter() - start), + outcome="success", + ) + ) return result + except Exception as e: + # The single failure log for every tool type (ownership rule): exception type + # and duration only, no response body or arguments. This replaces the + # success-path completion event, so a failed call still yields exactly one line. + logger.warning( + format_event( + "Tool call failed", + tool=tool_name, + tool_call_id=tool_call_id, + duration=format_duration(time.perf_counter() - start), + error=type(e).__name__, + ), + exc_info=True, + ) + raise finally: self.__perf_timer.stop_period(timer_name) diff --git a/src/quickapp/common/tool_fallback/processor.py b/src/quickapp/common/tool_fallback/processor.py index 8c215b9c..adc4e482 100644 --- a/src/quickapp/common/tool_fallback/processor.py +++ b/src/quickapp/common/tool_fallback/processor.py @@ -3,6 +3,7 @@ from quickapp.common import ToolCallResult from quickapp.common.exceptions import TOOL_TIMEOUT_PHRASE, ToolTimeoutError +from quickapp.common.lifecycle_logging import format_event from quickapp.common.tool_fallback.applicable_mixin import ApplicableStrategyMixin from quickapp.common.tool_fallback.base_strategy import BaseStrategy from quickapp.common.tool_fallback.mapping import STRATEGY_TYPE_TO_HANDLER @@ -43,6 +44,7 @@ def process_fallback( return FallbackProcessor._process_timeout(strategies, tool_call_id, error) message: str = "" + matched_strategy: str | None = None for strategy in strategies: if FallbackProcessor._is_applicable(strategy, error): logger.debug( @@ -53,6 +55,7 @@ def process_fallback( strategy_message = FallbackProcessor._handle_fallback_strategy(strategy, error) if strategy_message: message = strategy_message + matched_strategy = strategy.type break if not message: @@ -64,8 +67,7 @@ def process_fallback( raise error logger.info( - "Fallback applied for tool_call_id=%s; returning fallback message to LLM", - tool_call_id, + format_event("Fallback applied", tool_call_id=tool_call_id, strategy=matched_strategy) ) return ToolCallResult( content=message, tool_call_id=tool_call_id, content_type="text/markdown" @@ -77,6 +79,8 @@ def _process_timeout( tool_call_id: str, error: ToolTimeoutError, ) -> ToolCallResult: + message = "" + strategy_label = "timeout_default" for strategy in strategies: if strategy.trigger_on is None: continue @@ -84,14 +88,15 @@ def _process_timeout( continue strategy_message = FallbackProcessor._handle_fallback_strategy(strategy, error) if strategy_message: - return ToolCallResult( - content=strategy_message, - tool_call_id=tool_call_id, - content_type="text/markdown", - ) + message = strategy_message + strategy_label = strategy.type + break + logger.info( + format_event("Fallback applied", tool_call_id=tool_call_id, strategy=strategy_label) + ) return ToolCallResult( - content=_format_timeout_message(error), + content=message or _format_timeout_message(error), tool_call_id=tool_call_id, content_type="text/markdown", ) diff --git a/src/quickapp/core/agent/orchestrator.py b/src/quickapp/core/agent/orchestrator.py index c614e855..ada26407 100644 --- a/src/quickapp/core/agent/orchestrator.py +++ b/src/quickapp/core/agent/orchestrator.py @@ -1,4 +1,5 @@ import logging +import time from collections.abc import AsyncIterator from contextlib import asynccontextmanager @@ -22,6 +23,7 @@ from quickapp.common.chat_completion_stream.stream_result import ChatStreamAccumulator from quickapp.common.chat_completion_stream.tool_call import AccumulatedToolCall 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.perf_timer.perf_timer import PerformanceTimer from quickapp.common.presentation_settings import PresentationSettings @@ -67,6 +69,8 @@ def __init__( self.__assistant_invoker_provider = assistant_invoker_provider self.__stream_handler = stream_handler self.__iterations_counter = 0 + self.__total_tool_calls = 0 + self.__completion_kind = "completed" self.__MAX_ITERATIONS_COUNT = app_config.orchestrator.max_iterations self.__orchestrator_deployment_name = app_config.orchestrator.deployment.deployment_id self.__propagate_orchestrator_stages: bool = app_config.orchestrator.propagate_stages @@ -86,6 +90,19 @@ def __init__( ) self.__propagated_attachment_urls: set[str] = set() + @property + def iteration_count(self) -> int: + return self.__iterations_counter + + @property + def total_tool_calls(self) -> int: + return self.__total_tool_calls + + @property + def completion_kind(self) -> str: + """``completed`` or ``external_tool_calls`` — how the loop terminated.""" + return self.__completion_kind + @asynccontextmanager async def _persisting_state(self) -> AsyncIterator[None]: exc_to_reraise: BaseException | None = None @@ -131,10 +148,26 @@ async def _run_iteration(self) -> bool: period = f"{self.__period_name}_{self.__iterations_counter}" self.__perf_timer.start_period(period, level=2) + model_call_start = time.perf_counter() stream_result = await self.__invoke_and_accumulate_stream_with_recovery() + model_call_duration = time.perf_counter() - model_call_start tool_calls = stream_result.tool_calls + usage = stream_result.usage + logger.info( + format_event( + "Model call completed", + iteration=self.__iterations_counter, + deployment=self.__orchestrator_deployment_name, + duration=format_duration(model_call_duration), + finish="tool_calls" if tool_calls else "stop", + tools=[tc.name for tc in tool_calls] if tool_calls else None, + content_length=len(stream_result.content), + tokens=(f"{usage.prompt_tokens}/{usage.completion_tokens}" if usage else None), + ) + ) + # Thinking stages stay in custom_content (streamed to choice), not in state. response_state = dict(stream_result.state or {}) state: dict[str, object] | None = ( @@ -194,6 +227,7 @@ async def _run_iteration(self) -> bool: 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) tool_call_results = await self.__tool_executor.execute(tool_calls) if not tool_call_results: @@ -217,6 +251,8 @@ async def _execute_internal_tool_calls(self, tool_calls: list[AccumulatedToolCal def _surface_external_tool_calls( self, tool_calls: list[AccumulatedToolCall], period: str ) -> 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) for tc in tool_calls: self.__choice.create_function_tool_call(tc.id, tc.name, tc.arguments) diff --git a/src/quickapp/core/application/_quick_app_completion.py b/src/quickapp/core/application/_quick_app_completion.py index d06bd68a..1e4e93ce 100644 --- a/src/quickapp/core/application/_quick_app_completion.py +++ b/src/quickapp/core/application/_quick_app_completion.py @@ -1,17 +1,22 @@ import logging +import time import uuid +from collections import Counter from aidial_sdk.chat_completion import ChatCompletion, Request, Response from aidial_sdk.deployment.configuration import ConfigurationRequest, ConfigurationResponse from aidial_sdk.exceptions import HTTPException as DialHTTPException from injector import Injector, inject -from quickapp.common import InitializerType +from quickapp.common import InitializerType, StagedBaseTool from quickapp.common.base_initializer import invoke_initializers from quickapp.common.exceptions import ConfigResolutionException +from quickapp.common.lifecycle_logging import format_duration, format_event from quickapp.common.perf_timer.perf_timer import PerformanceTimer from quickapp.common.presentation_settings import PresentationSettings +from quickapp.config.application import ApplicationConfig from quickapp.core.agent import Orchestrator +from quickapp.skills.agent_skills_provider import AgentSkillsProvider from ._exception_message_resolver import ResolvedError, resolve_exception from ._initialization_error_handler import _InitializationErrorHandler @@ -56,8 +61,12 @@ async def chat_completion(self, request: Request, response: Response) -> None: validate_messages_shape(request.messages) timer_service = self.__injector.get(PerformanceTimer) timer_service.start_period(self.__timer_period_name, level=1) + request_start = time.perf_counter() with response.create_single_choice() as choice: failed = False + outcome = "completed" + error_reference: str | None = None + agent_invoker: Orchestrator | None = None try: request_context_setup = self.__injector.get(_RequestContextSetup) try: @@ -65,8 +74,11 @@ async def chat_completion(self, request: Request, response: Response) -> None: except ConfigResolutionException: # System prompt resolution is the only path that still raises; # tool / toolset failures are skip-and-record inside the resolver. + failed = True + outcome = "failed" self.__injector.get(_InitializationErrorHandler).handle_initialization_issues() return + self.__log_request_received(request) timer_service.add_milestone(self.__timer_period_name, "request context pre-init") await invoke_initializers(self.__injector, InitializerType.completion) timer_service.add_milestone(self.__timer_period_name, "initializers") @@ -74,24 +86,74 @@ async def chat_completion(self, request: Request, response: Response) -> None: timer_service.add_milestone(self.__timer_period_name, "messages finalized") self.__injector.get(_InitializationErrorHandler).handle_initialization_issues() timer_service.add_milestone(self.__timer_period_name, "initialization issues") + self.__log_request_initialized() agent_invoker = self.__injector.get(Orchestrator) # type: ignore[type-abstract] await agent_invoker.invoke() + outcome = agent_invoker.completion_kind except Exception as e: # Raises a DIAL protocol error; the SDK delivers it as a non-200 response # (or an SSE error chunk once the choice has opened the stream). failed = True - self.__handle_exception(e) + outcome = "failed" + error_reference = uuid.uuid4().hex[:8] + self.__handle_exception(e, error_reference) finally: timer_service.stop_period(self.__timer_period_name) logger.debug( "Chat completion performance report:\n%s", timer_service.get_report_json() ) + logger.info( + format_event( + "Request completed", + outcome=outcome, + iterations=agent_invoker.iteration_count if agent_invoker else 0, + tool_calls=agent_invoker.total_tool_calls if agent_invoker else 0, + duration=format_duration(time.perf_counter() - request_start), + error_reference=error_reference, + ) + ) # Skip the execution-time stage when an error is propagating, so no # spurious stage trails the delivered error. if not failed and self.__presentation_settings.show_execution_time_stage: with choice.create_stage("Execution time") as stage: stage.append_content(timer_service.get_report_md()) + def __log_request_received(self, request: Request) -> None: + app_config = self.__injector.get(ApplicationConfig) + attachment_count = sum( + len(message.custom_content.attachments) + for message in request.messages + if message.custom_content and message.custom_content.attachments + ) + logger.info( + format_event( + "Request received", + deployment=app_config.orchestrator.deployment.deployment_id, + messages=len(request.messages), + attachments=attachment_count, + ) + ) + + def __log_request_initialized(self) -> None: + app_config = self.__injector.get(ApplicationConfig) + tools = self.__injector.get(list[StagedBaseTool]) + tool_types = Counter( + str(getattr(tool.tool_config, "type", "unknown")).removesuffix("-tool") + for tool in tools + ) + skill_count = len(self.__injector.get(AgentSkillsProvider).get_all_skills()) + len( + app_config.skills or [] + ) + logger.info( + format_event( + "Request initialized", + tools=len(tools), + tool_types=tool_types or None, + skills=skill_count, + contexts=len(app_config.contexts), + ) + ) + async def configuration(self, request: ConfigurationRequest) -> ConfigurationResponse: await self.__injector.get(_RequestContextSetup).setup_context(request) await invoke_initializers(self.__injector, InitializerType.configuration) @@ -101,8 +163,7 @@ async def configuration(self, request: ConfigurationRequest) -> ConfigurationRes return Configuration.from_list_of_configurations(configurations).to_configuration_response() @staticmethod - def __handle_exception(e: Exception) -> None: - error_reference = uuid.uuid4().hex[:8] + def __handle_exception(e: Exception, error_reference: str) -> None: resolved = resolve_exception(e) logger.exception( "Exception %s occurred (error_reference=%s, retryable=%s, details=%s). %s", diff --git a/src/quickapp/dial_core_services/_interactive_login_service.py b/src/quickapp/dial_core_services/_interactive_login_service.py index 169c41bc..15565ca2 100644 --- a/src/quickapp/dial_core_services/_interactive_login_service.py +++ b/src/quickapp/dial_core_services/_interactive_login_service.py @@ -1,6 +1,7 @@ import asyncio import json import logging +import time import httpx from httpx_sse import aconnect_sse @@ -9,6 +10,7 @@ from quickapp.common import CLIENT_CHANNEL_ID, DIAL_API_KEY 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.dial_core_services._interactive_login_settings import InteractiveLoginSettings from quickapp.dial_core_services._login_result import LoginResult @@ -39,12 +41,13 @@ async def request_signin_batch(self, toolset_dial_ids: list[str]) -> dict[str, L Returns a dict mapping each dial_id to its LoginResult. This method never raises exceptions — all failures are mapped to LoginResult values. """ + start = time.perf_counter() + logger.info(format_event("Interactive login requested", toolsets=toolset_dial_ids)) + if self.__client_channel_id is None: - logger.info( - "Interactive login skipped: no client channel ID. Toolsets: %s", - toolset_dial_ids, + return self.__log_resolved( + {tid: LoginResult.NO_CHANNEL for tid in toolset_dial_ids}, start ) - return {tid: LoginResult.NO_CHANNEL for tid in toolset_dial_ids} id_to_dial_id: dict[str, str] = {} rpc_batch: list[dict] = [] @@ -60,27 +63,32 @@ async def request_signin_batch(self, toolset_dial_ids: list[str]) -> dict[str, L } ) - logger.info( - "Requesting interactive login for toolsets %s (channel: %s)", - toolset_dial_ids, - self.__client_channel_id, - ) - try: - return await asyncio.wait_for( + results = await asyncio.wait_for( self._do_interact(rpc_batch, id_to_dial_id, toolset_dial_ids), timeout=self.__settings.interactive_login_timeout_seconds, ) except TimeoutError: - logger.info( - "Interactive login timed out after %ss for toolsets %s", - self.__settings.interactive_login_timeout_seconds, - toolset_dial_ids, - ) - return {tid: LoginResult.TIMEOUT for tid in toolset_dial_ids} + results = {tid: LoginResult.TIMEOUT for tid in toolset_dial_ids} except Exception: - logger.exception("Interactive login failed for toolsets %s", toolset_dial_ids) - return {tid: LoginResult.ERROR for tid in toolset_dial_ids} + # Handled (mapped to an ERROR outcome, request continues) -> WARNING. + logger.warning( + "Interactive login failed for toolsets %s", toolset_dial_ids, exc_info=True + ) + results = {tid: LoginResult.ERROR for tid in toolset_dial_ids} + return self.__log_resolved(results, start) + + def __log_resolved( + self, results: dict[str, LoginResult], start: float + ) -> dict[str, LoginResult]: + logger.info( + format_event( + "Interactive login resolved", + outcomes={tid: res.value for tid, res in results.items()}, + duration=format_duration(time.perf_counter() - start), + ) + ) + return results async def _do_interact( self, @@ -148,7 +156,6 @@ def _parse_batch_response( if tid not in result_map: result_map[tid] = LoginResult.ERROR - logger.info("Interactive login results: %s", result_map) return result_map async def request_signin(self, toolset_dial_id: str) -> LoginResult: diff --git a/src/quickapp/dial_deployment_tooling/dial_completion_service.py b/src/quickapp/dial_deployment_tooling/dial_completion_service.py index ffb7815a..1dba85d8 100644 --- a/src/quickapp/dial_deployment_tooling/dial_completion_service.py +++ b/src/quickapp/dial_deployment_tooling/dial_completion_service.py @@ -62,7 +62,8 @@ async def complete_request_async( # Expect params to be pre-processed by BaseDeploymentTool._pre_process_params content = params.get(CONTENT_PARAM, "") if not content: - logger.warning( + # Treated as normal (at most a config smell), so DEBUG rather than WARNING. + logger.debug( "Tool call content is empty. Check the tool configuration," " it should use `query` parameter" ) diff --git a/src/quickapp/mcp_tooling/_mcp_tool.py b/src/quickapp/mcp_tooling/_mcp_tool.py index 18f01a37..0c3f8788 100644 --- a/src/quickapp/mcp_tooling/_mcp_tool.py +++ b/src/quickapp/mcp_tooling/_mcp_tool.py @@ -214,9 +214,10 @@ async def _run_in_stage_async( tool_content = "\n\n".join(filter(None, text_parts)) - # Raise on error flag so fallback strategies can apply + # Detect-and-raise only; the StagedBaseTool choke point owns the failure + # WARNING, so this stays at DEBUG (ownership rule). Body stripped by #436. if getattr(tool_call_result, "isError", False): - logger.error( + logger.debug( "MCP tool '%s' returned isError=True; error: %s; structuredContent: %s", self.__tool.name, tool_content, diff --git a/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_attachment_get_content_injector.py b/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_attachment_get_content_injector.py index 62d0d1d9..d4f65ddf 100644 --- a/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_attachment_get_content_injector.py +++ b/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_attachment_get_content_injector.py @@ -153,7 +153,7 @@ async def _resolve_deliverable_attachment(self, attachment: Attachment) -> Attac return attachment if scheme == UrlScheme.EXTERNAL: return await self._promote_external(attachment, url) - logger.info("get_content injector: skipping attachment with unsupported url scheme") + logger.debug("get_content injector: skipping attachment with unsupported url scheme") return None async def _promote_external(self, attachment: Attachment, url: str) -> Attachment | None: @@ -163,7 +163,7 @@ async def _promote_external(self, attachment: Attachment, url: str) -> Attachmen try: promoted = await self.__materializer.materialize_external(url) except InvalidToolCallParameterException as exc: - logger.info( + logger.debug( "get_content injector: skipping external attachment, promotion blocked (%s)", exc, ) diff --git a/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_get_content_tool.py b/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_get_content_tool.py index 9f5e94f0..1c077641 100644 --- a/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_get_content_tool.py +++ b/src/quickapp/orchestrator_attachment_strategies/lazy_on_demand/_get_content_tool.py @@ -99,7 +99,7 @@ async def _run_in_stage_async( **kwargs: Any, ) -> ToolCallResult: if attachment_url is None or not str(attachment_url).strip(): - logger.info("get_content tool rejected: empty attachment_url") + logger.debug("get_content tool rejected: empty attachment_url") return self._error_result("Missing or empty attachment_url.") normalized_url = normalize_attachment_url_argument(str(attachment_url)) @@ -110,19 +110,19 @@ async def _run_in_stage_async( try: resolved = await self._resolve_external(normalized_url) except InvalidToolCallParameterException as exc: - logger.info("get_content tool rejected: external promotion failed (%s)", exc) + logger.debug("get_content tool rejected: external promotion failed (%s)", exc) return self._error_result(str(exc)) elif scheme == UrlScheme.DIAL: if not normalized_url.startswith("files/"): - logger.info("get_content tool rejected: URL does not start with files/") + logger.debug("get_content tool rejected: URL does not start with files/") return self._error_result("Invalid storage path for attachment file.") resolved = self._resolve_dial(normalized_url) else: - logger.info("get_content tool rejected: unsupported url scheme") + logger.debug("get_content tool rejected: unsupported url scheme") return self._error_result("Invalid storage path for attachment file.") if not self.__orchestrator_capabilities.orchestrator_accepts_mime_type(resolved.mime): - logger.info( + logger.debug( "get_content tool rejected: orchestrator does not accept MIME %s for deployment id=%s", resolved.mime, self.__orchestrator_capabilities.deployment_id, diff --git a/src/quickapp/rest_api_tooling/_rest_api_tool.py b/src/quickapp/rest_api_tooling/_rest_api_tool.py index 0e9020c0..58ec6fe6 100644 --- a/src/quickapp/rest_api_tooling/_rest_api_tool.py +++ b/src/quickapp/rest_api_tooling/_rest_api_tool.py @@ -97,7 +97,9 @@ async def _run_in_stage_async( response.raise_for_status() except httpx.HTTPStatusError as e: error_message = self._extract_response_error_message(e.response) - logger.error( + # Detect-and-raise only; the StagedBaseTool choke point owns the + # failure WARNING, so this stays at DEBUG (ownership rule). + logger.debug( "REST API tool '%s' returned HTTP %s; error: %s", self._tool_config.open_ai_tool.function.name, e.response.status_code, diff --git a/src/quickapp/skills/agent_skills_provider.py b/src/quickapp/skills/agent_skills_provider.py index ba6d8f0b..d82f8d4b 100644 --- a/src/quickapp/skills/agent_skills_provider.py +++ b/src/quickapp/skills/agent_skills_provider.py @@ -60,7 +60,8 @@ def _load_skills(self) -> None: self._skills = skills self._contents = contents - logger.info(f"Loaded {len(skills)} skill(s)") + # DEBUG: superseded at INFO by the request-initialized lifecycle event. + logger.debug("Loaded %d skill(s)", len(skills)) def get_all_skills(self) -> list[SkillMetadata]: """Return the cached list of predefined skill metadata.""" diff --git a/src/tests/unit_tests/application_tests/test_completion.py b/src/tests/unit_tests/application_tests/test_completion.py index fc4af2df..cc7099d9 100644 --- a/src/tests/unit_tests/application_tests/test_completion.py +++ b/src/tests/unit_tests/application_tests/test_completion.py @@ -149,6 +149,15 @@ def _make( _MessagesSetup: messages_setup, ConfigResolver: config_resolver, quick_app_completion.PerformanceTimer: Mock(), + quick_app_completion.ApplicationConfig: SimpleNamespace( + orchestrator=SimpleNamespace( + deployment=SimpleNamespace(deployment_id="default-deployment") + ), + skills=None, + contexts=[], + ), + list[quick_app_completion.StagedBaseTool]: [], + quick_app_completion.AgentSkillsProvider: SimpleNamespace(get_all_skills=lambda: []), } if orchestrator is not None: mapping[quick_app_completion.Orchestrator] = orchestrator @@ -176,6 +185,10 @@ async def test_chat_completion_success(make_request_completion): orchestrator_called = {"count": 0} class OrchestratorFake: + iteration_count = 1 + total_tool_calls = 0 + completion_kind = "completed" + async def invoke(self): orchestrator_called["count"] += 1 @@ -196,6 +209,10 @@ async def test_chat_completion_orchestrator_exceed_raises_dial_error(make_reques response = FakeResponse(choice) class OrchRaise: + iteration_count = 1 + total_tool_calls = 0 + completion_kind = "completed" + async def invoke(self): raise OrchestratorExceedMaxIterationsException() @@ -218,6 +235,10 @@ async def test_chat_completion_generic_exception_raises_generic_message(make_req response = FakeResponse(choice) class OrchRaise: + iteration_count = 1 + total_tool_calls = 0 + completion_kind = "completed" + async def invoke(self): raise ValueError("boom") @@ -282,6 +303,10 @@ async def test_chat_completion_http_error_raises_safe_message(make_request_compl response = FakeResponse(choice) class OrchRaise: + iteration_count = 1 + total_tool_calls = 0 + completion_kind = "completed" + async def invoke(self): raise HTTPError("http://internal-service/secret-endpoint failure") @@ -313,6 +338,10 @@ async def test_chat_completion_openai_internal_server_error_raises_safe_message( _response = _httpx.Response(500, request=_request) class OrchRaise: + iteration_count = 1 + total_tool_calls = 0 + completion_kind = "completed" + async def invoke(self): raise _openai.InternalServerError( "upstream internal error", response=_response, body=None @@ -345,6 +374,10 @@ async def test_chat_completion_sets_context_messages_when_request_is_request( response = FakeResponse(choice) class OrchestratorFake: + iteration_count = 1 + total_tool_calls = 0 + completion_kind = "completed" + async def invoke(self): return None diff --git a/src/tests/unit_tests/application_tests/test_quick_app_completion_error_delivery.py b/src/tests/unit_tests/application_tests/test_quick_app_completion_error_delivery.py index b9b32b90..1e9d2182 100644 --- a/src/tests/unit_tests/application_tests/test_quick_app_completion_error_delivery.py +++ b/src/tests/unit_tests/application_tests/test_quick_app_completion_error_delivery.py @@ -40,7 +40,7 @@ class TestHandleException: def test_raises_dial_error_with_reference(self) -> None: e = openai.APITimeoutError(request=httpx.Request("GET", "http://x/api")) with pytest.raises(DialHTTPException) as excinfo: - _handle_exception(e) + _handle_exception(e, "0a1b2c3d") exc = excinfo.value assert exc.status_code == 500 assert exc.type == "runtime_error" @@ -56,7 +56,7 @@ def test_client_error_status_preserved(self) -> None: body=None, ) with pytest.raises(DialHTTPException) as excinfo: - _handle_exception(e) + _handle_exception(e, "0a1b2c3d") assert excinfo.value.status_code == 400 # No upstream type -> the OpenAI-idiomatic default for a client-attributable 4xx. assert excinfo.value.type == "invalid_request_error" @@ -68,7 +68,7 @@ def test_rate_limit_downgraded_to_500(self) -> None: body=None, ) with pytest.raises(DialHTTPException) as excinfo: - _handle_exception(e) + _handle_exception(e, "0a1b2c3d") assert excinfo.value.status_code == 500 # The default type keys on the *outgoing* (downgraded) status, not the upstream one. assert excinfo.value.type == "runtime_error" @@ -80,7 +80,7 @@ def test_code_and_type_propagated_to_wire(self) -> None: body={"error": {"code": "content_filter", "type": "invalid_request_error"}}, ) with pytest.raises(DialHTTPException) as excinfo: - _handle_exception(e) + _handle_exception(e, "0a1b2c3d") exc = excinfo.value assert exc.code == "content_filter" assert exc.type == "invalid_request_error"