From dc9fc5afabd32ed34c439d2544e99e8a655a2b8b Mon Sep 17 00:00:00 2001 From: Maria Duda Date: Tue, 16 Jun 2026 23:14:28 -0300 Subject: [PATCH] feat(devops): emit structured JSON logs (#38) --- backend/src/simples_backend/app.py | 26 ++++++++-- backend/src/simples_backend/logging_config.py | 51 +++++++++++++++++++ backend/src/simples_backend/routes/compile.py | 18 +++++++ backend/src/simples_backend/routes/run_ws.py | 44 ++++++++++++++-- 4 files changed, 133 insertions(+), 6 deletions(-) create mode 100644 backend/src/simples_backend/logging_config.py diff --git a/backend/src/simples_backend/app.py b/backend/src/simples_backend/app.py index fe2a5d3..45bef76 100644 --- a/backend/src/simples_backend/app.py +++ b/backend/src/simples_backend/app.py @@ -1,8 +1,10 @@ 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 @@ -10,6 +12,7 @@ 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, diff --git a/backend/src/simples_backend/logging_config.py b/backend/src/simples_backend/logging_config.py new file mode 100644 index 0000000..2e1ad36 --- /dev/null +++ b/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) diff --git a/backend/src/simples_backend/routes/compile.py b/backend/src/simples_backend/routes/compile.py index 617e841..1e5afc6 100644 --- a/backend/src/simples_backend/routes/compile.py +++ b/backend/src/simples_backend/routes/compile.py @@ -1,5 +1,8 @@ from __future__ import annotations +import logging +import time + from flask import Blueprint, g, jsonify, request from flask_limiter import Limiter @@ -7,6 +10,8 @@ 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": { diff --git a/backend/src/simples_backend/routes/run_ws.py b/backend/src/simples_backend/routes/run_ws.py index 677f342..2a98fb0 100644 --- a/backend/src/simples_backend/routes/run_ws.py +++ b/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,6 +139,7 @@ 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() @@ -114,6 +147,11 @@ def handle_ws_connection( 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: