Files
FabledScribe/src/fabledassistant/services/logging.py
T
bvandeusen 765e99bb24 Fix duplicate message bug and add generation timing instrumentation
Bug fix:
- ChatView.vue onMounted now skips fetchConversation when the conversation
  is already loaded in the store (same guard that the convId watcher uses).
  This prevents duplicate assistant messages when navigating from the
  dashboard inline chat to /chat/:id after streaming completes.

Generation timing:
- logging.py: add log_generation() — persists per-generation timing
  breakdown to app_logs (category=usage, action=generation) including
  model, total_ms, intent_ms, ttft_ms, generation_ms, and per-tool timings.
  Queryable via existing admin log viewer.
- generation_task.py: collect wall-clock timestamps at every pipeline stage:
  intent classification, per-tool execution (both intent-routed and native),
  time-to-first-token (measured from generation start to first content chunk),
  LLM streaming round duration. Logs via log_generation() and includes timing
  in the SSE 'done' event payload.
- types/chat.ts: add GenerationTiming interface; add optional timing field
  to Message.
- chat.ts: capture timing from done event and attach to assistant message.
- ChatMessage.vue: show timing footer on assistant messages with breakdown:
  "⏱ 4.2s total · first token 0.8s · analyzed 0.3s · created event 0.4s
  · generated 3.5s". Visible this session; persisted to app_logs for
  cross-session benchmarking.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
2026-02-18 18:18:46 -05:00

198 lines
6.0 KiB
Python

"""Application logging service for audit, usage, and error events."""
import asyncio
import json
import logging
import traceback as tb_module
from datetime import datetime, timedelta, timezone
from sqlalchemy import delete, func, select, text
from fabledassistant.config import Config
from fabledassistant.models import async_session
from fabledassistant.models.app_log import AppLog
logger = logging.getLogger(__name__)
_retention_task: asyncio.Task | None = None
async def log_audit(
action: str,
user_id: int | None = None,
username: str | None = None,
ip_address: str | None = None,
details: dict | None = None,
) -> None:
async with async_session() as session:
log = AppLog(
category="audit",
user_id=user_id,
username=username,
action=action,
ip_address=ip_address,
details=json.dumps(details) if details else None,
)
session.add(log)
await session.commit()
async def log_usage(
user_id: int | None = None,
username: str | None = None,
endpoint: str | None = None,
method: str | None = None,
status_code: int | None = None,
duration_ms: float | None = None,
) -> None:
async with async_session() as session:
log = AppLog(
category="usage",
user_id=user_id,
username=username,
endpoint=endpoint,
method=method,
status_code=status_code,
duration_ms=duration_ms,
)
session.add(log)
await session.commit()
async def log_generation(
user_id: int,
conv_id: int,
model: str,
timing: dict,
) -> None:
"""Persist per-generation timing breakdown to app_logs for benchmarking."""
async with async_session() as session:
log = AppLog(
category="usage",
user_id=user_id,
action="generation",
endpoint=f"/chat/conversations/{conv_id}",
duration_ms=timing.get("total_ms"),
details=json.dumps({"model": model, **timing}),
)
session.add(log)
await session.commit()
async def log_error(
user_id: int | None = None,
username: str | None = None,
endpoint: str | None = None,
method: str | None = None,
error_type: str | None = None,
error_message: str | None = None,
traceback: str | None = None,
) -> None:
details = {}
if error_type:
details["error_type"] = error_type
if error_message:
details["error_message"] = error_message
if traceback:
details["traceback"] = traceback
async with async_session() as session:
log = AppLog(
category="error",
user_id=user_id,
username=username,
endpoint=endpoint,
method=method,
details=json.dumps(details) if details else None,
)
session.add(log)
await session.commit()
async def get_logs(
category: str | None = None,
user_id: int | None = None,
search: str | None = None,
date_from: str | None = None,
date_to: str | None = None,
limit: int = 50,
offset: int = 0,
) -> tuple[list[dict], int]:
async with async_session() as session:
query = select(AppLog)
count_query = select(func.count(AppLog.id))
if category:
query = query.where(AppLog.category == category)
count_query = count_query.where(AppLog.category == category)
if user_id is not None:
query = query.where(AppLog.user_id == user_id)
count_query = count_query.where(AppLog.user_id == user_id)
if search:
pattern = f"%{search}%"
search_filter = (
AppLog.action.ilike(pattern)
| AppLog.endpoint.ilike(pattern)
| AppLog.username.ilike(pattern)
| AppLog.details.ilike(pattern)
)
query = query.where(search_filter)
count_query = count_query.where(search_filter)
if date_from:
query = query.where(AppLog.created_at >= date_from)
count_query = count_query.where(AppLog.created_at >= date_from)
if date_to:
query = query.where(AppLog.created_at <= date_to)
count_query = count_query.where(AppLog.created_at <= date_to)
total = (await session.execute(count_query)).scalar() or 0
query = query.order_by(AppLog.created_at.desc()).limit(limit).offset(offset)
result = await session.execute(query)
logs = [row.to_dict() for row in result.scalars().all()]
return logs, total
async def get_log_stats() -> dict:
async with async_session() as session:
result = await session.execute(
text(
"SELECT category, COUNT(*) as count FROM app_logs GROUP BY category"
)
)
stats = {row.category: row.count for row in result}
return {
"audit": stats.get("audit", 0),
"usage": stats.get("usage", 0),
"error": stats.get("error", 0),
"total": sum(stats.values()),
}
async def delete_old_logs(retention_days: int) -> int:
cutoff = datetime.now(timezone.utc) - timedelta(days=retention_days)
async with async_session() as session:
result = await session.execute(
delete(AppLog).where(AppLog.created_at < cutoff)
)
await session.commit()
return result.rowcount
async def _retention_loop() -> None:
while True:
await asyncio.sleep(3600) # hourly
try:
deleted = await delete_old_logs(Config.LOG_RETENTION_DAYS)
if deleted:
logger.info("Log retention: deleted %d old log entries", deleted)
except Exception:
logger.exception("Error in log retention cleanup")
def start_log_retention_loop() -> None:
global _retention_task
if _retention_task is None or _retention_task.done():
_retention_task = asyncio.create_task(_retention_loop())