diff --git a/server_api/chatbot/logging_utils.py b/server_api/chatbot/logging_utils.py new file mode 100644 index 00000000..4cbbe819 --- /dev/null +++ b/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", + ) diff --git a/server_api/main.py b/server_api/main.py index a97153f8..44acbd88 100644 --- a/server_api/main.py +++ b/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(): diff --git a/tests/test_chat_logging_fields.py b/tests/test_chat_logging_fields.py new file mode 100644 index 00000000..71c02ee6 --- /dev/null +++ b/tests/test_chat_logging_fields.py @@ -0,0 +1,43 @@ +import logging +import time + +from server_api.chatbot import logging_utils + + +def test_standardized_summary_log_success_fields(caplog): + caplog.set_level(logging.INFO) + + logging_utils.log_request_summary( + request_id="req-123", + endpoint="/chat/query", + start_time=time.perf_counter() - 0.01, + status="ok", + ) + + message = caplog.records[-1].getMessage() + assert "request_id=req-123" in message + assert "endpoint=/chat/query" in message + assert "latency_ms=" in message + assert "status=ok" in message + assert "error_type=none" in message + + +def test_standardized_summary_log_error_fields_and_no_payload_leak(caplog): + caplog.set_level(logging.INFO) + sensitive_query = "my secret token is abc123" + + logging_utils.log_request_summary( + request_id="req-456", + endpoint="/chat/helper/query", + start_time=time.perf_counter() - 0.02, + status="error", + error_type="HTTPException", + ) + + message = caplog.records[-1].getMessage() + assert "request_id=req-456" in message + assert "endpoint=/chat/helper/query" in message + assert "latency_ms=" in message + assert "status=error" in message + assert "error_type=HTTPException" in message + assert sensitive_query not in message