feat: add INFO request-lifecycle logging skeleton and rebalance levels #435

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

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

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 ``"<prefix>: 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"

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,21 +157,31 @@ 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,
         stage_wrapper: BaseStageWrapper | None,
         *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)

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,21 +79,24 @@ 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
             if not FallbackProcessor._is_applicable(strategy, error):
                 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",
         )

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)