Backend chat observability upgrade: standardized request summary logs

server_api/chatbot/logging_utils.py

@@ -0,0 +1,31 @@
+import logging
+import time
+import uuid
+from typing import Optional
+
+from fastapi import Request
+
+logger = logging.getLogger(__name__)
+
+
+def request_id_from_request(request: Request) -> str:
+    return request.headers.get("x-request-id") or str(uuid.uuid4())
+
+
+def log_request_summary(
+    *,
+    request_id: str,
+    endpoint: str,
+    start_time: float,
+    status: str,
+    error_type: Optional[str] = None,
+) -> None:
+    latency_ms = round((time.perf_counter() - start_time) * 1000, 2)
+    logger.info(
+        "request_summary request_id=%s endpoint=%s latency_ms=%s status=%s error_type=%s",
+        request_id,
+        endpoint,
+        latency_ms,
+        status,
+        error_type or "none",
+    )

server_api/main.py

@@ -3,6 +3,7 @@
 import re
 import shutil
 import tempfile
+import time
 from typing import List, Optional
 from urllib.parse import urlsplit, urlunsplit
 
@@ -21,6 +22,7 @@
 from server_api.auth.database import get_db
 from server_api.auth.router import get_current_user
 from server_api.ehtool import router as ehtool_router
+from server_api.chatbot.logging_utils import log_request_summary, request_id_from_request
 
 from fastapi.staticfiles import StaticFiles
 import os
@@ -709,90 +711,145 @@ async def chat_query(
     user: models.User = Depends(get_current_user),
     db: Session = Depends(get_db),
 ):
-    if not _ensure_chatbot():
-        detail = "Chatbot is not configured"
-        if "_chatbot_error" in globals():
-            detail = f"{detail}: {_chatbot_error}"
-        raise HTTPException(status_code=503, detail=detail)
-    body = await req.json()
-    query = body.get("query")
-    convo_id = body.get("conversationId")
-    if not isinstance(query, str) or not query.strip():
-        raise HTTPException(status_code=400, detail="Query must be a non-empty string.")
-
-    # Auto-create a conversation if none supplied
-    if not convo_id:
-        convo = models.Conversation(user_id=user.id, title="New Chat")
-        db.add(convo)
-        db.commit()
-        db.refresh(convo)
-        convo_id = convo.id
-    else:
-        convo = (
-            db.query(models.Conversation)
-            .filter(
-                models.Conversation.id == convo_id,
-                models.Conversation.user_id == user.id,
+    request_id = request_id_from_request(req)
+    start_time = time.perf_counter()
+    status = "error"
+    error_type = None
+    try:
+        if not _ensure_chatbot():
+            detail = "Chatbot is not configured"
+            if "_chatbot_error" in globals():
+                detail = f"{detail}: {_chatbot_error}"
+            raise HTTPException(status_code=503, detail=detail)
+        body = await req.json()
+        query = body.get("query")
+        convo_id = body.get("conversationId")
+        if not isinstance(query, str) or not query.strip():
+            raise HTTPException(
+                status_code=400, detail="Query must be a non-empty string."
             )
-            .first()
-        )
-        if not convo:
-            raise HTTPException(status_code=404, detail="Conversation not found")
-
-    # Rebuild in-memory history from DB when switching conversations
-    _load_history_for_convo(convo_id, db)
-
-    if _reset_search is not None:
-        _reset_search()
-    all_messages = _chat_history + [{"role": "user", "content": query}]
-    result = chain.invoke({"messages": all_messages})
-    messages = result.get("messages", [])
-    response = messages[-1].content if messages else "No response generated"
-
-    # Persist to DB
-    db.add(models.ChatMessage(conversation_id=convo_id, role="user", content=query))
-    db.add(
-        models.ChatMessage(conversation_id=convo_id, role="assistant", content=response)
-    )
 
-    # Auto-title: first user message becomes the title (truncated)
-    if convo.title == "New Chat":
-        convo.title = query[:120].strip() or "New Chat"
+        # Auto-create a conversation if none supplied
+        if not convo_id:
+            convo = models.Conversation(user_id=user.id, title="New Chat")
+            db.add(convo)
+            db.commit()
+            db.refresh(convo)
+            convo_id = convo.id
+        else:
+            convo = (
+                db.query(models.Conversation)
+                .filter(
+                    models.Conversation.id == convo_id,
+                    models.Conversation.user_id == user.id,
+                )
+                .first()
+            )
+            if not convo:
+                raise HTTPException(status_code=404, detail="Conversation not found")
+
+        # Rebuild in-memory history from DB when switching conversations
+        _load_history_for_convo(convo_id, db)
+
+        if _reset_search is not None:
+            _reset_search()
+        all_messages = _chat_history + [{"role": "user", "content": query}]
+        result = chain.invoke({"messages": all_messages})
+        messages = result.get("messages", [])
+        response = messages[-1].content if messages else "No response generated"
+
+        # Persist to DB
+        db.add(models.ChatMessage(conversation_id=convo_id, role="user", content=query))
+        db.add(
+            models.ChatMessage(
+                conversation_id=convo_id, role="assistant", content=response
+            )
+        )
 
-    db.commit()
+        # Auto-title: first user message becomes the title (truncated)
+        if convo.title == "New Chat":
+            convo.title = query[:120].strip() or "New Chat"
 
-    # Update in-memory history
-    _chat_history.append({"role": "user", "content": query})
-    _chat_history.append({"role": "assistant", "content": response})
+        db.commit()
 
-    return {"response": response, "conversationId": convo_id}
+        # Update in-memory history
+        _chat_history.append({"role": "user", "content": query})
+        _chat_history.append({"role": "assistant", "content": response})
+        status = "ok"
+        return {"response": response, "conversationId": convo_id}
+    except Exception as exc:
+        error_type = type(exc).__name__
+        raise
+    finally:
+        log_request_summary(
+            request_id=request_id,
+            endpoint=req.url.path,
+            start_time=start_time,
+            status=status,
+            error_type=error_type,
+        )
 
 
 @app.post("/chat/clear")
 async def clear_chat(
+    req: Request,
     user: models.User = Depends(get_current_user),
 ):
     """Reset the in-memory LangChain context (does NOT delete DB messages)."""
+    request_id = request_id_from_request(req)
+    start_time = time.perf_counter()
+    status = "error"
+    error_type = None
     global _active_convo_id, _chat_history
-    if not _ensure_chatbot():
-        detail = "Chatbot is not configured"
-        if "_chatbot_error" in globals():
-            detail = f"{detail}: {_chatbot_error}"
-        raise HTTPException(status_code=503, detail=detail)
-    if _reset_search is not None:
-        _reset_search()
-    _chat_history.clear()
-    _active_convo_id = None
-    return {"message": "Chat session reset"}
+    try:
+        if not _ensure_chatbot():
+            detail = "Chatbot is not configured"
+            if "_chatbot_error" in globals():
+                detail = f"{detail}: {_chatbot_error}"
+            raise HTTPException(status_code=503, detail=detail)
+        if _reset_search is not None:
+            _reset_search()
+        _chat_history.clear()
+        _active_convo_id = None
+        status = "ok"
+        return {"message": "Chat session reset"}
+    except Exception as exc:
+        error_type = type(exc).__name__
+        raise
+    finally:
+        log_request_summary(
+            request_id=request_id,
+            endpoint=req.url.path,
+            start_time=start_time,
+            status=status,
+            error_type=error_type,
+        )
 
 
 @app.get("/chat/status")
-async def chat_status():
-    configured = _ensure_chatbot()
-    detail = None
-    if not configured and "_chatbot_error" in globals():
-        detail = str(_chatbot_error)
-    return {"configured": configured, "error": detail}
+async def chat_status(req: Request):
+    request_id = request_id_from_request(req)
+    start_time = time.perf_counter()
+    status = "error"
+    error_type = None
+    try:
+        configured = _ensure_chatbot()
+        detail = None
+        if not configured and "_chatbot_error" in globals():
+            detail = str(_chatbot_error)
+        status = "ok"
+        return {"configured": configured, "error": detail}
+    except Exception as exc:
+        error_type = type(exc).__name__
+        raise
+    finally:
+        log_request_summary(
+            request_id=request_id,
+            endpoint=req.url.path,
+            start_time=start_time,
+            status=status,
+            error_type=error_type,
+        )
 
 
 # ---------------------------------------------------------------------------
@@ -819,48 +876,84 @@ def _ensure_helper_chat(task_key: str):
 
 @app.post("/chat/helper/query")
 async def chat_helper_query(req: Request):
-    body = await req.json()
-    task_key = body.get("taskKey")
-    query = body.get("query")
-    field_context = body.get("fieldContext", "")
-
-    if not task_key:
-        raise HTTPException(status_code=400, detail="taskKey is required")
-    if not isinstance(query, str) or not query.strip():
-        raise HTTPException(status_code=400, detail="query must be a non-empty string.")
-
-    if not _ensure_helper_chat(task_key):
-        detail = "Helper chatbot is not configured"
-        if "_chatbot_error" in globals():
-            detail = f"{detail}: {_chatbot_error}"
-        raise HTTPException(status_code=503, detail=detail)
-
-    agent, reset_fn = _helper_chains[task_key]
-    history = _helper_histories[task_key]
-
-    # Prepend field context to the first message so the LLM knows what field
-    # the user is looking at.
-    user_content = (
-        f"[Field context: {field_context}]\n\n{query}" if field_context else query
-    )
+    request_id = request_id_from_request(req)
+    start_time = time.perf_counter()
+    status = "error"
+    error_type = None
+    try:
+        body = await req.json()
+        task_key = body.get("taskKey")
+        query = body.get("query")
+        field_context = body.get("fieldContext", "")
+
+        if not task_key:
+            raise HTTPException(status_code=400, detail="taskKey is required")
+        if not isinstance(query, str) or not query.strip():
+            raise HTTPException(
+                status_code=400, detail="query must be a non-empty string."
+            )
+
+        if not _ensure_helper_chat(task_key):
+            detail = "Helper chatbot is not configured"
+            if "_chatbot_error" in globals():
+                detail = f"{detail}: {_chatbot_error}"
+            raise HTTPException(status_code=503, detail=detail)
 
-    reset_fn()
-    all_messages = history + [{"role": "user", "content": user_content}]
-    result = agent.invoke({"messages": all_messages})
-    messages = result.get("messages", [])
-    response = messages[-1].content if messages else "No response generated"
-    history.append({"role": "user", "content": user_content})
-    history.append({"role": "assistant", "content": response})
-    return {"response": response}
+        agent, reset_fn = _helper_chains[task_key]
+        history = _helper_histories[task_key]
+
+        # Prepend field context to the first message so the LLM knows what field
+        # the user is looking at.
+        user_content = (
+            f"[Field context: {field_context}]\n\n{query}" if field_context else query
+        )
+
+        reset_fn()
+        all_messages = history + [{"role": "user", "content": user_content}]
+        result = agent.invoke({"messages": all_messages})
+        messages = result.get("messages", [])
+        response = messages[-1].content if messages else "No response generated"
+        history.append({"role": "user", "content": user_content})
+        history.append({"role": "assistant", "content": response})
+        status = "ok"
+        return {"response": response}
+    except Exception as exc:
+        error_type = type(exc).__name__
+        raise
+    finally:
+        log_request_summary(
+            request_id=request_id,
+            endpoint=req.url.path,
+            start_time=start_time,
+            status=status,
+            error_type=error_type,
+        )
 
 
 @app.post("/chat/helper/clear")
 async def chat_helper_clear(req: Request):
-    body = await req.json()
-    task_key = body.get("taskKey")
-    if task_key and task_key in _helper_histories:
-        _helper_histories[task_key].clear()
-    return {"message": "Helper chat cleared"}
+    request_id = request_id_from_request(req)
+    start_time = time.perf_counter()
+    status = "error"
+    error_type = None
+    try:
+        body = await req.json()
+        task_key = body.get("taskKey")
+        if task_key and task_key in _helper_histories:
+            _helper_histories[task_key].clear()
+        status = "ok"
+        return {"message": "Helper chat cleared"}
+    except Exception as exc:
+        error_type = type(exc).__name__
+        raise
+    finally:
+        log_request_summary(
+            request_id=request_id,
+            endpoint=req.url.path,
+            start_time=start_time,
+            status=status,
+            error_type=error_type,
+        )
 
 
 def run():