Backend chat observability: add standardized request summary logs

server_api/main.py

@@ -1,8 +1,11 @@
 import json
+import logging
 import pathlib
 import re
 import shutil
 import tempfile
+import time
+import uuid
 from typing import List, Optional
 from urllib.parse import urlsplit, urlunsplit
 
@@ -25,6 +28,8 @@
 from fastapi.staticfiles import StaticFiles
 import os
 
+logger = logging.getLogger(__name__)
+
 # Chatbot is optional; keep the server running if dependencies or model endpoints
 # are unavailable. We initialize lazily on demand.
 try:
@@ -709,63 +714,92 @@ 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,
+    started_at = time.perf_counter()
+    request_id = req.headers.get("x-request-id") or str(uuid.uuid4())
+    endpoint = req.url.path
+    status = "ok"
+    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-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
+            )
+        )
 
-    # Auto-title: first user message becomes the title (truncated)
-    if convo.title == "New Chat":
-        convo.title = query[:120].strip() or "New Chat"
+        # Auto-title: first user message becomes the title (truncated)
+        if convo.title == "New Chat":
+            convo.title = query[:120].strip() or "New Chat"
 
-    db.commit()
+        db.commit()
 
-    # Update in-memory history
-    _chat_history.append({"role": "user", "content": query})
-    _chat_history.append({"role": "assistant", "content": response})
+        # Update in-memory history
+        _chat_history.append({"role": "user", "content": query})
+        _chat_history.append({"role": "assistant", "content": response})
 
-    return {"response": response, "conversationId": convo_id}
+        return {"response": response, "conversationId": convo_id}
+    except Exception as exc:
+        status = "error"
+        error_type = type(exc).__name__
+        raise
+    finally:
+        latency_ms = round((time.perf_counter() - started_at) * 1000, 3)
+        logger.info(
+            "chat_request_summary %s",
+            json.dumps(
+                {
+                    "request_id": request_id,
+                    "endpoint": endpoint,
+                    "latency_ms": latency_ms,
+                    "status": status,
+                    "error_type": error_type,
+                },
+                sort_keys=True,
+            ),
+        )
 
 
 @app.post("/chat/clear")
@@ -819,39 +853,66 @@ 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.")
+    started_at = time.perf_counter()
+    request_id = req.headers.get("x-request-id") or str(uuid.uuid4())
+    endpoint = req.url.path
+    status = "ok"
+    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)
+        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]
+        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
-    )
+        # 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})
-    return {"response": response}
+        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}
+    except Exception as exc:
+        status = "error"
+        error_type = type(exc).__name__
+        raise
+    finally:
+        latency_ms = round((time.perf_counter() - started_at) * 1000, 3)
+        logger.info(
+            "chat_request_summary %s",
+            json.dumps(
+                {
+                    "request_id": request_id,
+                    "endpoint": endpoint,
+                    "latency_ms": latency_ms,
+                    "status": status,
+                    "error_type": error_type,
+                },
+                sort_keys=True,
+            ),
+        )
 
 
 @app.post("/chat/helper/clear")

tests/test_chat_logging_fields.py

@@ -0,0 +1,122 @@
+import asyncio
+import json
+import sys
+import unittest
+from types import SimpleNamespace
+from unittest.mock import patch
+
+sys.modules.setdefault("tifffile", SimpleNamespace())
+sys.modules.setdefault("cv2", SimpleNamespace())
+
+import server_api.main as main
+
+
+class _FakeRequest:
+    def __init__(self, payload, path, headers=None):
+        self._payload = payload
+        self.url = SimpleNamespace(path=path)
+        self.headers = headers or {}
+
+    async def json(self):
+        return self._payload
+
+
+class _FakeQuery:
+    def __init__(self, convo):
+        self._convo = convo
+
+    def filter(self, *args, **kwargs):
+        return self
+
+    def first(self):
+        return self._convo
+
+
+class _FakeDB:
+    def __init__(self, convo):
+        self._convo = convo
+
+    def query(self, model):
+        return _FakeQuery(self._convo)
+
+    def add(self, _obj):
+        return None
+
+    def commit(self):
+        return None
+
+
+class _FakeAgent:
+    def invoke(self, _payload):
+        raise RuntimeError("agent stalled")
+
+
+class ChatLoggingFieldsTests(unittest.TestCase):
+    def _extract_summary_payload(self, logs):
+        for entry in logs:
+            if "chat_request_summary " in entry:
+                return json.loads(entry.split("chat_request_summary ", 1)[1])
+        self.fail(f"No chat_request_summary line found in logs: {logs}")
+
+    def test_chat_query_logs_standard_fields_on_success(self):
+        convo = SimpleNamespace(id=7, title="Existing")
+        fake_db = _FakeDB(convo=convo)
+        fake_user = SimpleNamespace(id=99)
+        request = _FakeRequest(
+            payload={"query": "hello", "conversationId": 7},
+            path="/chat/query",
+            headers={"x-request-id": "req-success"},
+        )
+
+        with (
+            patch.object(main, "_ensure_chatbot", return_value=True),
+            patch.object(main, "_load_history_for_convo", return_value=None),
+            patch.object(main, "_chat_history", []),
+            patch.object(main, "_reset_search", None),
+            patch.object(
+                main,
+                "chain",
+                SimpleNamespace(
+                    invoke=lambda _payload: {
+                        "messages": [SimpleNamespace(content="assistant response")]
+                    }
+                ),
+            ),
+            self.assertLogs("server_api.main", level="INFO") as captured,
+        ):
+            response = asyncio.run(main.chat_query(request, user=fake_user, db=fake_db))
+
+        self.assertEqual(response, {"response": "assistant response", "conversationId": 7})
+        payload = self._extract_summary_payload(captured.output)
+        self.assertEqual(payload["request_id"], "req-success")
+        self.assertEqual(payload["endpoint"], "/chat/query")
+        self.assertEqual(payload["status"], "ok")
+        self.assertIsNone(payload["error_type"])
+        self.assertIsInstance(payload["latency_ms"], (int, float))
+
+    def test_chat_helper_query_logs_standard_fields_on_error(self):
+        request = _FakeRequest(
+            payload={"taskKey": "workflow-agent", "query": "help"},
+            path="/chat/helper/query",
+            headers={"x-request-id": "req-error"},
+        )
+
+        with (
+            patch.object(main, "_ensure_helper_chat", return_value=True),
+            patch.dict(main._helper_chains, {"workflow-agent": (_FakeAgent(), lambda: None)}, clear=True),
+            patch.dict(main._helper_histories, {"workflow-agent": []}, clear=True),
+            self.assertLogs("server_api.main", level="INFO") as captured,
+        ):
+            with self.assertRaises(RuntimeError):
+                asyncio.run(main.chat_helper_query(request))
+
+        payload = self._extract_summary_payload(captured.output)
+        self.assertEqual(payload["request_id"], "req-error")
+        self.assertEqual(payload["endpoint"], "/chat/helper/query")
+        self.assertEqual(payload["status"], "error")
+        self.assertEqual(payload["error_type"], "RuntimeError")
+        self.assertIsInstance(payload["latency_ms"], (int, float))
+
+
+if __name__ == "__main__":
+    unittest.main()