From 03272b99d0be482dcdf4931eaacc2a7cec71622e Mon Sep 17 00:00:00 2001 From: Adam Gohain <68021524+akgohain@users.noreply.github.com> Date: Mon, 13 Apr 2026 15:59:16 -0400 Subject: [PATCH] Add standardized chat endpoint observability logs --- server_api/main.py | 297 +++++++++++++++++++++--------- tests/test_chat_logging_fields.py | 86 +++++++++ 2 files changed, 298 insertions(+), 85 deletions(-) create mode 100644 tests/test_chat_logging_fields.py diff --git a/server_api/main.py b/server_api/main.py index a97153f..19cd41e 100644 --- a/server_api/main.py +++ b/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 @@ -45,6 +48,22 @@ # Helper chat (inline "?" popovers) — keyed by taskKey for isolated sessions _helper_chains = {} # taskKey -> (agent, reset_fn) _helper_histories = {} # taskKey -> list of messages +_chat_logger = logging.getLogger("server_api.chat_observability") + + +def _log_chat_request_summary( + *, request_id: str, endpoint: str, start_time: float, status: str, error_type: str = "" +): + """Emit a single-line structured summary log for chat/workflow endpoints.""" + latency_ms = round((time.perf_counter() - start_time) * 1000, 2) + _chat_logger.info( + "chat_request_summary request_id=%s endpoint=%s latency_ms=%s status=%s error_type=%s", + request_id, + endpoint, + latency_ms, + status, + error_type, + ) def _ensure_chatbot(): @@ -709,63 +728,95 @@ async def chat_query( user: models.User = Depends(get_current_user), db: Session = Depends(get_db), ): + request_id = str(uuid.uuid4()) + endpoint = "/chat/query" + start_time = time.perf_counter() if not _ensure_chatbot(): detail = "Chatbot is not configured" if "_chatbot_error" in globals(): detail = f"{detail}: {_chatbot_error}" + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="error", + error_type="HTTPException", + ) 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, + try: + 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, + ) + .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, ) - .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} + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="ok", + ) + return {"response": response, "conversationId": convo_id} + except Exception as exc: + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="error", + error_type=type(exc).__name__, + ) + raise @app.post("/chat/clear") @@ -773,25 +824,61 @@ async def clear_chat( user: models.User = Depends(get_current_user), ): """Reset the in-memory LangChain context (does NOT delete DB messages).""" + request_id = str(uuid.uuid4()) + endpoint = "/chat/clear" + start_time = time.perf_counter() 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}" + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="error", + error_type="HTTPException", + ) 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 _reset_search is not None: + _reset_search() + _chat_history.clear() + _active_convo_id = None + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="ok", + ) + return {"message": "Chat session reset"} + except Exception as exc: + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="error", + error_type=type(exc).__name__, + ) + raise @app.get("/chat/status") async def chat_status(): + request_id = str(uuid.uuid4()) + endpoint = "/chat/status" + start_time = time.perf_counter() configured = _ensure_chatbot() detail = None if not configured and "_chatbot_error" in globals(): detail = str(_chatbot_error) + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="ok" if configured else "error", + error_type="" if configured else "ChatbotUnavailable", + ) return {"configured": configured, "error": detail} @@ -819,48 +906,88 @@ 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", "") + request_id = str(uuid.uuid4()) + endpoint = "/chat/helper/query" + start_time = time.perf_counter() + 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 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}) + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="ok", + ) + return {"response": response} + except Exception as exc: + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="error", + error_type=type(exc).__name__, + ) + raise @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 = str(uuid.uuid4()) + endpoint = "/chat/helper/clear" + start_time = time.perf_counter() + try: + body = await req.json() + task_key = body.get("taskKey") + if task_key and task_key in _helper_histories: + _helper_histories[task_key].clear() + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="ok", + ) + return {"message": "Helper chat cleared"} + except Exception as exc: + _log_chat_request_summary( + request_id=request_id, + endpoint=endpoint, + start_time=start_time, + status="error", + error_type=type(exc).__name__, + ) + raise def run(): diff --git a/tests/test_chat_logging_fields.py b/tests/test_chat_logging_fields.py new file mode 100644 index 0000000..43251fb --- /dev/null +++ b/tests/test_chat_logging_fields.py @@ -0,0 +1,86 @@ +import re +import sys +import types +import unittest +from types import SimpleNamespace +from unittest.mock import patch + +from fastapi.testclient import TestClient +from fastapi import APIRouter + +ehtool_router_stub = types.ModuleType("server_api.ehtool.router") +ehtool_router_stub.router = APIRouter() +sys.modules.setdefault("server_api.ehtool.router", ehtool_router_stub) +sys.modules.setdefault("server_api.ehtool", types.SimpleNamespace(router=ehtool_router_stub)) + +from server_api.auth.router import get_current_user +from server_api.main import app + + +class ChatLoggingFieldsTests(unittest.TestCase): + def setUp(self): + self.client = TestClient(app) + app.dependency_overrides[get_current_user] = ( + lambda: SimpleNamespace(id=999, username="test") + ) + + def tearDown(self): + app.dependency_overrides.clear() + + def test_chat_query_success_emits_standard_summary_fields(self): + class DummyChain: + def invoke(self, payload): + return {"messages": [SimpleNamespace(content="assistant response")]} + + with patch("server_api.main._ensure_chatbot", return_value=True), patch( + "server_api.main.chain", DummyChain() + ), patch( + "server_api.main._reset_search", None + ), self.assertLogs( + "server_api.chat_observability", level="INFO" + ) as captured: + response = self.client.post("/chat/query", json={"query": "my secret prompt"}) + + self.assertEqual(response.status_code, 200) + log_line = captured.output[-1] + self.assertIn("request_id=", log_line) + self.assertIn("endpoint=/chat/query", log_line) + self.assertIn("latency_ms=", log_line) + self.assertIn("status=ok", log_line) + self.assertIn("error_type=", log_line) + self.assertNotIn("my secret prompt", log_line) + + def test_chat_helper_query_error_emits_standard_summary_fields(self): + with patch("server_api.main._ensure_helper_chat", return_value=False), self.assertLogs( + "server_api.chat_observability", level="INFO" + ) as captured: + response = self.client.post( + "/chat/helper/query", + json={"taskKey": "workflow_agent", "query": "help me"}, + ) + + self.assertEqual(response.status_code, 503) + log_line = captured.output[-1] + self.assertIn("request_id=", log_line) + self.assertIn("endpoint=/chat/helper/query", log_line) + self.assertIn("latency_ms=", log_line) + self.assertIn("status=error", log_line) + self.assertIn("error_type=HTTPException", log_line) + self.assertNotIn("help me", log_line) + + def test_chat_status_failure_includes_error_type_field(self): + with patch("server_api.main._ensure_chatbot", return_value=False), patch( + "server_api.main._chatbot_error", Exception("down") + ), self.assertLogs("server_api.chat_observability", level="INFO") as captured: + response = self.client.get("/chat/status") + + self.assertEqual(response.status_code, 200) + log_line = captured.output[-1] + self.assertIn("endpoint=/chat/status", log_line) + self.assertIn("status=error", log_line) + self.assertIn("error_type=ChatbotUnavailable", log_line) + self.assertRegex(log_line, r"request_id=[0-9a-f-]{36}") + + +if __name__ == "__main__": + unittest.main()