添加日志

mini-program/.env.example

@@ -12,3 +12,6 @@ DB_NAME=mini_program
 JWT_SECRET=change_me_to_a_long_random_string
 JWT_ALGORITHM=HS256
 JWT_ACCESS_TOKEN_EXPIRE_MINUTES=60
+LOG_LEVEL=INFO
+LOG_JSON=false
+SLOW_SQL_MS=200

mini-program/app/db.py

@@ -1,6 +1,8 @@
 from collections.abc import Generator
+import logging
+import time
 
-from sqlalchemy import create_engine, text
+from sqlalchemy import create_engine, event, text
 from sqlalchemy.orm import Session, sessionmaker
 
 try:
@@ -19,6 +21,47 @@ engine = create_engine(
     pool_recycle=1800,
     future=True,
 )
+logger = logging.getLogger("app.db")
+
+
+@event.listens_for(engine, "before_cursor_execute")
+def before_cursor_execute(
+    conn,
+    cursor,
+    statement,
+    parameters,
+    context,
+    executemany,
+):
+    conn.info.setdefault("query_start_time", []).append(time.perf_counter())
+
+
+@event.listens_for(engine, "after_cursor_execute")
+def after_cursor_execute(
+    conn,
+    cursor,
+    statement,
+    parameters,
+    context,
+    executemany,
+):
+    start_time = None
+    query_start_time = conn.info.get("query_start_time")
+    if query_start_time:
+        start_time = query_start_time.pop(-1)
+    if start_time is None:
+        return
+
+    elapsed_ms = (time.perf_counter() - start_time) * 1000
+    if elapsed_ms >= settings.slow_sql_ms:
+        logger.warning(
+            "slow sql detected",
+            extra={
+                "event": "slow_sql",
+                "sql_ms": round(elapsed_ms, 2),
+                "statement": " ".join(statement.split())[:280],
+            },
+        )
 
 SessionLocal = sessionmaker(
     bind=engine,
@@ -39,7 +82,9 @@ def get_db() -> Generator[Session, None, None]:
 def check_db_connection() -> None:
     with engine.connect() as conn:
         conn.execute(text("SELECT 1"))
+    logger.info("database connection check succeeded", extra={"event": "db_check"})
 
 
 def close_db_engine() -> None:
     engine.dispose()
+    logger.info("database engine disposed", extra={"event": "db_close"})

mini-program/app/logging_setup.py

@@ -0,0 +1,86 @@
+import json
+import logging
+from datetime import UTC, datetime
+
+try:
+    # For module mode: `uvicorn app.main:app`
+    from app.settings import settings
+except ModuleNotFoundError:
+    # For script mode: `python app/main.py` or VS Code "Run Python File"
+    from settings import settings
+
+
+_CONFIGURED = False
+
+
+class JsonFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        payload: dict[str, object] = {
+            "timestamp": datetime.now(UTC).isoformat(),
+            "level": record.levelname,
+            "logger": record.name,
+            "message": record.getMessage(),
+        }
+
+        for key in (
+            "event",
+            "request_id",
+            "method",
+            "path",
+            "status_code",
+            "duration_ms",
+            "client_ip",
+            "user_id",
+            "conversation_id",
+            "message_id",
+            "seq",
+            "client_msg_id",
+            "idempotent",
+            "count",
+            "has_more",
+            "cursor_seq",
+            "limit",
+            "reason",
+            "sql_ms",
+            "statement",
+            "username",
+        ):
+            if hasattr(record, key):
+                payload[key] = getattr(record, key)
+
+        if record.exc_info:
+            payload["exception"] = self.formatException(record.exc_info)
+        return json.dumps(payload, ensure_ascii=False)
+
+
+def configure_logging() -> None:
+    global _CONFIGURED
+    if _CONFIGURED:
+        return
+
+    log_level_name = settings.log_level.upper().strip()
+    log_level = getattr(logging, log_level_name, logging.INFO)
+
+    handler = logging.StreamHandler()
+    if settings.log_json:
+        handler.setFormatter(JsonFormatter())
+    else:
+        handler.setFormatter(
+            logging.Formatter(
+                fmt="%(asctime)s | %(levelname)s | %(name)s | %(message)s",
+            )
+        )
+
+    root_logger = logging.getLogger()
+    root_logger.handlers.clear()
+    root_logger.setLevel(log_level)
+    root_logger.addHandler(handler)
+
+    # Keep uvicorn logs consistent with app logs.
+    for logger_name in ("uvicorn", "uvicorn.error", "uvicorn.access"):
+        uvicorn_logger = logging.getLogger(logger_name)
+        uvicorn_logger.handlers.clear()
+        uvicorn_logger.propagate = True
+    logging.getLogger("httpx").setLevel(logging.WARNING)
+
+    _CONFIGURED = True

mini-program/app/main.py

@@ -1,11 +1,14 @@
 import os
+import logging
 
 from fastapi import FastAPI
 
 try:
     # For module mode: `uvicorn app.main:app`
     from app.db import check_db_connection, close_db_engine
+    from app.logging_setup import configure_logging
     from app.middleware.auth import install_auth_middleware
+    from app.middleware.request_log import install_request_logging_middleware
     from app.routers.auth import router as auth_router
     from app.routers.health import router as health_router
     from app.routers.messages import router as messages_router
@@ -13,13 +16,19 @@ try:
 except ModuleNotFoundError:
     # For script mode: `python app/main.py` or VS Code "Run Python File"
     from db import check_db_connection, close_db_engine
+    from logging_setup import configure_logging
     from middleware.auth import install_auth_middleware
+    from middleware.request_log import install_request_logging_middleware
     from routers.auth import router as auth_router
     from routers.health import router as health_router
     from routers.messages import router as messages_router
     from settings import settings
 
 
+configure_logging()
+logger = logging.getLogger("app.main")
+
+
 def create_app() -> FastAPI:
     app = FastAPI(
         title=settings.app_name,
@@ -30,12 +39,15 @@ def create_app() -> FastAPI:
     @app.on_event("startup")
     def on_startup() -> None:
         check_db_connection()
+        logger.info("application started", extra={"event": "app_start"})
 
     @app.on_event("shutdown")
     def on_shutdown() -> None:
+        logger.info("application shutting down", extra={"event": "app_shutdown"})
         close_db_engine()
 
     install_auth_middleware(app)
+    install_request_logging_middleware(app)
     app.include_router(auth_router)
     app.include_router(health_router)
     app.include_router(messages_router)

mini-program/app/middleware/auth.py

@@ -1,4 +1,5 @@
 from collections.abc import Awaitable, Callable
+import logging
 
 from fastapi import FastAPI, HTTPException, Request
 from sqlalchemy import text
@@ -21,6 +22,8 @@ EXCLUDED_PATH_PREFIXES = (
     "/auth/login",
 )
 
+logger = logging.getLogger("app.auth")
+
 
 def _is_excluded_path(path: str) -> bool:
     for prefix in EXCLUDED_PATH_PREFIXES:
@@ -41,15 +44,42 @@ def install_auth_middleware(app: FastAPI) -> None:
 
         auth_header = request.headers.get("Authorization")
         if not auth_header:
+            logger.warning(
+                "auth failed: missing header",
+                extra={
+                    "event": "auth_check",
+                    "request_id": getattr(request.state, "request_id", None),
+                    "path": path,
+                    "reason": "missing_authorization_header",
+                },
+            )
             return auth_error_response("missing authorization header")
 
         parts = auth_header.split(" ", 1)
         if len(parts) != 2 or parts[0].lower() != "bearer":
+            logger.warning(
+                "auth failed: invalid header format",
+                extra={
+                    "event": "auth_check",
+                    "request_id": getattr(request.state, "request_id", None),
+                    "path": path,
+                    "reason": "invalid_authorization_format",
+                },
+            )
             return auth_error_response("invalid authorization format")
 
         try:
             user_id = decode_access_token(parts[1].strip())
         except HTTPException:
+            logger.warning(
+                "auth failed: invalid token",
+                extra={
+                    "event": "auth_check",
+                    "request_id": getattr(request.state, "request_id", None),
+                    "path": path,
+                    "reason": "invalid_or_expired_token",
+                },
+            )
             return auth_error_response("invalid or expired access token")
 
         with SessionLocal() as db:
@@ -69,6 +99,16 @@ def install_auth_middleware(app: FastAPI) -> None:
                 .first()
             )
             if not user_row or int(user_row["status"]) != 1:
+                logger.warning(
+                    "auth failed: user unavailable",
+                    extra={
+                        "event": "auth_check",
+                        "request_id": getattr(request.state, "request_id", None),
+                        "path": path,
+                        "user_id": user_id,
+                        "reason": "user_not_found_or_disabled",
+                    },
+                )
                 return auth_error_response("user not found or disabled")
 
         request.state.user_id = user_id

mini-program/app/middleware/request_log.py

@@ -0,0 +1,65 @@
+import logging
+import time
+import uuid
+from collections.abc import Awaitable, Callable
+
+from fastapi import FastAPI, Request
+from starlette.responses import Response
+
+
+logger = logging.getLogger("app.request")
+
+
+def install_request_logging_middleware(app: FastAPI) -> None:
+    @app.middleware("http")
+    async def request_logging_middleware(
+        request: Request,
+        call_next: Callable[[Request], Awaitable[Response]],
+    ) -> Response:
+        request_id = request.headers.get("X-Request-ID") or uuid.uuid4().hex
+        request.state.request_id = request_id
+        started_at = time.perf_counter()
+
+        try:
+            response = await call_next(request)
+        except Exception:
+            duration_ms = round((time.perf_counter() - started_at) * 1000, 2)
+            logger.exception(
+                "request failed",
+                extra={
+                    "event": "request",
+                    "request_id": request_id,
+                    "method": request.method,
+                    "path": request.url.path,
+                    "status_code": 500,
+                    "duration_ms": duration_ms,
+                    "client_ip": request.client.host if request.client else None,
+                    "user_id": getattr(request.state, "user_id", None),
+                },
+            )
+            raise
+
+        duration_ms = round((time.perf_counter() - started_at) * 1000, 2)
+        status_code = response.status_code
+        level = logging.INFO
+        if status_code >= 500:
+            level = logging.ERROR
+        elif status_code >= 400:
+            level = logging.WARNING
+
+        logger.log(
+            level,
+            "request completed",
+            extra={
+                "event": "request",
+                "request_id": request_id,
+                "method": request.method,
+                "path": request.url.path,
+                "status_code": status_code,
+                "duration_ms": duration_ms,
+                "client_ip": request.client.host if request.client else None,
+                "user_id": getattr(request.state, "user_id", None),
+            },
+        )
+        response.headers["X-Request-ID"] = request_id
+        return response

mini-program/app/routers/auth.py

@@ -1,6 +1,7 @@
 import hashlib
+import logging
 
-from fastapi import APIRouter, Depends, HTTPException, status
+from fastapi import APIRouter, Depends, HTTPException, Request, status
 from sqlalchemy import text
 from sqlalchemy.orm import Session
 
@@ -17,10 +18,22 @@ except ModuleNotFoundError:
 
 
 router = APIRouter(prefix="/auth", tags=["auth"])
+logger = logging.getLogger("app.auth")
+
+
+def _mask_username(username: str) -> str:
+    if len(username) <= 2:
+        return "*" * len(username)
+    return f"{username[:2]}***"
 
 
 @router.post("/login", response_model=LoginResponse)
-def login(payload: LoginRequest, db: Session = Depends(get_db)) -> LoginResponse:
+def login(
+    payload: LoginRequest,
+    request: Request,
+    db: Session = Depends(get_db),
+) -> LoginResponse:
+    username_masked = _mask_username(payload.username)
     with db.begin():
         row = (
             db.execute(
@@ -45,12 +58,31 @@ def login(payload: LoginRequest, db: Session = Depends(get_db)) -> LoginResponse
             .first()
         )
         if not row:
+            logger.warning(
+                "login failed",
+                extra={
+                    "event": "login",
+                    "request_id": getattr(request.state, "request_id", None),
+                    "username": username_masked,
+                    "reason": "invalid_username_or_password",
+                },
+            )
             raise HTTPException(
                 status_code=status.HTTP_401_UNAUTHORIZED,
                 detail="invalid username or password",
             )
 
         if int(row["auth_status"]) != 1 or int(row["user_status"]) != 1:
+            logger.warning(
+                "login failed",
+                extra={
+                    "event": "login",
+                    "request_id": getattr(request.state, "request_id", None),
+                    "username": username_masked,
+                    "user_id": int(row["user_id"]),
+                    "reason": "account_disabled",
+                },
+            )
             raise HTTPException(
                 status_code=status.HTTP_401_UNAUTHORIZED,
                 detail="account is disabled",
@@ -59,6 +91,15 @@ def login(payload: LoginRequest, db: Session = Depends(get_db)) -> LoginResponse
         # Seed data currently stores sha256; migrate to bcrypt/argon2 in production.
         password_hash = hashlib.sha256(payload.password.encode("utf-8")).hexdigest()
         if not row["password_hash"] or password_hash != row["password_hash"]:
+            logger.warning(
+                "login failed",
+                extra={
+                    "event": "login",
+                    "request_id": getattr(request.state, "request_id", None),
+                    "username": username_masked,
+                    "reason": "invalid_username_or_password",
+                },
+            )
             raise HTTPException(
                 status_code=status.HTTP_401_UNAUTHORIZED,
                 detail="invalid username or password",
@@ -88,6 +129,15 @@ def login(payload: LoginRequest, db: Session = Depends(get_db)) -> LoginResponse
         )
 
     access_token, expires_in = create_access_token(user_id=int(row["user_id"]))
+    logger.info(
+        "login succeeded",
+        extra={
+            "event": "login",
+            "request_id": getattr(request.state, "request_id", None),
+            "user_id": int(row["user_id"]),
+            "username": username_masked,
+        },
+    )
     return LoginResponse(
         access_token=access_token,
         expires_in=expires_in,

mini-program/app/routers/messages.py

@@ -1,8 +1,9 @@
 import json
+import logging
 from collections.abc import Mapping
 from typing import Any
 
-from fastapi import APIRouter, Depends, HTTPException, Query, Response, status
+from fastapi import APIRouter, Depends, HTTPException, Query, Request, Response, status
 from sqlalchemy import text
 from sqlalchemy.orm import Session
 
@@ -29,6 +30,7 @@ except ModuleNotFoundError:
 
 
 router = APIRouter(prefix="/messages", tags=["messages"])
+logger = logging.getLogger("app.messages")
 
 
 def _build_preview(content_type: int, content_text: str | None) -> str:
@@ -141,6 +143,7 @@ def _assert_conversation_access(
 @router.post("", response_model=MessageCreateResponse, status_code=status.HTTP_201_CREATED)
 def create_message(
     payload: MessageCreateRequest,
+    request: Request,
     response: Response,
     current_user_id: int = Depends(get_current_user_id),
     db: Session = Depends(get_db),
@@ -223,6 +226,19 @@ def create_message(
 
         existing = _get_existing_message(db, conversation_id, payload.client_msg_id)
         if existing:
+            logger.info(
+                "message idempotent hit",
+                extra={
+                    "event": "message_create",
+                    "request_id": getattr(request.state, "request_id", None),
+                    "user_id": sender_user_id,
+                    "conversation_id": conversation_id,
+                    "message_id": int(existing["id"]),
+                    "seq": int(existing["seq"]),
+                    "client_msg_id": payload.client_msg_id,
+                    "idempotent": True,
+                },
+            )
             response.status_code = status.HTTP_200_OK
             return MessageCreateResponse(
                 idempotent=True,
@@ -328,6 +344,19 @@ def create_message(
         if not created:
             raise HTTPException(status_code=500, detail="failed to load created message")
 
+    logger.info(
+        "message created",
+        extra={
+            "event": "message_create",
+            "request_id": getattr(request.state, "request_id", None),
+            "user_id": sender_user_id,
+            "conversation_id": conversation_id,
+            "message_id": int(created["id"]),
+            "seq": int(created["seq"]),
+            "client_msg_id": payload.client_msg_id,
+            "idempotent": False,
+        },
+    )
     return MessageCreateResponse(
         idempotent=False,
         message=_row_to_message_item(created),
@@ -336,6 +365,7 @@ def create_message(
 
 @router.get("", response_model=MessageListResponse)
 def list_messages(
+    request: Request,
     conversation_id: int = Query(gt=0),
     cursor_seq: int | None = Query(default=None, ge=1),
     limit: int = Query(default=20, ge=1, le=100),
@@ -382,6 +412,19 @@ def list_messages(
     items = [_row_to_message_item(row) for row in rows]
 
     next_cursor_seq = items[0].seq if has_more and items else None
+    logger.info(
+        "messages listed",
+        extra={
+            "event": "message_list",
+            "request_id": getattr(request.state, "request_id", None),
+            "user_id": current_user_id,
+            "conversation_id": conversation_id,
+            "cursor_seq": cursor_seq,
+            "limit": limit,
+            "count": len(items),
+            "has_more": has_more,
+        },
+    )
     return MessageListResponse(
         conversation_id=conversation_id,
         has_more=has_more,

mini-program/app/settings.py

@@ -35,6 +35,9 @@ class Settings(BaseSettings):
         default=60,
         validation_alias="JWT_ACCESS_TOKEN_EXPIRE_MINUTES",
     )
+    log_level: str = Field(default="INFO", validation_alias="LOG_LEVEL")
+    log_json: bool = Field(default=False, validation_alias="LOG_JSON")
+    slow_sql_ms: int = Field(default=200, validation_alias="SLOW_SQL_MS")
 
     @property
     def mysql_dsn(self) -> str: