fix: comprehensive logging for all operations, exceptions, and agent lifecycle (#952) (#953)

Author: Cataldir

apps/search-enrichment-agent/src/search_enrichment_agent/event_handlers.py

@@ -97,7 +97,13 @@ async def handle_search_enrichment_job(_partition_context, event) -> None:  # no
                 result.get("status"),
                 result.get("strategy"),
             )
-        except Exception:
+        except Exception as exc:
+            logger.error(
+                "search_enrichment_event_processing_failed entity_id=%s error=%s",
+                entity_id,
+                exc,
+                exc_info=True,
+            )
             _trace_eventhub_liveness(
                 outcome="error",
                 status="error",

lib/src/holiday_peak_lib/adapters/base.py

@@ -18,6 +18,7 @@
 """
 
 import asyncio
+import logging
 import random
 import time
 from abc import ABC, abstractmethod
@@ -28,6 +29,8 @@
     CircuitBreaker,
     CircuitBreakerOpenError,
 )
+
+logger = logging.getLogger(__name__)
 from pydantic import BaseModel, ValidationError
 
 ModelT = TypeVar("ModelT", bound=BaseModel)
@@ -176,7 +179,19 @@ def __init__(
 
     # Public methods (resilient wrappers)
     async def connect(self, **kwargs: Any) -> None:
-        await self._connect_impl(**kwargs)
+        adapter_name = type(self).__name__
+        logger.info("adapter_connect_start adapter=%s", adapter_name)
+        try:
+            await self._connect_impl(**kwargs)
+            logger.info("adapter_connect_success adapter=%s", adapter_name)
+        except Exception as exc:
+            logger.error(
+                "adapter_connect_failed adapter=%s error=%s",
+                adapter_name,
+                exc,
+                exc_info=True,
+            )
+            raise
 
     async def fetch(self, query: dict[str, Any]) -> Iterable[dict[str, Any]]:
         key = self._cache_key(query)
@@ -228,6 +243,7 @@ async def _delete_impl(self, identifier: str) -> bool:
     async def _call_with_resilience(self, func):
         await self._rate_limiter.acquire()
 
+        adapter_name = type(self).__name__
         last_error: Exception | None = None
         for attempt in range(1, self._retries + 2):
             try:
@@ -238,14 +254,31 @@ async def _timed_call() -> Any:
                 result = await self._circuit_breaker.call(_timed_call)
                 return result
             except CircuitBreakerOpenError as exc:
+                logger.error(
+                    "adapter_circuit_breaker_open adapter=%s",
+                    adapter_name,
+                )
                 raise AdapterError("Circuit breaker open") from exc
             except Exception as exc:  # noqa: BLE001
                 last_error = exc
                 if attempt > self._retries:
                     break
+                logger.warning(
+                    "adapter_retry adapter=%s attempt=%d/%d error=%s",
+                    adapter_name,
+                    attempt,
+                    self._retries,
+                    exc,
+                )
                 delay = min(self._max_delay, self._base_delay * (2 ** (attempt - 1)))
                 delay *= 1 + random.random() * 0.25
                 await asyncio.sleep(delay)
+        logger.error(
+            "adapter_operation_failed adapter=%s retries_exhausted=%d error=%s",
+            adapter_name,
+            self._retries,
+            last_error,
+        )
         raise AdapterError("Operation failed after retries") from last_error
 
     def resilience_status(self) -> dict[str, Any]:

lib/src/holiday_peak_lib/agents/base_agent.py

@@ -1,12 +1,15 @@
 """Base agent abstraction with model selection and SDK integration points."""
 
 import asyncio
+import logging
 import os
 from abc import ABC, abstractmethod
 from dataclasses import dataclass
 from time import perf_counter
 from typing import Any, AsyncGenerator, Awaitable, Callable
 
+logger = logging.getLogger(__name__)
+
 from agent_framework import BaseAgent
 from holiday_peak_lib.agents.complexity import assess_complexity
 
@@ -380,10 +383,22 @@ async def __invoke_target(
         except asyncio.TimeoutError:
             outcome = "timeout"
             error_text = "Model invocation timed out"
+            logger.error(
+                "agent_model_invocation_timeout service=%s model=%s",
+                getattr(self, "service_name", "unknown"),
+                target.model,
+            )
             raise
         except Exception as exc:
             outcome = "error"
             error_text = str(exc)
+            logger.error(
+                "agent_model_invocation_failed service=%s model=%s error=%s",
+                getattr(self, "service_name", "unknown"),
+                target.model,
+                exc,
+                exc_info=True,
+            )
             raise
         finally:
             elapsed_ms = (perf_counter() - started) * 1000
@@ -641,3 +656,38 @@ async def invoke_model_stream(
     @abstractmethod
     async def handle(self, request: dict[str, Any]) -> dict[str, Any]:
         """Handle an incoming request."""
+
+    def __init_subclass__(cls, **kwargs: Any) -> None:
+        """Auto-wrap concrete handle() implementations with entry/exit logging."""
+        super().__init_subclass__(**kwargs)
+        original_handle = cls.__dict__.get("handle")
+        if original_handle is None:
+            return
+
+        async def _logged_handle(self: Any, request: dict[str, Any]) -> dict[str, Any]:
+            svc = getattr(self, "service_name", cls.__name__)
+            logger.info("agent_handle_entry service=%s", svc)
+            started = perf_counter()
+            try:
+                result = await original_handle(self, request)
+                elapsed = (perf_counter() - started) * 1000
+                logger.info(
+                    "agent_handle_success service=%s elapsed_ms=%.1f",
+                    svc,
+                    elapsed,
+                )
+                return result
+            except Exception as exc:
+                elapsed = (perf_counter() - started) * 1000
+                logger.error(
+                    "agent_handle_failed service=%s elapsed_ms=%.1f error=%s",
+                    svc,
+                    elapsed,
+                    exc,
+                    exc_info=True,
+                )
+                raise
+
+        _logged_handle.__name__ = "handle"
+        _logged_handle.__qualname__ = f"{cls.__qualname__}.handle"
+        cls.handle = _logged_handle  # type: ignore[method-assign]

lib/src/holiday_peak_lib/agents/memory/session_manager.py

@@ -19,11 +19,14 @@
 from __future__ import annotations
 
 import json
+import logging
 import re
 import time
 from dataclasses import asdict, dataclass, field
 from typing import Any
 
+logger = logging.getLogger(__name__)
+
 # ---------------------------------------------------------------------------
 # Data structures
 # ---------------------------------------------------------------------------
@@ -298,8 +301,15 @@ async def evaluate_session_continuity(
             )
             if cosmos_session and "foundry_session_state" in cosmos_session:
                 foundry_state = cosmos_session["foundry_session_state"]
-        except Exception:  # noqa: BLE001 — fail-open on Cosmos read
-            pass
+        except Exception as exc:  # noqa: BLE001 — fail-open on Cosmos read
+            logger.warning(
+                "session_continuity_cosmos_read_failed "
+                "session_id=%s service=%s entity_id=%s error=%s",
+                summary.session_id,
+                service,
+                entity_id,
+                exc,
+            )
 
     return SessionDecision(
         continue_session=True,
@@ -416,8 +426,15 @@ async def persist_full_session(
     }
     try:
         await warm_memory.upsert(document)
-    except Exception:  # noqa: BLE001 — fail-open on Cosmos write
-        pass
+    except Exception as exc:  # noqa: BLE001 — fail-open on Cosmos write
+        logger.warning(
+            "session_persistence_cosmos_write_failed "
+            "session_id=%s service=%s entity_id=%s error=%s",
+            session_id,
+            service,
+            entity_id,
+            exc,
+        )
 
 
 # ---------------------------------------------------------------------------

lib/src/holiday_peak_lib/app_factory.py

@@ -251,6 +251,14 @@ def _sync_foundry_tracing_state() -> None:
 
     tracer = get_foundry_tracer(service_name)
 
+    # Suppress azure-ai-projects SDK internal telemetry instrumentor when
+    # no real OpenTelemetry exporter is configured. The SDK crashes with
+    # AttributeError on NonRecordingSpan.attributes (GH-946).
+    if not os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING") and not os.getenv(
+        "AZURE_TRACING_ENABLED"
+    ):
+        os.environ.setdefault("AZURE_TRACING_ENABLED", "false")
+
     configured_foundry_roles = tuple(
         role for role, config in (("fast", slm_config), ("rich", llm_config)) if config is not None
     )

lib/src/holiday_peak_lib/mcp/server.py

@@ -2,12 +2,15 @@
 
 from __future__ import annotations
 
+import logging
 from dataclasses import dataclass
 from inspect import isawaitable
 from typing import Any, Awaitable, Callable
 
 from fastapi import APIRouter, FastAPI, HTTPException
 from holiday_peak_lib.self_healing import FailureSignal, SurfaceType
+
+logger = logging.getLogger(__name__)
 from pydantic import BaseModel, ValidationError
 
 ToolHandler = Callable[[dict[str, Any]], Awaitable[dict[str, Any]] | dict[str, Any]]
@@ -126,11 +129,21 @@ def _wrap_handler(
         output_model: type[BaseModel] | None,
     ) -> Callable[[dict[str, Any]], Awaitable[dict[str, Any]]]:
         async def validated_handler(payload: dict[str, Any]) -> dict[str, Any]:
+            logger.info(
+                "mcp_tool_invoked path=%s service=%s",
+                path,
+                self.app.title,
+            )
             normalized_payload = payload
             if input_model is not None:
                 try:
                     validated_input = input_model.model_validate(payload)
                 except ValidationError as exc:
+                    logger.warning(
+                        "mcp_tool_input_validation_failed path=%s error=%s",
+                        path,
+                        exc,
+                    )
                     await self._emit_failure(
                         path=path,
                         status_code=422,
@@ -146,14 +159,29 @@ async def validated_handler(payload: dict[str, Any]) -> dict[str, Any]:
                     ) from exc
                 normalized_payload = validated_input.model_dump(mode="json")
 
-            result = handler(normalized_payload)
-            if isawaitable(result):
-                result = await result
+            try:
+                result = handler(normalized_payload)
+                if isawaitable(result):
+                    result = await result
+            except Exception as exc:
+                logger.error(
+                    "mcp_tool_execution_failed path=%s service=%s error=%s",
+                    path,
+                    self.app.title,
+                    exc,
+                    exc_info=True,
+                )
+                raise
 
             if output_model is not None:
                 try:
                     validated_output = output_model.model_validate(result)
                 except ValidationError as exc:
+                    logger.warning(
+                        "mcp_tool_output_validation_failed path=%s error=%s",
+                        path,
+                        exc,
+                    )
                     await self._emit_failure(
                         path=path,
                         status_code=500,

lib/src/holiday_peak_lib/utils/circuit_breaker.py

@@ -142,10 +142,19 @@ async def call(
                 if self._state != CircuitState.CLOSED:
                     await self._transition(CircuitState.CLOSED)
             return result
-        except Exception:
+        except Exception as exc:
             async with self._lock:
                 self._failure_count += 1
                 self._last_failure_time = time.monotonic()
+                logger.warning(
+                    "circuit_breaker_failure name=%s state=%s failure_count=%d "
+                    "threshold=%d error=%s",
+                    self.name,
+                    self._state.value,
+                    self._failure_count,
+                    self.failure_threshold,
+                    exc,
+                )
                 if self._state == CircuitState.HALF_OPEN or (
                     self._state == CircuitState.CLOSED
                     and self._failure_count >= self.failure_threshold

lib/src/holiday_peak_lib/utils/event_hub.py

@@ -795,7 +795,17 @@ def make_handler(eventhub_name: str):
 
             async def _handler(partition_context, event):  # noqa: ANN001
                 if handler is not None:
-                    await handler(partition_context, event)
+                    try:
+                        await handler(partition_context, event)
+                    except Exception as exc:
+                        logger.error(
+                            "eventhub_handler_failed eventhub=%s service=%s error=%s",
+                            eventhub_name,
+                            service_name,
+                            exc,
+                            exc_info=True,
+                        )
+                        raise
                     return
                 payload = json.loads(event.body_as_str())
                 _safe_log(

lib/src/holiday_peak_lib/utils/logging.py

@@ -73,6 +73,9 @@ def configure_logging(
     if conn:
         from azure.monitor.opentelemetry import configure_azure_monitor
 
+        # Ensure OTEL_SERVICE_NAME is set so App Insights identifies the emitting service.
+        os.environ.setdefault("OTEL_SERVICE_NAME", resolved_app)
+
         try:
             configure_azure_monitor(connection_string=conn)
             base_logger.info("Azure Monitor logging enabled via configure_azure_monitor.")

lib/src/holiday_peak_lib/utils/telemetry.py

@@ -271,6 +271,8 @@ def _initialize_foundry_instrumentation(self) -> None:
                     pass
 
             if self.connection_string and not _FOUNDRY_INSTRUMENTATION_STATE["azure_monitor"]:
+                # Ensure OTEL_SERVICE_NAME is set so App Insights identifies the emitting service.
+                os.environ.setdefault("OTEL_SERVICE_NAME", self.service_name)
                 try:
                     configure_azure_monitor(connection_string=self.connection_string)
                     _FOUNDRY_INSTRUMENTATION_STATE["azure_monitor"] = True