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