Observability (oopsies)

.gitignore

@@ -42,3 +42,8 @@ judging/
 
 plan.md
 
+# Local runtime logs
+logs/
+!logs/.gitkeep
+!logs/**/.gitkeep
+

app/__init__.py

@@ -1,7 +1,13 @@
 import os
+import json
+import uuid
+import logging
+import time
+from logging.handlers import RotatingFileHandler
+from datetime import datetime, timezone
 
 from dotenv import load_dotenv
-from flask import Flask, jsonify
+from flask import Flask, current_app, jsonify, g, request
 from flask_cors import CORS
 
 from app.database import init_db, db, check_db_connection
@@ -12,12 +18,106 @@
 from app.routes import register_routes
 
 
+class JsonFormatter(logging.Formatter):
+    def format(self, record):
+        payload = {
+            "ts": datetime.now(timezone.utc).isoformat(),
+            "level": record.levelname,
+            "logger": record.name,
+            "event": record.getMessage(),
+            "service": "url-shortener-api",
+        }
+
+        # Allow route and dependency logs to attach machine-readable fields.
+        for key in (
+            "request_id",
+            "method",
+            "path",
+            "endpoint",
+            "route",
+            "status_code",
+            "duration_ms",
+            "component",
+            "error",
+            "user_id",
+            "url_id",
+            "short_code",
+            "param",
+            "value",
+            "resource",
+            "reason",
+            "log_level",
+        ):
+            if hasattr(record, key):
+                payload[key] = getattr(record, key)
+
+        return json.dumps(payload, ensure_ascii=True)
+
+
+def _configure_logging(app: Flask) -> None:
+    level_name = os.environ.get("LOG_LEVEL", "INFO").upper()
+    level = getattr(logging, level_name, logging.INFO)
+    log_file_path = os.environ.get("LOG_FILE_PATH", "logs/app.log")
+    log_max_bytes = int(os.environ.get("LOG_FILE_MAX_BYTES", str(10 * 1024 * 1024)))
+    log_backup_count = int(os.environ.get("LOG_FILE_BACKUP_COUNT", "5"))
+
+    formatter = JsonFormatter()
+    stream_handler = logging.StreamHandler()
+    stream_handler.setFormatter(formatter)
+
+    handlers = [stream_handler]
+    file_logging_error = None
+    try:
+        log_dir = os.path.dirname(log_file_path)
+        if log_dir:
+            os.makedirs(log_dir, exist_ok=True)
+        file_handler = RotatingFileHandler(
+            log_file_path,
+            maxBytes=log_max_bytes,
+            backupCount=log_backup_count,
+            encoding="utf-8",
+        )
+        file_handler.setFormatter(formatter)
+        handlers.append(file_handler)
+    except OSError as exc:
+        file_logging_error = str(exc)
+
+    app.logger.handlers.clear()
+    for handler in handlers:
+        app.logger.addHandler(handler)
+    app.logger.setLevel(level)
+    app.logger.propagate = False
+
+    werkzeug_logger = logging.getLogger("werkzeug")
+    werkzeug_logger.handlers.clear()
+    for handler in handlers:
+        werkzeug_logger.addHandler(handler)
+    werkzeug_logger.setLevel(level)
+    werkzeug_logger.propagate = False
+
+    app.logger.info(
+        "logger_configured",
+        extra={"endpoint": "app._configure_logging", "log_level": level_name, "resource": log_file_path},
+    )
+
+    if file_logging_error:
+        app.logger.warning(
+            "file_logging_disabled",
+            extra={
+                "endpoint": "app._configure_logging",
+                "resource": log_file_path,
+                "error": file_logging_error,
+            },
+        )
+
+
 def create_app():
     load_dotenv()
 
     app = Flask(__name__)
     app.config["SECRET_KEY"] = os.environ.get("SECRET_KEY", "dev-secret-change-me")
     CORS(app)
+    _configure_logging(app)
 
     init_db(app)
     init_cache()
@@ -26,17 +126,53 @@ def create_app():
     try:
         db.create_tables([User, URL, Event], safe=True)
     except Exception:
+        current_app.logger.warning(
+            "db_create_tables_skipped",
+            extra={"component": "db", "endpoint": "app.create_app", "reason": "tables_already_exist_or_race"},
+        )
         pass  # Tables already created by another instance
     db.close()
 
     register_routes(app)
 
+    @app.before_request
+    def _before_request_log_start():
+        g.request_start = time.perf_counter()
+        g.request_id = request.headers.get("X-Request-ID") or str(uuid.uuid4())
+
+    @app.after_request
+    def _after_request_log(response):
+        start = getattr(g, "request_start", None)
+        elapsed_ms = (time.perf_counter() - start) * 1000 if start else 0
+        app.logger.info(
+            "request_completed",
+            extra={
+                "request_id": getattr(g, "request_id", ""),
+                "method": request.method,
+                "path": request.path,
+                "endpoint": request.endpoint or "unknown",
+                "route": request.url_rule.rule if request.url_rule else "unknown",
+                "status_code": response.status_code,
+                "duration_ms": round(elapsed_ms, 2),
+            },
+        )
+        return response
+
     def _dependency_status():
         """Check DB and Redis. Returns (db_status, cache_status)."""
         try:
             check_db_connection()
             db_status = "ok"
         except Exception as e:
+            current_app.logger.error(
+                "dependency_check_failed",
+                extra={
+                    "component": "db",
+                    "endpoint": request.endpoint or "unknown",
+                    "route": request.url_rule.rule if request.url_rule else "unknown",
+                    "error": str(e),
+                },
+            )
             db_status = str(e)
 
         from app.cache import get_cache
@@ -46,6 +182,15 @@ def _dependency_status():
                 cache.ping()
             cache_status = "ok"
         except Exception as e:
+            current_app.logger.error(
+                "dependency_check_failed",
+                extra={
+                    "component": "cache",
+                    "endpoint": request.endpoint or "unknown",
+                    "route": request.url_rule.rule if request.url_rule else "unknown",
+                    "error": str(e),
+                },
+            )
             cache_status = str(e)
 
         return db_status, cache_status
@@ -79,14 +224,47 @@ def health():
 
     @app.errorhandler(404)
     def not_found(e):
+        app.logger.warning(
+            "http_not_found",
+            extra={
+                "request_id": getattr(g, "request_id", ""),
+                "method": request.method,
+                "path": request.path,
+                "endpoint": request.endpoint or "unknown",
+                "route": request.url_rule.rule if request.url_rule else "unknown",
+                "status_code": 404,
+            },
+        )
         return jsonify(error="not found"), 404
 
     @app.errorhandler(405)
     def method_not_allowed(e):
+        app.logger.warning(
+            "http_method_not_allowed",
+            extra={
+                "request_id": getattr(g, "request_id", ""),
+                "method": request.method,
+                "path": request.path,
+                "endpoint": request.endpoint or "unknown",
+                "route": request.url_rule.rule if request.url_rule else "unknown",
+                "status_code": 405,
+            },
+        )
         return jsonify(error="method not allowed"), 405
 
     @app.errorhandler(500)
     def internal_error(e):
+        app.logger.exception(
+            "http_internal_error",
+            extra={
+                "request_id": getattr(g, "request_id", ""),
+                "method": request.method,
+                "path": request.path,
+                "endpoint": request.endpoint or "unknown",
+                "route": request.url_rule.rule if request.url_rule else "unknown",
+                "status_code": 500,
+            },
+        )
         return jsonify(error="internal server error"), 500
 
     return app

app/routes/auth.py

@@ -46,6 +46,11 @@ def register():
         created_at=datetime.utcnow(),
     )
 
+    current_app.logger.info(
+        "user_registered",
+        extra={"component": "auth", "endpoint": "auth.register", "user_id": user.id, "value": email},
+    )
+
     return jsonify(
         session_token=_make_session_token(user.id),
         user={"id": user.id, "email": user.email},

app/routes/events.py

@@ -3,7 +3,7 @@
 import os
 from datetime import datetime
 
-from flask import Blueprint, jsonify, request
+from flask import current_app, Blueprint, jsonify, request
 
 from app.cache import cache_get, cache_set, cache_delete_pattern
 from app.database import db
@@ -33,7 +33,7 @@ def list_events():
     user_id = request.args.get("user_id")
     event_type = request.args.get("event_type")
 
-    cache_key = f"events:list:{url_id}:{user_id}:{event_type}"
+    cache_key = "events:list:" + str(url_id) + ":" + str(user_id) + ":" + str(event_type)
     cached = cache_get(cache_key)
     if cached is not None:
         return jsonify(cached)
@@ -44,12 +44,20 @@ def list_events():
         try:
             query = query.where(Event.url == int(url_id))
         except (ValueError, TypeError):
+            current_app.logger.warning(
+                "invalid_filter",
+                extra={"component": "events", "endpoint": "events.list_events", "param": "url_id", "value": str(url_id)},
+            )
             return jsonify(error="url_id must be an integer"), 400
 
     if user_id is not None:
         try:
             query = query.where(Event.user == int(user_id))
         except (ValueError, TypeError):
+            current_app.logger.warning(
+                "invalid_filter",
+                extra={"component": "events", "endpoint": "events.list_events", "param": "user_id", "value": str(user_id)},
+            )
             return jsonify(error="user_id must be an integer"), 400
 
     if event_type is not None:
@@ -58,6 +66,10 @@ def list_events():
     try:
         limit = int(request.args.get("limit", 100))
     except (ValueError, TypeError):
+        current_app.logger.warning(
+            "invalid_limit_parameter",
+            extra={"component": "events", "endpoint": "events.list_events", "param": "limit", "value": str(request.args.get("limit"))},
+        )
         limit = 100
     query = query.limit(min(limit, 500))
 
@@ -76,7 +88,11 @@ def load_events_csv():
         with open(filepath, newline="", encoding="utf-8") as f:
             rows = list(csv.DictReader(f))
     except FileNotFoundError:
-        return jsonify(error=f"{filename} not found"), 404
+        current_app.logger.error(
+            "file_not_found",
+            extra={"component": "events", "endpoint": "events.load_events_csv", "resource": filepath},
+        )
+        return jsonify(error=filename + " not found"), 404
 
     allowed = {"id", "url_id", "user_id", "event_type", "timestamp", "details"}
     now = str(datetime.utcnow())
@@ -87,6 +103,10 @@ def load_events_csv():
             try:
                 entry["details"] = json.loads(entry["details"])
             except (ValueError, TypeError):
+                current_app.logger.warning(
+                    "invalid_event_details_format",
+                    extra={"component": "events", "endpoint": "events.load_events_csv", "value": str(row)},
+                )
                 entry["details"] = None
         entry.setdefault("timestamp", now)
         cleaned.append(entry)