Add comprehensive structured logging with Loki + Grafana

Backend logging:
- Centralized JSON logging config with LOG_LEVEL env var
- Request logging middleware: user, method, path, status, duration, request_id
- Fixed all 9 silent except:pass blocks to log warnings with tracebacks
- Celery workers use same structured JSON format

Infrastructure:
- Loki 3.3.2 for log storage (30-day retention)
- Promtail 3.3.2 for Docker container log shipping
- Grafana 10.3.1 with auto-provisioned Loki datasource
- Grafana on port 3002 (admin/pedshub_grafana)

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

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()

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)

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")
 

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

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)

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 {}
 
 

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()
 

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

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

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:

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

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

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: