Implement comprehensive logging system with environment variable control

Co-authored-by: ks6088ts <[email protected]>

Author: Copilot

.env.template

@@ -31,3 +31,6 @@ MICROSOFT_GRAPH_TENANT_ID="<YOUR_TENANT_ID>"
 MICROSOFT_GRAPH_CLIENT_ID="<YOUR_CLIENT_ID>"
 MICROSOFT_GRAPH_CLIENT_SECRET="<YOUR_CLIENT_SECRET>"
 MICROSOFT_GRAPH_USER_SCOPES="User.Read Sites.Read.All" # scopes for Microsoft Graph API
+
+# Logging Configuration
+LOG_LEVEL="INFO" # Valid levels: DEBUG, INFO, WARNING, ERROR, CRITICAL

template_fastapi/app.py

@@ -12,12 +12,20 @@
 from opentelemetry.trace import Span
 
 from template_fastapi.routers import agents, chats, demos, files, foodies, items, speeches
+from template_fastapi.settings.logging import configure_logging, get_logger
+
+# Configure logging first
+configure_logging()
+logger = get_logger(__name__)
 
 app = FastAPI()
 
+logger.info("Starting FastAPI application")
+
 # If APPLICATIONINSIGHTS_CONNECTION_STRING exists, configure Azure Monitor
 AZURE_CONNECTION_STRING = getenv("APPLICATIONINSIGHTS_CONNECTION_STRING")
 if AZURE_CONNECTION_STRING:
+    logger.info("Configuring Azure Monitor telemetry")
 
     def server_request_hook(span: Span, scope: dict):
         if span and span.is_recording():
@@ -26,14 +34,16 @@ def server_request_hook(span: Span, scope: dict):
                 user_id = uuid.uuid4().hex  # Replace with actual user ID retrieval logic
                 span.set_attribute("enduser.id", user_id)
             except KeyError:
-                pass
+                logger.warning("Failed to set user ID attribute in telemetry")
 
     configure_azure_monitor(
         connection_string=AZURE_CONNECTION_STRING,
         # enable_live_metrics=True,
         server_request_hook=server_request_hook,
     )
     FastAPIInstrumentor.instrument_app(app)
+else:
+    logger.info("Azure Monitor telemetry not configured (APPLICATIONINSIGHTS_CONNECTION_STRING not set)")
 
 # Include routers
 # Routers configuration list
@@ -77,6 +87,7 @@ def server_request_hook(span: Span, scope: dict):
 
 # Include routers using a loop
 for routerConfig in routersConfig:
+    logger.info(f"Including router: {routerConfig['prefix']} with tags: {routerConfig['tags']}")
     app.include_router(
         router=routerConfig["router"],
         prefix=routerConfig["prefix"],
@@ -87,3 +98,5 @@ def server_request_hook(span: Span, scope: dict):
             },
         },
     )
+
+logger.info("FastAPI application configured successfully")

template_fastapi/core.py

@@ -1,11 +1,18 @@
 import logging
 
-logger = logging.getLogger(__name__)
+from template_fastapi.settings.logging import get_logger
+
+# For backward compatibility with the original tests
+# We still need to support the original behavior
+logger = get_logger(__name__)
 
 
 def hello_world(verbose: bool = False):
+    """Simple hello world function with optional verbose logging."""
     if verbose:
+        # Configure basic logging for verbose mode (for backward compatibility)
         logging.basicConfig(level=logging.DEBUG)
+    # Use module-level logging for test compatibility
     logging.debug("Hello World")
 
 

template_fastapi/routers/agents/azure_ai_foundry.py

@@ -11,7 +11,9 @@
     ThreadResponse,
 )
 from template_fastapi.repositories.agents import AgentRepository
+from template_fastapi.settings.logging import get_logger
 
+logger = get_logger(__name__)
 router = APIRouter()
 agent_repo = AgentRepository()
 
@@ -25,9 +27,13 @@ async def create_agent(request: AgentRequest) -> AgentResponse:
     """
     新しいエージェントを作成する
     """
+    logger.info(f"Creating new agent with model: {request.model}")
     try:
-        return agent_repo.create_agent(request)
+        result = agent_repo.create_agent(request)
+        logger.info(f"Successfully created agent with ID: {result.id}")
+        return result
     except Exception as e:
+        logger.error(f"Failed to create agent: {str(e)}", exc_info=True)
         raise HTTPException(status_code=500, detail=f"エージェントの作成に失敗しました: {str(e)}")
 
 
@@ -40,9 +46,13 @@ async def get_agent(agent_id: str) -> AgentResponse:
     """
     エージェントの情報を取得する
     """
+    logger.info(f"Getting agent: {agent_id}")
     try:
-        return agent_repo.get_agent(agent_id)
+        result = agent_repo.get_agent(agent_id)
+        logger.debug(f"Successfully retrieved agent: {agent_id}")
+        return result
     except Exception as e:
+        logger.warning(f"Agent not found: {agent_id} - {str(e)}")
         raise HTTPException(status_code=404, detail=f"エージェントが見つかりません: {str(e)}")
 
 
@@ -57,9 +67,13 @@ async def list_agents(
     """
     エージェントの一覧を取得する
     """
+    logger.info(f"Listing agents with limit: {limit}")
     try:
-        return agent_repo.list_agents(limit=limit)
+        result = agent_repo.list_agents(limit=limit)
+        logger.info(f"Retrieved {len(result.agents)} agents")
+        return result
     except Exception as e:
+        logger.error(f"Failed to list agents: {str(e)}", exc_info=True)
         raise HTTPException(status_code=500, detail=f"エージェント一覧の取得に失敗しました: {str(e)}")
 
 
@@ -71,13 +85,17 @@ async def delete_agent(agent_id: str) -> dict:
     """
     エージェントを削除する
     """
+    logger.info(f"Deleting agent: {agent_id}")
     try:
         success = agent_repo.delete_agent(agent_id)
         if success:
+            logger.info(f"Successfully deleted agent: {agent_id}")
             return {"message": "エージェントが正常に削除されました"}
         else:
+            logger.error(f"Failed to delete agent (no error): {agent_id}")
             raise HTTPException(status_code=500, detail="エージェントの削除に失敗しました")
     except Exception as e:
+        logger.error(f"Failed to delete agent {agent_id}: {str(e)}", exc_info=True)
         raise HTTPException(status_code=500, detail=f"エージェントの削除に失敗しました: {str(e)}")
 
 
@@ -90,9 +108,14 @@ async def chat_with_agent(agent_id: str, request: ChatRequest) -> ChatResponse:
     """
     エージェントとチャットする
     """
+    logger.info(f"Starting chat with agent {agent_id} on thread {request.thread_id}")
+    logger.debug(f"Chat message: {request.message[:100]}...")  # Log first 100 chars
     try:
-        return agent_repo.chat_with_agent(agent_id, request)
+        result = agent_repo.chat_with_agent(agent_id, request)
+        logger.info(f"Chat completed successfully with agent {agent_id}")
+        return result
     except Exception as e:
+        logger.error(f"Failed to chat with agent {agent_id}: {str(e)}", exc_info=True)
         raise HTTPException(status_code=500, detail=f"エージェントとのチャットに失敗しました: {str(e)}")
 
 
@@ -105,9 +128,13 @@ async def create_thread(request: ThreadRequest) -> ThreadResponse:
     """
     新しいスレッドを作成する
     """
+    logger.info("Creating new thread")
     try:
-        return agent_repo.create_thread(request)
+        result = agent_repo.create_thread(request)
+        logger.info(f"Successfully created thread with ID: {result.id}")
+        return result
     except Exception as e:
+        logger.error(f"Failed to create thread: {str(e)}", exc_info=True)
         raise HTTPException(status_code=500, detail=f"スレッドの作成に失敗しました: {str(e)}")
 
 
@@ -120,9 +147,13 @@ async def get_thread(thread_id: str) -> ThreadResponse:
     """
     スレッドの情報を取得する
     """
+    logger.info(f"Getting thread: {thread_id}")
     try:
-        return agent_repo.get_thread(thread_id)
+        result = agent_repo.get_thread(thread_id)
+        logger.debug(f"Successfully retrieved thread: {thread_id}")
+        return result
     except Exception as e:
+        logger.warning(f"Thread not found: {thread_id} - {str(e)}")
         raise HTTPException(status_code=404, detail=f"スレッドが見つかりません: {str(e)}")
 
 
@@ -134,13 +165,17 @@ async def delete_thread(thread_id: str) -> dict:
     """
     スレッドを削除する
     """
+    logger.info(f"Deleting thread: {thread_id}")
     try:
         success = agent_repo.delete_thread(thread_id)
         if success:
+            logger.info(f"Successfully deleted thread: {thread_id}")
             return {"message": "スレッドが正常に削除されました"}
         else:
+            logger.error(f"Failed to delete thread (no error): {thread_id}")
             raise HTTPException(status_code=500, detail="スレッドの削除に失敗しました")
     except Exception as e:
+        logger.error(f"Failed to delete thread {thread_id}: {str(e)}", exc_info=True)
         raise HTTPException(status_code=500, detail=f"スレッドの削除に失敗しました: {str(e)}")
 
 
@@ -155,7 +190,11 @@ async def list_threads(
     """
     エージェントのスレッド一覧を取得する
     """
+    logger.info(f"Listing threads with limit: {limit}")
     try:
-        return agent_repo.list_threads(limit=limit)
+        result = agent_repo.list_threads(limit=limit)
+        logger.info(f"Retrieved {len(result.threads)} threads")
+        return result
     except Exception as e:
+        logger.error(f"Failed to list threads: {str(e)}", exc_info=True)
         raise HTTPException(status_code=500, detail=f"スレッド一覧の取得に失敗しました: {str(e)}")

template_fastapi/routers/chats.py

@@ -3,7 +3,9 @@
 
 from template_fastapi.repositories.chats import ChatRepository
 from template_fastapi.settings.chats import get_chats_settings
+from template_fastapi.settings.logging import get_logger
 
+logger = get_logger(__name__)
 router = APIRouter()
 templates = Jinja2Templates(directory="template_fastapi/templates")
 chat_repository = ChatRepository()
@@ -14,7 +16,9 @@
 )
 async def get(request: Request):
     """Get the chat page with configurable WebSocket URL."""
+    logger.info("Serving chat page")
     settings = get_chats_settings()
+    logger.debug(f"Using WebSocket URL: {settings.chats_websocket_url}")
     return templates.TemplateResponse(
         "chats.html",
         {
@@ -29,11 +33,20 @@ async def get(request: Request):
 )
 async def websocket_endpoint(websocket: WebSocket, client_id: int):
     """WebSocket endpoint for chat functionality."""
-    await chat_repository.manager.connect(websocket)
+    logger.info(f"WebSocket connection attempt for client {client_id}")
     try:
+        await chat_repository.manager.connect(websocket)
+        logger.info(f"WebSocket connected successfully for client {client_id}")
+        
         while True:
             data = await websocket.receive_text()
+            logger.debug(f"Received message from client {client_id}: {data[:100]}...")  # Log first 100 chars
             await chat_repository.handle_client_message(data, websocket, client_id)
+            
     except WebSocketDisconnect:
+        logger.info(f"WebSocket disconnected for client {client_id}")
         chat_repository.manager.disconnect(websocket)
         await chat_repository.handle_client_disconnect(client_id)
+    except Exception as e:
+        logger.error(f"WebSocket error for client {client_id}: {str(e)}", exc_info=True)
+        chat_repository.manager.disconnect(websocket)

template_fastapi/routers/demos.py

@@ -4,7 +4,9 @@
 from fastapi import APIRouter, HTTPException
 
 from template_fastapi.opentelemetry import get_meter, get_tracer
+from template_fastapi.settings.logging import get_logger
 
+logger = get_logger(__name__)
 tracer = get_tracer(__name__)
 meter = get_meter(__name__)
 router = APIRouter()
@@ -16,6 +18,7 @@ async def flaky_exception():
     """
     A flaky endpoint that always raises an exception.
     """
+    logger.warning("Flaky exception endpoint called - simulating error")
     raise HTTPException(
         status_code=500,
         detail="Simulated exception",
@@ -29,18 +32,24 @@ async def flaky(failure_rate: int):
 
     The failure rate is a percentage (0-100) that determines the likelihood of failure.
     """
+    logger.debug(f"Flaky endpoint called with failure rate: {failure_rate}")
+    
     if not (0 <= failure_rate <= 100):
+        logger.error(f"Invalid failure rate: {failure_rate}")
         raise HTTPException(
             status_code=400,
             detail="Failure rate must be between 0 and 100",
         )
 
-    if random.randint(0, 100) < failure_rate:
+    random_value = random.randint(0, 100)
+    if random_value < failure_rate:
+        logger.warning(f"Simulating failure (random: {random_value}, threshold: {failure_rate})")
         raise HTTPException(
             status_code=500,
             detail="Simulated failure",
         )
 
+    logger.info(f"Request succeeded (random: {random_value}, threshold: {failure_rate})")
     return {
         "message": "Request succeeded",
     }
@@ -53,17 +62,22 @@ async def heavy_sync_with_sleep(sleep_ms: int):
 
     This simulates a long-running synchronous operation.
     """
+    logger.info(f"Heavy sync endpoint called with sleep time: {sleep_ms}ms")
+    
     if sleep_ms < 0:
+        logger.error(f"Invalid sleep time: {sleep_ms}")
         raise HTTPException(
             status_code=400,
             detail="Sleep time must be a non-negative integer",
         )
 
     with tracer.start_as_current_span("parent"):
-        print(f"Sleeping for {sleep_ms} milliseconds")
+        logger.debug(f"Starting sleep for {sleep_ms} milliseconds")
         time.sleep(sleep_ms / 1000.0)
         with tracer.start_as_current_span("child"):
-            print("Child span")
+            logger.debug("Child span execution")
+    
+    logger.info(f"Completed sleep operation for {sleep_ms}ms")
     return {
         "message": f"Slept for {sleep_ms} milliseconds",
     }
@@ -82,5 +96,6 @@ async def roll_dice():
     """
     with tracer.start_as_current_span("roll_dice"):
         roll = random.randint(1, 6)
+        logger.info(f"Dice rolled: {roll}")
         roll_counter.add(1, {"roll.value": str(roll)})
     return roll