probe and logging changes

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="<green>{time:YYYY-MM-DD HH:mm:ss}</green> | <level>{level}</level> | <cyan>{module}:{function}:{line}</cyan> | <level>{message}</level>",
+    format="<green>{time:YYYY-MM-DD HH:mm:ss}</green> | <level>{level}</level> | <cyan>{module}:{function}:{line}</cyan> | <magenta>{extra[module_tag]}</magenta> <level>{message}</level>",
     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,

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