diff --git a/backend/app/config.py b/backend/app/config.py index 2668ef2..cd26706 100644 --- a/backend/app/config.py +++ b/backend/app/config.py @@ -51,5 +51,7 @@ class Settings(BaseSettings): OIDC_SCOPES: str = "openid email profile" # space-separated OIDC_PROVIDER_NAME: str = "SSO" # Display name on login button + LOG_LEVEL: str = "INFO" # DEBUG, INFO, WARNING, ERROR + settings = Settings() diff --git a/backend/app/logging_config.py b/backend/app/logging_config.py new file mode 100644 index 0000000..1474a05 --- /dev/null +++ b/backend/app/logging_config.py @@ -0,0 +1,52 @@ +"""Centralized structured JSON logging for backend and Celery workers.""" +import logging +import logging.config +import sys + + +def setup_logging(level: str = "INFO"): + """Configure all Python loggers to output structured JSON to stdout.""" + try: + from pythonjsonlogger.json import JsonFormatter + formatter_class = "pythonjsonlogger.json.JsonFormatter" + formatter_fmt = "%(asctime)s %(name)s %(levelname)s %(message)s" + except ImportError: + # Fallback if python-json-logger not installed + formatter_class = "logging.Formatter" + formatter_fmt = "%(asctime)s [%(levelname)s] %(name)s: %(message)s" + + config = { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "json": { + "class": formatter_class, + "format": formatter_fmt, + "datefmt": "%Y-%m-%dT%H:%M:%S", + }, + }, + "handlers": { + "console": { + "class": "logging.StreamHandler", + "stream": "ext://sys.stdout", + "formatter": "json", + }, + }, + "root": { + "level": level.upper(), + "handlers": ["console"], + }, + "loggers": { + # Quieten noisy libraries + "uvicorn.access": {"level": "WARNING"}, + "uvicorn.error": {"level": level.upper()}, + "chromadb": {"level": "WARNING"}, + "httpcore": {"level": "WARNING"}, + "httpx": {"level": "WARNING"}, + "celery": {"level": level.upper()}, + "sqlalchemy.engine": {"level": "WARNING"}, + }, + } + + logging.config.dictConfig(config) + logging.getLogger(__name__).debug("Logging configured: level=%s", level) diff --git a/backend/app/main.py b/backend/app/main.py index 964b3a3..94af015 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -6,6 +6,10 @@ from fastapi.middleware.cors import CORSMiddleware from fastapi.staticfiles import StaticFiles from app.config import settings +from app.logging_config import setup_logging + +# Configure structured JSON logging before anything else +setup_logging(settings.LOG_LEVEL) from app.database import engine, Base, SessionLocal from app.routers import auth, documents, quizzes, attempts, admin, tts, nextcloud, categories, questions, question_categories, favorites, teach, contact, tags, flashcards, courses from app.utils.auth import get_password_hash @@ -513,6 +517,10 @@ app.add_middleware(SessionMiddleware, secret_key=settings.SECRET_KEY) from app.utils.auth import TokenRefreshMiddleware app.add_middleware(TokenRefreshMiddleware) +# Request logging middleware — logs every request with user, duration, status +from app.middleware.request_logging import RequestLoggingMiddleware +app.add_middleware(RequestLoggingMiddleware) + # Serve uploaded images as static files app.mount("/uploads", StaticFiles(directory=settings.UPLOAD_DIR), name="uploads") diff --git a/backend/app/middleware/__init__.py b/backend/app/middleware/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/backend/app/middleware/request_logging.py b/backend/app/middleware/request_logging.py new file mode 100644 index 0000000..a63eda5 --- /dev/null +++ b/backend/app/middleware/request_logging.py @@ -0,0 +1,70 @@ +"""Middleware that logs every HTTP request with user context and timing.""" +import logging +import time +import uuid + +from starlette.middleware.base import BaseHTTPMiddleware +from starlette.requests import Request + +logger = logging.getLogger("pedshub.requests") + +# Paths to skip logging (noisy or uninteresting) +SKIP_PATHS = {"/api/health", "/favicon.ico", "/robots.txt"} +SKIP_PREFIXES = ("/uploads/",) + + +class RequestLoggingMiddleware(BaseHTTPMiddleware): + async def dispatch(self, request: Request, call_next): + path = request.url.path + + # Skip noisy paths + if path in SKIP_PATHS or any(path.startswith(p) for p in SKIP_PREFIXES): + return await call_next(request) + + request_id = uuid.uuid4().hex[:8] + request.state.request_id = request_id + + # Extract user from JWT (best-effort, never block) + user_id = None + user_email = None + auth = request.headers.get("authorization", "") + if auth.startswith("Bearer "): + try: + from jose import jwt + from app.config import settings + payload = jwt.decode( + auth[7:], settings.SECRET_KEY, + algorithms=[settings.ALGORITHM], + options={"verify_exp": False}, + ) + user_email = payload.get("sub") + except Exception: + pass + + start = time.perf_counter() + response = await call_next(request) + duration_ms = round((time.perf_counter() - start) * 1000, 1) + + status = response.status_code + method = request.method + client_ip = request.client.host if request.client else "-" + + log_data = { + "request_id": request_id, + "method": method, + "path": path, + "status": status, + "duration_ms": duration_ms, + "client_ip": client_ip, + } + if user_email: + log_data["user"] = user_email + + if status >= 500: + logger.error("%(method)s %(path)s %(status)s %(duration_ms)sms", log_data, extra=log_data) + elif status >= 400: + logger.warning("%(method)s %(path)s %(status)s %(duration_ms)sms", log_data, extra=log_data) + else: + logger.info("%(method)s %(path)s %(status)s %(duration_ms)sms", log_data, extra=log_data) + + return response diff --git a/backend/app/routers/attempts.py b/backend/app/routers/attempts.py index 39f57c9..23dc4a8 100644 --- a/backend/app/routers/attempts.py +++ b/backend/app/routers/attempts.py @@ -1,6 +1,9 @@ +import logging from datetime import datetime from fastapi import APIRouter, Depends, HTTPException, Request + +logger = logging.getLogger(__name__) from pydantic import BaseModel from sqlalchemy.orm import Session from sqlalchemy import func @@ -163,7 +166,7 @@ def submit_attempt( r = redis_lib.from_url(settings.REDIS_URL, decode_responses=True) r.delete(f"quiz_progress:{current_user.id}:{attempt.quiz_id}") except Exception: - pass + logger.warning("Failed to clear quiz progress from Redis", exc_info=True) percentage = (score / attempt.total_questions * 100) if attempt.total_questions > 0 else 0 @@ -173,7 +176,7 @@ def submit_attempt( from app.services.reminder_service import update_reminder_schedule update_reminder_schedule(db, current_user.id, attempt.quiz_id, percentage) except Exception: - pass # Don't fail submission if reminder update fails + logger.warning("Failed to update reminder schedule for quiz %d", attempt.quiz_id, exc_info=True) return AttemptDetail( id=attempt.id, @@ -259,7 +262,7 @@ def save_progress( "total_time": data.total_time, })) except Exception: - pass # Redis unavailable — degrade gracefully + logger.warning("Redis unavailable for progress save", exc_info=True) return {"saved": True} @@ -338,11 +341,11 @@ def get_progress( r.delete(key) return None # no progress to resume — already submitted except Exception: - pass + logger.warning("Failed to check quiz timer expiration", exc_info=True) return saved except Exception: - pass + logger.warning("Redis unavailable for progress retrieval", exc_info=True) return None @@ -358,7 +361,7 @@ def clear_progress( r = redis_lib.from_url(settings.REDIS_URL, decode_responses=True) r.delete(f"quiz_progress:{current_user.id}:{attempt_id}") except Exception: - pass + logger.warning("Redis unavailable for progress clear", exc_info=True) @router.delete("/{attempt_id}", status_code=204) diff --git a/backend/app/routers/courses.py b/backend/app/routers/courses.py index d7c61c1..1586c5c 100644 --- a/backend/app/routers/courses.py +++ b/backend/app/routers/courses.py @@ -1018,7 +1018,7 @@ async def upload_scorm_package( launch_file = href break except Exception: - pass + logger.warning("Failed to parse SCORM manifest for lesson %d", lesson_id, exc_info=True) if not launch_file: launch_file = "index.html" # fallback @@ -1072,6 +1072,7 @@ def get_scorm_data( data = r.get(key) return json.loads(data) if data else {} except Exception: + logger.warning("Redis unavailable for SCORM data retrieval", exc_info=True) return {} diff --git a/backend/app/routers/questions.py b/backend/app/routers/questions.py index 6542f4d..1c2654a 100644 --- a/backend/app/routers/questions.py +++ b/backend/app/routers/questions.py @@ -1,9 +1,12 @@ """Question bank — view, search, categorise, and create quizzes from individual questions.""" import csv import io +import logging import os import re import uuid + +logger = logging.getLogger(__name__) from fastapi import APIRouter, Depends, HTTPException, Query, UploadFile, File, Form from fastapi.responses import StreamingResponse from pydantic import BaseModel @@ -382,7 +385,7 @@ def create_question_manually( embedding_service.embed_question(question) db.commit() except Exception: - pass + logger.warning("Failed to generate embedding for question %d", question.id, exc_info=True) return { "id": question.id, @@ -647,7 +650,7 @@ def upload_questions_csv( from app.services import embedding_service embedding_service.embed_question(q) except Exception: - pass + logger.warning("Failed to generate embedding for imported question %d", q.id, exc_info=True) if created: db.commit() diff --git a/backend/app/tasks/__init__.py b/backend/app/tasks/__init__.py index 846a808..d45e372 100644 --- a/backend/app/tasks/__init__.py +++ b/backend/app/tasks/__init__.py @@ -1,6 +1,10 @@ from celery import Celery from app.config import settings +from app.logging_config import setup_logging + +# Configure structured JSON logging for Celery workers +setup_logging(settings.LOG_LEVEL) celery_app = Celery( "quiz_tasks", @@ -11,3 +15,4 @@ celery_app = Celery( celery_app.conf.task_serializer = "json" celery_app.conf.result_serializer = "json" celery_app.conf.accept_content = ["json"] +celery_app.conf.worker_hijack_root_logger = False # Don't override our JSON logging diff --git a/backend/requirements.txt b/backend/requirements.txt index 7d2ac08..3e8ab8d 100644 --- a/backend/requirements.txt +++ b/backend/requirements.txt @@ -24,3 +24,4 @@ openpyxl==3.1.2 authlib==1.3.0 itsdangerous==2.1.2 fpdf2==2.8.1 +python-json-logger>=2.0.0 diff --git a/docker-compose.yml b/docker-compose.yml index 3b55ebd..de4fbe5 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -33,6 +33,7 @@ services: - ./backend/.env environment: - ANONYMIZED_TELEMETRY=False + - LOG_LEVEL=${LOG_LEVEL:-INFO} volumes: - uploads_data:/app/uploads - chroma_data:/app/chroma_data @@ -45,11 +46,12 @@ services: celery: build: ./backend - command: celery -A app.tasks worker --loglevel=info --concurrency=2 + command: celery -A app.tasks worker --loglevel=${LOG_LEVEL:-info} --concurrency=2 env_file: - ./backend/.env environment: - ANONYMIZED_TELEMETRY=False + - LOG_LEVEL=${LOG_LEVEL:-INFO} volumes: - uploads_data:/app/uploads - chroma_data:/app/chroma_data @@ -66,6 +68,43 @@ services: - redis_data:/data restart: unless-stopped + # ── Logging: Loki + Promtail + Grafana ────────────────────────────── + loki: + image: grafana/loki:3.3.2 + restart: unless-stopped + command: -config.file=/etc/loki/loki-config.yml + volumes: + - ./loki/loki-config.yml:/etc/loki/loki-config.yml:ro + - loki_data:/loki + ports: + - "127.0.0.1:3100:3100" + + promtail: + image: grafana/promtail:3.3.2 + restart: unless-stopped + command: -config.file=/etc/promtail/promtail-config.yml + volumes: + - ./promtail/promtail-config.yml:/etc/promtail/promtail-config.yml:ro + - /var/lib/docker/containers:/var/lib/docker/containers:ro + - /var/run/docker.sock:/var/run/docker.sock:ro + - promtail_positions:/positions + depends_on: + - loki + + grafana: + image: grafana/grafana:10.3.1 + restart: unless-stopped + environment: + GF_SECURITY_ADMIN_PASSWORD: ${GRAFANA_ADMIN_PASSWORD:?set GRAFANA_ADMIN_PASSWORD} + GF_AUTH_ANONYMOUS_ENABLED: "false" + volumes: + - grafana_data:/var/lib/grafana + - ./grafana/provisioning:/etc/grafana/provisioning:ro + ports: + - "127.0.0.1:3002:3000" + depends_on: + - loki + db-backup: image: prodrigestivill/postgres-backup-local:16 restart: unless-stopped @@ -90,3 +129,6 @@ volumes: chroma_data: postgres_data: redis_data: + loki_data: + grafana_data: + promtail_positions: diff --git a/grafana/provisioning/datasources/loki.yml b/grafana/provisioning/datasources/loki.yml new file mode 100644 index 0000000..9a14ad2 --- /dev/null +++ b/grafana/provisioning/datasources/loki.yml @@ -0,0 +1,8 @@ +apiVersion: 1 +datasources: + - name: Loki + type: loki + access: proxy + url: http://loki:3100 + isDefault: true + editable: false diff --git a/loki/loki-config.yml b/loki/loki-config.yml new file mode 100644 index 0000000..0be16e8 --- /dev/null +++ b/loki/loki-config.yml @@ -0,0 +1,36 @@ +auth_enabled: false + +server: + http_listen_port: 3100 + +common: + path_prefix: /loki + storage: + filesystem: + chunks_directory: /loki/chunks + rules_directory: /loki/rules + replication_factor: 1 + ring: + kvstore: + store: inmemory + +schema_config: + configs: + - from: 2020-10-24 + store: tsdb + object_store: filesystem + schema: v13 + index: + prefix: index_ + period: 24h + +limits_config: + retention_period: 30d + max_query_series: 500 + +compactor: + working_directory: /loki/compactor + compaction_interval: 10m + retention_enabled: true + retention_delete_delay: 2h + delete_request_store: filesystem diff --git a/promtail/promtail-config.yml b/promtail/promtail-config.yml new file mode 100644 index 0000000..c397c00 --- /dev/null +++ b/promtail/promtail-config.yml @@ -0,0 +1,48 @@ +server: + http_listen_port: 9080 + grpc_listen_port: 0 + +positions: + filename: /positions/positions.yaml + +clients: + - url: http://loki:3100/loki/api/v1/push + +scrape_configs: + - job_name: docker + docker_sd_configs: + - host: unix:///var/run/docker.sock + refresh_interval: 5s + relabel_configs: + # Keep only quiz-* containers + - source_labels: ['__meta_docker_container_name'] + regex: '.*quiz.*' + action: keep + # Extract container name as label + - source_labels: ['__meta_docker_container_name'] + regex: '/?(.*)' + target_label: container + # Extract compose service name + - source_labels: ['__meta_docker_container_label_com_docker_compose_service'] + target_label: service + pipeline_stages: + # Docker JSON log wrapper + - docker: {} + # Try to parse structured JSON logs from backend/celery + - match: + selector: '{service=~"backend|celery"}' + stages: + - json: + expressions: + level: levelname + logger: name + msg: message + request_id: request_id + method: method + path: path + status: status + duration_ms: duration_ms + user: user + - labels: + level: + logger: