Update the middleware logging accuracy (#713)

* Update the middleware logging accuracy

* Update the log style

Author: wu-clan

backend/common/log.py

@@ -94,7 +94,7 @@ def set_custom_logfile() -> None:
     log_config = {
         'format': settings.LOG_FILE_FORMAT,
         'enqueue': True,
-        'rotation': '5 MB',
+        'rotation': '00:00',
         'retention': '7 days',
         'compression': 'tar.gz',
     }

backend/core/conf.py

@@ -53,8 +53,8 @@ class Settings(BaseSettings):
     FASTAPI_STATIC_FILES: bool = True
 
     # 数据库
-    DATABASE_ECHO: bool = False
-    DATABASE_POOL_ECHO: bool = False
+    DATABASE_ECHO: bool | Literal['debug'] = False
+    DATABASE_POOL_ECHO: bool | Literal['debug'] = False
     DATABASE_SCHEMA: str = 'fba'
     DATABASE_CHARSET: str = 'utf8mb4'
 
@@ -115,7 +115,6 @@ class Settings(BaseSettings):
 
     # 中间件配置
     MIDDLEWARE_CORS: bool = True
-    MIDDLEWARE_ACCESS: bool = True
 
     # 请求限制配置
     REQUEST_LIMITER_REDIS_PREFIX: str = 'fba:limiter'
@@ -151,18 +150,14 @@ class Settings(BaseSettings):
     LOG_CID_DEFAULT_VALUE: str = '-'
     LOG_CID_UUID_LENGTH: int = 32  # 日志 correlation_id 长度，必须小于等于 32
     LOG_STD_LEVEL: str = 'INFO'
-    LOG_ACCESS_FILE_LEVEL: str = 'INFO'
-    LOG_ERROR_FILE_LEVEL: str = 'ERROR'
     LOG_STD_FORMAT: str = (
-        '<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</> | <lvl>{level: <8}</> | '
-        '<cyan> {correlation_id} </> | <lvl>{message}</>'
-    )
-    LOG_FILE_FORMAT: str = (
-        '<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</> | <lvl>{level: <8}</> | '
-        '<cyan> {correlation_id} </> | <lvl>{message}</>'
+        '<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</> | <lvl>{level: <8}</> | <cyan>{correlation_id}</> | <lvl>{message}</>'
     )
+    LOG_ACCESS_FILE_LEVEL: str = 'INFO'
+    LOG_ERROR_FILE_LEVEL: str = 'ERROR'
     LOG_ACCESS_FILENAME: str = 'fba_access.log'
     LOG_ERROR_FILENAME: str = 'fba_error.log'
+    LOG_FILE_FORMAT: str = '{time:YYYY-MM-DD HH:mm:ss.SSS} | <lvl>{level: <8}</> | {correlation_id} | <lvl>{message}</>'
 
     # 操作日志
     OPERA_LOG_PATH_EXCLUDE: list[str] = [

backend/core/registrar.py

@@ -20,6 +20,7 @@
 from backend.core.path_conf import STATIC_DIR, UPLOAD_DIR
 from backend.database.db import create_table
 from backend.database.redis import redis_client
+from backend.middleware.access_middleware import AccessMiddleware
 from backend.middleware.jwt_auth_middleware import JwtAuthMiddleware
 from backend.middleware.opera_log_middleware import OperaLogMiddleware
 from backend.middleware.state_middleware import StateMiddleware
@@ -69,8 +70,8 @@ def register_app() -> FastAPI:
     )
 
     # 注册组件
-    register_socket_app(app)
     register_logger()
+    register_socket_app(app)
     register_static_file(app)
     register_middleware(app)
     register_router(app)
@@ -110,29 +111,20 @@ def register_middleware(app: FastAPI) -> None:
     :param app: FastAPI 应用实例
     :return:
     """
-    # Opera log (必须)
+    # Opera log
     app.add_middleware(OperaLogMiddleware)
 
-    # JWT auth (必须)
+    # State
+    app.add_middleware(StateMiddleware)
+
+    # JWT auth
     app.add_middleware(
         AuthenticationMiddleware,
         backend=JwtAuthMiddleware(),
         on_error=JwtAuthMiddleware.auth_exception_handler,
     )
 
-    # Access log
-    if settings.MIDDLEWARE_ACCESS:
-        from backend.middleware.access_middleware import AccessMiddleware
-
-        app.add_middleware(AccessMiddleware)
-
-    # State
-    app.add_middleware(StateMiddleware)
-
-    # Trace ID (必须)
-    app.add_middleware(CorrelationIdMiddleware, validator=False)
-
-    # CORS（必须放在最下面）
+    # CORS
     if settings.MIDDLEWARE_CORS:
         from fastapi.middleware.cors import CORSMiddleware
 
@@ -145,6 +137,12 @@ def register_middleware(app: FastAPI) -> None:
             expose_headers=settings.CORS_EXPOSE_HEADERS,
         )
 
+    # Access log
+    app.add_middleware(AccessMiddleware)
+
+    # Trace ID
+    app.add_middleware(CorrelationIdMiddleware, validator=False)
+
 
 def register_router(app: FastAPI) -> None:
     """

backend/main.py

@@ -8,14 +8,14 @@
 from backend.plugin.tools import get_plugins, install_requirements
 from backend.utils.timezone import timezone
 
-_print_log_style = f'{timezone.to_str(timezone.now(), "%Y-%m-%d %H:%M:%S.%M0")} | fba      |  -  | '
-console.print(Text(f'{_print_log_style}检测插件依赖...', style='bold cyan'))
+_log_prefix = f'{timezone.to_str(timezone.now(), "%Y-%m-%d %H:%M:%S.%M0")} | {"INFO": <8} | - | '
+console.print(Text(f'{_log_prefix}检测插件依赖...', style='bold cyan'))
 
 _plugins = get_plugins()
 
 with Progress(
-    SpinnerColumn(finished_text=f'[bold green]{_print_log_style}插件准备就绪[/]'),
-    TextColumn('[bold green]{task.completed}/{task.total}[/]'),
+    SpinnerColumn(finished_text=f'[bold green]{_log_prefix}插件准备就绪[/]'),
+    TextColumn('{task.completed}/{task.total}', style='bold green'),
     TimeElapsedColumn(),
     console=console,
 ) as progress:
@@ -24,6 +24,6 @@
         install_requirements(plugin)
         progress.advance(task)
 
-console.print(Text(f'{_print_log_style}启动服务...', style='bold magenta'))
+console.print(Text(f'{_log_prefix}启动服务...', style='bold magenta'))
 
 app = register_app()

backend/middleware/access_middleware.py

@@ -1,5 +1,7 @@
 #!/usr/bin/env python3
 # -*- coding: utf-8 -*-
+import time
+
 from fastapi import Request, Response
 from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint
 
@@ -8,7 +10,7 @@
 
 
 class AccessMiddleware(BaseHTTPMiddleware):
-    """请求日志中间件"""
+    """访问日志中间件"""
 
     async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response:
         """
@@ -18,11 +20,25 @@ async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -
         :param call_next: 下一个中间件或路由处理函数
         :return:
         """
+        path = request.url.path if not request.url.query else request.url.path + '/' + request.url.query
+
+        if request.method != 'OPTIONS':
+            log.info(f'--> 请求开始[{path}]')
+            log.info(f'请求方式：[{request.method}]')
+
+        perf_time = time.perf_counter()
+        request.state.perf_time = perf_time
+
         start_time = timezone.now()
+        request.state.start_time = start_time
+
         response = await call_next(request)
-        end_time = timezone.now()
-        log.info(
-            f'{request.client.host: <15} | {request.method: <8} | {response.status_code: <6} | '
-            f'{request.url.path} | {round((end_time - start_time).total_seconds(), 3) * 1000.0}ms'
-        )
+
+        elapsed = (time.perf_counter() - perf_time) * 1000
+
+        if request.method != 'OPTIONS':
+            log.info(f'接口耗时：[{elapsed:.3f}]ms')
+            log.info(f'接口状态：[{response.status_code}]')
+            log.info('<-- 请求结束')
+
         return response