feat(log): add logger

This commit is contained in:
MingxuanGame
2025-07-28 10:38:40 +00:00
parent e369944d87
commit 1be3388524
13 changed files with 212 additions and 174 deletions

View File

@@ -10,6 +10,7 @@ from app.database import (
OAuthToken,
User as DBUser,
)
from app.log import logger
import bcrypt
from jose import JWTError, jwt
@@ -47,8 +48,8 @@ def verify_password_legacy(plain_password: str, bcrypt_hash: str) -> bool:
bcrypt_cache[bcrypt_hash] = pw_md5
return is_valid
except Exception as e:
print(f"Password verification error: {e}")
except Exception:
logger.exception("Password verification error")
return False
@@ -104,8 +105,8 @@ async def authenticate_user_legacy(
# 缓存验证结果
bcrypt_cache[user.pw_bcrypt] = pw_md5.encode()
return user
except Exception as e:
print(f"Authentication error for user {name}: {e}")
except Exception:
logger.exception(f"Authentication error for user {name}")
return None

View File

@@ -44,5 +44,8 @@ class Settings:
"FETCHER_CALLBACK_URL", "http://localhost:8000/fetcher/callback"
)
# 日志设置
LOG_LEVEL: str = os.getenv("LOG_LEVEL", "INFO").upper()
settings = Settings()

View File

@@ -3,6 +3,7 @@ from __future__ import annotations
from app.config import settings
from app.dependencies.database import get_redis
from app.fetcher import Fetcher
from app.log import logger
fetcher: Fetcher | None = None
@@ -25,5 +26,7 @@ def get_fetcher() -> Fetcher:
if refresh_token:
fetcher.refresh_token = str(refresh_token)
if not fetcher.access_token or not fetcher.refresh_token:
print("Login to initialize fetcher:", fetcher.authorize_url)
logger.opt(colors=True).info(
f"Login to initialize fetcher: <y>{fetcher.authorize_url}</y>"
)
return fetcher

View File

@@ -1,6 +1,7 @@
from __future__ import annotations
from app.database.beatmap import BeatmapResp
from app.log import logger
from ._base import BaseFetcher
@@ -17,6 +18,9 @@ class BeatmapFetcher(BaseFetcher):
params = {"checksum": beatmap_checksum}
else:
raise ValueError("Either beatmap_id or beatmap_checksum must be provided.")
logger.opt(colors=True).debug(
f"<blue>[BeatmapFetcher]</blue> get_beatmap: <y>{params}</y>"
)
async with AsyncClient() as client:
response = await client.get(
"https://osu.ppy.sh/api/v2/beatmaps/lookup",

View File

@@ -1,6 +1,7 @@
from __future__ import annotations
from app.database.beatmapset import BeatmapsetResp
from app.log import logger
from ._base import BaseFetcher
@@ -9,6 +10,9 @@ from httpx import AsyncClient
class BeatmapsetFetcher(BaseFetcher):
async def get_beatmapset(self, beatmap_set_id: int) -> BeatmapsetResp:
logger.opt(colors=True).debug(
f"<blue>[BeatmapsetFetcher]</blue> get_beatmapset: <y>{beatmap_set_id}</y>"
)
async with AsyncClient() as client:
response = await client.get(
f"https://osu.ppy.sh/api/v2/beatmapsets/{beatmap_set_id}",

View File

@@ -3,10 +3,14 @@ from __future__ import annotations
from ._base import BaseFetcher
from httpx import AsyncClient
from loguru import logger
class OsuDotDirectFetcher(BaseFetcher):
async def get_beatmap_raw(self, beatmap_id: int) -> str:
logger.opt(colors=True).debug(
f"<blue>[OsuDotDirectFetcher]</blue> get_beatmap_raw: <y>{beatmap_id}</y>"
)
async with AsyncClient() as client:
response = await client.get(
f"https://osu.direct/api/osu/{beatmap_id}/raw",

138
app/log.py Normal file
View File

@@ -0,0 +1,138 @@
from __future__ import annotations
import http
import inspect
import logging
import re
from sys import stdout
from typing import TYPE_CHECKING
from app.config import settings
import loguru
if TYPE_CHECKING:
from loguru import Logger
logger: "Logger" = loguru.logger
class InterceptHandler(logging.Handler):
def emit(self, record: logging.LogRecord) -> None:
# Get corresponding Loguru level if it exists.
try:
level: str | int = logger.level(record.levelname).name
except ValueError:
level = record.levelno
# Find caller from where originated the logged message.
frame, depth = inspect.currentframe(), 0
while frame:
filename = frame.f_code.co_filename
is_logging = filename == logging.__file__
is_frozen = "importlib" in filename and "_bootstrap" in filename
if depth > 0 and not (is_logging or is_frozen):
break
frame = frame.f_back
depth += 1
message = record.getMessage()
if record.name == "uvicorn.access":
message = self._format_uvicorn_access_log(message)
elif record.name == "uvicorn.error":
message = self._format_uvicorn_error_log(message)
logger.opt(depth=depth, exception=record.exc_info, colors=True).log(
level, message
)
def _format_uvicorn_error_log(self, message: str) -> str:
websocket_pattern = (
r'(\d+\.\d+\.\d+\.\d+:\d+)\s*-\s*"WebSocket\s+([^"]+)"\s+([\w\[\]]+)'
)
websocket_match = re.search(websocket_pattern, message)
if websocket_match:
ip, path, status = websocket_match.groups()
colored_ip = f"<cyan>{ip}</cyan>"
status_colors = {
"[accepted]": "<green>[accepted]</green>",
"403": "<red>403 [rejected]</red>",
}
colored_status = status_colors.get(
status.lower(), f"<white>{status}</white>"
)
return (
f'{colored_ip} - "<bold><magenta>WebSocket</magenta> '
f'{path}</bold>" '
f"{colored_status}"
)
else:
return message
def _format_uvicorn_access_log(self, message: str) -> str:
http_pattern = r'(\d+\.\d+\.\d+\.\d+:\d+)\s*-\s*"(\w+)\s+([^"]+)"\s+(\d+)'
http_match = re.search(http_pattern, message)
if http_match:
ip, method, path, status_code = http_match.groups()
try:
status_phrase = http.HTTPStatus(int(status_code)).phrase
except ValueError:
status_phrase = ""
colored_ip = f"<cyan>{ip}</cyan>"
method_colors = {
"GET": "<green>GET</green>",
"POST": "<blue>POST</blue>",
"PUT": "<yellow>PUT</yellow>",
"DELETE": "<red>DELETE</red>",
"PATCH": "<magenta>PATCH</magenta>",
"OPTIONS": "<white>OPTIONS</white>",
"HEAD": "<white>HEAD</white>",
}
colored_method = method_colors.get(method, f"<white>{method}</white>")
status = int(status_code)
status_color = "white"
if 200 <= status < 300:
status_color = "green"
elif 300 <= status < 400:
status_color = "yellow"
elif 400 <= status < 500:
status_color = "red"
elif 500 <= status < 600:
status_color = "red"
return (
f'{colored_ip} - "<bold>{colored_method} '
f'{path}</bold>" '
f"<{status_color}>{status_code} {status_phrase}</{status_color}>"
)
return message
logger.remove()
logger.add(
stdout,
colorize=True,
format=(
"<green>{time:YYYY-MM-DD HH:mm:ss}</green> [<level>{level}</level>] | {message}"
),
level=settings.LOG_LEVEL,
diagnose=settings.DEBUG,
)
logging.basicConfig(handlers=[InterceptHandler()], level=settings.LOG_LEVEL, force=True)
uvicorn_loggers = [
"uvicorn",
"uvicorn.error",
"uvicorn.access",
"fastapi",
]
for logger_name in uvicorn_loggers:
uvicorn_logger = logging.getLogger(logger_name)
uvicorn_logger.handlers = [InterceptHandler()]
uvicorn_logger.propagate = False

View File

@@ -3,10 +3,10 @@ from __future__ import annotations
from abc import abstractmethod
import asyncio
import time
import traceback
from typing import Any
from app.config import settings
from app.log import logger
from app.models.signalr import UserState
from app.signalr.exception import InvokeException
from app.signalr.packet import (
@@ -79,7 +79,7 @@ class Client:
except WebSocketDisconnect:
break
except Exception as e:
print(f"Error in ping task for {self.connection_id}: {e}")
logger.error(f"Error in ping task for {self.connection_id}: {e}")
break
@@ -205,22 +205,24 @@ class Hub[TState: UserState]:
self.tasks.add(task)
task.add_done_callback(self.tasks.discard)
except WebSocketDisconnect as e:
print(f"Client {client.connection_id} disconnected: {e.code}, {e.reason}")
logger.info(
f"Client {client.connection_id} disconnected: {e.code}, {e.reason}"
)
except RuntimeError as e:
if "disconnect message" in str(e):
print(f"Client {client.connection_id} closed the connection.")
logger.info(f"Client {client.connection_id} closed the connection.")
else:
traceback.print_exc()
print(f"RuntimeError in client {client.connection_id}: {e}")
logger.exception(f"RuntimeError in client {client.connection_id}: {e}")
except CloseConnection as e:
if not e.from_client:
await client.send_packet(
ClosePacket(error=e.message, allow_reconnect=e.allow_reconnect)
)
print(f"Client {client.connection_id} closed the connection: {e.message}")
except Exception as e:
traceback.print_exc()
print(f"Error in client {client.connection_id}: {e}")
logger.info(
f"Client {client.connection_id} closed the connection: {e.message}"
)
except Exception:
logger.exception(f"Error in client {client.connection_id}")
await self.remove_client(client)
@@ -236,7 +238,10 @@ class Hub[TState: UserState]:
except InvokeException as e:
error = e.message
except Exception as e:
traceback.print_exc()
logger.exception(
f"Error invoking method {packet.target} for "
f"client {client.connection_id}"
)
error = str(e)
if packet.invocation_id is not None:
await client.send_packet(

View File

@@ -84,7 +84,6 @@ class MetadataHub(Hub[MetadataClientState]):
if (
friend_state := self.state.get(friend_id)
) and friend_state.pushable:
print("Pushed")
tasks.append(
self.broadcast_group_call(
self.friend_presence_watchers_group(friend_id),

View File

@@ -319,7 +319,6 @@ class SpectatorHub(Hub[StoreClientState]):
)
async def StartWatchingUser(self, client: Client, target_id: int) -> None:
print(f"StartWatchingUser -> {client.connection_id} {target_id}")
user_id = int(client.connection_id)
target_store = self.get_or_create_state(client)
if target_store.state:
@@ -347,7 +346,6 @@ class SpectatorHub(Hub[StoreClientState]):
)
async def EndWatchingUser(self, client: Client, target_id: int) -> None:
print(f"EndWatchingUser -> {client.connection_id} {target_id}")
user_id = int(client.connection_id)
self.remove_from_group(client, self.group_id(target_id))
store = self.state.get(user_id)