diff --git a/logger.py b/logger.py index d1e50d72..ede5ccf3 100644 --- a/logger.py +++ b/logger.py @@ -3,6 +3,7 @@ import os import sys from datetime import timedelta +from pathlib import Path from loguru import logger @@ -42,6 +43,16 @@ os.makedirs(log_folder, exist_ok=True) logger.remove() +logger.configure( + patcher=lambda r: r["extra"].update( + module_tag=( + f"[MODULE:{Path(r['file'].path).parts[Path(r['file'].path).parts.index('modules') + 1]}]" + if "modules" in Path(r["file"].path).parts + else "" + ) + ) +) + level_mapping = {50: "CRITICAL", 40: "ERROR", 30: "WARNING", 20: "INFO", 10: "DEBUG", 0: "NOTSET"} @@ -78,7 +89,7 @@ def _filter(record): logger.add( sys.stderr, level=BASE_LEVEL, - format="{time:YYYY-MM-DD HH:mm:ss} | {level} | {module}:{function}:{line} | {message}", + format="{time:YYYY-MM-DD HH:mm:ss} | {level} | {module}:{function}:{line} | {extra[module_tag]} {message}", colorize=True, filter=_filter, ) @@ -87,7 +98,7 @@ log_file_path = os.path.join(log_folder, "logging.log") logger.add( log_file_path, level=BASE_LEVEL, - format="{time:YYYY-MM-DD HH:mm:ss} | {level} | {module}:{function}:{line} | {message}", + format="{time:YYYY-MM-DD HH:mm:ss} | {level} | {module}:{function}:{line} | {extra[module_tag]} {message}", rotation=LOG_ROTATION_TIME, retention=timedelta(days=3), filter=_filter, diff --git a/middlewares/probe.py b/middlewares/probe.py index 6eed4352..40f3be7e 100644 --- a/middlewares/probe.py +++ b/middlewares/probe.py @@ -31,7 +31,9 @@ class MiddlewareProbe(BaseMiddleware): now = time.perf_counter() t0 = data.setdefault("_mw_t0", now) prev = data.setdefault("_mw_prev", now) - logger.info(f"[mw:{self.name}] +{(now - prev) * 1000:.2f} ms total {(now - t0) * 1000:.2f} ms") + + data["_mw_prev"] = now + logger.info(f"[mw:{self.name}:enter] +{(now - prev) * 1000:.2f} ms total {(now - t0) * 1000:.2f} ms") downstream_ms = 0.0 @@ -47,7 +49,6 @@ class MiddlewareProbe(BaseMiddleware): return await self.inner(timed_handler, event, data) finally: end = time.perf_counter() - data["_mw_prev"] = end total_ms = (end - start) * 1000 self_ms = total_ms - downstream_ms logger.info(f"[mw:{self.name}:self] {self_ms:.2f} ms") @@ -63,13 +64,16 @@ class TailHandlerProbe(BaseMiddleware): now = time.perf_counter() t0 = data.setdefault("_mw_t0", now) prev = data.setdefault("_mw_prev", now) + + data["_mw_prev"] = now logger.info(f"[mw:{self.name}:enter] +{(now - prev) * 1000:.2f} ms total {(now - t0) * 1000:.2f} ms") + start = time.perf_counter() try: return await handler(event, data) finally: end = time.perf_counter() - data["_mw_prev"] = end handler_ms = (end - start) * 1000 total = (end - t0) * 1000 logger.info(f"[mw:{self.name}] {handler_ms:.2f} ms total {total:.2f} ms") + data["_mw_prev"] = end