feat(devops): emit structured JSON logs (#38)

backend/src/simples_backend/app.py

@@ -1,15 +1,18 @@
 from __future__ import annotations
 
 import logging
+import time
+
+from flask import Flask, g, jsonify, request
 
-from flask import Flask, jsonify
 from flask_limiter import Limiter
 from flask_limiter.errors import RateLimitExceeded as LimiterRateLimitExceeded
 from flask_limiter.util import get_remote_address
 from flask_sock import Sock
 
 from .auth import AuthError
 from .config import Settings, load_settings
+from .logging_config import configure_logging
 from .routes import (
     create_auth_blueprint,
     create_compile_blueprint,
@@ -24,16 +27,33 @@
     req.subprotocols[0] if req.subprotocols else None
 )
 
+logger = logging.getLogger(__name__)
+
 
 def create_app(settings: Settings | None = None) -> Flask:
-    logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s %(message)s")
-    """Flask application factory."""
+    configure_logging()
 
     app = Flask(__name__)
 
     resolved = load_settings() if settings is None else settings
     app.config["SETTINGS"] = resolved
 
+    @app.before_request
+    def _before_request():
+        g.request_start = time.monotonic()
+
+    @app.after_request
+    def _after_request(response):
+        duration_ms = int((time.monotonic() - g.request_start) * 1000)
+        logger.info(
+            "%s %s -> %s",
+            request.method,
+            request.path,
+            response.status_code,
+            extra={"duration_ms": duration_ms},
+        )
+        return response
+
     limiter = Limiter(
         get_remote_address,
         app=app,

backend/src/simples_backend/logging_config.py

@@ -0,0 +1,51 @@
+from __future__ import annotations
+
+import json
+import logging
+import uuid
+from datetime import datetime, timezone
+
+from flask import g, has_request_context
+
+
+class RequestIdFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        record.request_id = ""
+        record.user_id = ""
+        if has_request_context():
+            if not hasattr(g, "request_id"):
+                g.request_id = str(uuid.uuid4())
+            record.request_id = g.request_id
+            identity = getattr(g, "identity", None)
+            if identity:
+                record.user_id = identity.get("user_id", "")
+        return True
+
+
+class JsonFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        obj = {
+            "timestamp": datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat(),
+            "level": record.levelname,
+            "logger": record.name,
+            "message": record.getMessage(),
+            "module": record.module,
+            "function": record.funcName,
+            "line": record.lineno,
+        }
+        if getattr(record, "request_id", None):
+            obj["request_id"] = record.request_id
+        if getattr(record, "user_id", None):
+            obj["user_id"] = record.user_id
+        if getattr(record, "duration_ms", None) is not None:
+            obj["duration_ms"] = record.duration_ms
+        if record.exc_info and record.exc_info[0]:
+            obj["exception"] = self.formatException(record.exc_info)
+        return json.dumps(obj, ensure_ascii=False)
+
+
+def configure_logging() -> None:
+    handler = logging.StreamHandler()
+    handler.setFormatter(JsonFormatter())
+    handler.addFilter(RequestIdFilter())
+    logging.basicConfig(level=logging.INFO, handlers=[handler], force=True)

backend/src/simples_backend/routes/compile.py

@@ -1,12 +1,17 @@
 from __future__ import annotations
 
+import logging
+import time
+
 from flask import Blueprint, g, jsonify, request
 from flask_limiter import Limiter
 
 from ..auth import verify_jwt
 from ..config import Settings
 from ..services.compiler_service import CompilerError, compile_simples
 
+logger = logging.getLogger(__name__)
+
 MAX_CODE_SIZE = 1_000_000
 
 
@@ -39,10 +44,23 @@ def compile_code():
         if not isinstance(code, str) or not code.strip():
             return jsonify({"error": "invalid_code"}), 400
 
+        start = time.monotonic()
         try:
             nasm = compile_simples(code)
+            elapsed = int((time.monotonic() - start) * 1000)
+            logger.info(
+                "compile ok user=%s duration_ms=%d",
+                _user_key(), elapsed,
+                extra={"duration_ms": elapsed},
+            )
             return jsonify({"nasm": nasm})
         except CompilerError as e:
+            elapsed = int((time.monotonic() - start) * 1000)
+            logger.warning(
+                "compile error user=%s duration_ms=%d: %s",
+                _user_key(), elapsed, e.message,
+                extra={"duration_ms": elapsed},
+            )
             if e.phase is not None:
                 return jsonify({
                     "error": {

backend/src/simples_backend/routes/run_ws.py

@@ -3,9 +3,10 @@
 import json
 import logging
 import tempfile
+import time
 from enum import Enum, auto
 
-from flask import request
+from flask import g, request
 from flask_sock import Sock
 
 from flask_limiter import Limiter
@@ -47,8 +48,9 @@ def _send(ws, msg: dict) -> None:
         pass
 
 
-def handle_compile_and_run(ws, code: str, settings: Settings) -> ConnectionState:
+def handle_compile_and_run(ws, code: str, settings: Settings, identity: dict) -> ConnectionState:
     _send(ws, {"type": "compile_started"})
+    start = time.monotonic()
 
     try:
         with tempfile.TemporaryDirectory(prefix="sim-") as tmpdir:
@@ -58,12 +60,20 @@ def handle_compile_and_run(ws, code: str, settings: Settings) -> ConnectionState
             try:
                 obj_path = assemble_nasm(nasm, tmpdir, settings.compile_timeout_s)
             except ExecutionError as e:
+                logger.warning(
+                    "assemble failed: %s", e.message,
+                    extra={"user_id": identity.get("user_id", ""), "duration_ms": int((time.monotonic() - start) * 1000)},
+                )
                 _send(ws, {"type": "assemble_error", "stderr": e.message})
                 return ConnectionState.IDLE
 
             try:
                 bin_path = link_object(obj_path, tmpdir, settings.compile_timeout_s)
             except ExecutionError as e:
+                logger.warning(
+                    "link failed: %s", e.message,
+                    extra={"user_id": identity.get("user_id", ""), "duration_ms": int((time.monotonic() - start) * 1000)},
+                )
                 _send(ws, {"type": "link_error", "stderr": e.message})
                 return ConnectionState.IDLE
 
@@ -72,14 +82,31 @@ def handle_compile_and_run(ws, code: str, settings: Settings) -> ConnectionState
             strategy = PtyExecutionStrategy(image=settings.sandbox_image, stop_timeout_s=settings.stop_timeout_s)
             result = strategy.execute(tmpdir, ws, settings.exec_timeout_s)
 
+            elapsed = int((time.monotonic() - start) * 1000)
             if not result.timed_out:
                 _send(ws, {
                     "type": "exit",
                     "code": result.exit_code,
                     "duration_ms": result.duration_ms,
                 })
+            logger.info(
+                "compile_and_run %s code=%d user=%s duration_ms=%d",
+                "timeout" if result.timed_out else "done",
+                result.exit_code,
+                identity.get("user_id", ""),
+                elapsed,
+                extra={
+                    "user_id": identity.get("user_id", ""),
+                    "duration_ms": elapsed,
+                },
+            )
 
     except CompilerError as e:
+        elapsed = int((time.monotonic() - start) * 1000)
+        logger.warning(
+            "compile error: %s", e.message,
+            extra={"user_id": identity.get("user_id", ""), "duration_ms": elapsed},
+        )
         if e.phase is not None:
             _send(ws, {
                 "type": "compile_error",
@@ -91,6 +118,11 @@ def handle_compile_and_run(ws, code: str, settings: Settings) -> ConnectionState
         else:
             _send(ws, {"type": "internal_error", "message": e.message})
     except Exception as e:
+        elapsed = int((time.monotonic() - start) * 1000)
+        logger.error(
+            "unexpected error: %s", str(e),
+            extra={"user_id": identity.get("user_id", ""), "duration_ms": elapsed},
+        )
         _send(ws, {"type": "internal_error", "message": str(e)})
 
     return ConnectionState.IDLE
@@ -107,13 +139,19 @@ def handle_ws_connection(
             jwt_token = extract_jwt_from_ws()
             identity = verify_supabase_jwt(jwt_token, settings.supabase_jwt_secret, settings.supabase_url)
         except AuthError as e:
+            logger.info("ws auth failed: %s", e.code)
             _send(ws, {"type": "internal_error", "message": e.code})
             try:
                 ws.close()
             except Exception:
                 pass
             return
 
+    logger.info(
+        "ws connected user=%s", identity.get("user_id", ""),
+        extra={"user_id": identity.get("user_id", "")},
+    )
+
     state = ConnectionState.IDLE
 
     while True:
@@ -172,7 +210,7 @@ def handle_ws_connection(
                 continue
 
             state = ConnectionState.COMPILING
-            state = handle_compile_and_run(ws, code, settings)
+            state = handle_compile_and_run(ws, code, settings, identity)
             continue
 
         if t == "stdin" and state != ConnectionState.EXECUTING: