diff --git a/mini-program/.env.example b/mini-program/.env.example index ae08b16..667f70a 100644 --- a/mini-program/.env.example +++ b/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 diff --git a/mini-program/app/db.py b/mini-program/app/db.py index d07fa46..830734d 100644 --- a/mini-program/app/db.py +++ b/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"}) diff --git a/mini-program/app/logging_setup.py b/mini-program/app/logging_setup.py new file mode 100644 index 0000000..a75c160 --- /dev/null +++ b/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 diff --git a/mini-program/app/main.py b/mini-program/app/main.py index 0e9546c..3dba028 100644 --- a/mini-program/app/main.py +++ b/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) diff --git a/mini-program/app/middleware/auth.py b/mini-program/app/middleware/auth.py index 0427158..1c718c9 100644 --- a/mini-program/app/middleware/auth.py +++ b/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 diff --git a/mini-program/app/middleware/request_log.py b/mini-program/app/middleware/request_log.py new file mode 100644 index 0000000..5cfe65c --- /dev/null +++ b/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 diff --git a/mini-program/app/routers/auth.py b/mini-program/app/routers/auth.py index 5066c6d..248ea13 100644 --- a/mini-program/app/routers/auth.py +++ b/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, diff --git a/mini-program/app/routers/messages.py b/mini-program/app/routers/messages.py index 36c917b..4b23553 100644 --- a/mini-program/app/routers/messages.py +++ b/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, diff --git a/mini-program/app/settings.py b/mini-program/app/settings.py index 3f0fe71..528f08a 100644 --- a/mini-program/app/settings.py +++ b/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: