logging enhancements

.gitignore

@@ -6,3 +6,4 @@ uv.lock
 
 __pycache__/
 **/dist/
+**/*.log

app/config/settings.py

@@ -6,6 +6,11 @@ from pydantic import BaseModel
 from pydantic_settings import BaseSettings, SettingsConfigDict
 
 
+class LoggingConfig(BaseModel):
+  level: str = "INFO"
+  path: Path = Path("logs/karl.log")
+
+
 class AppConfig(BaseModel):
   host: str = "127.0.0.1"
   port: int = 8081
@@ -26,6 +31,7 @@ class KeePassConfig(BaseModel):
 
 class Settings(BaseSettings):
   model_config = SettingsConfigDict(env_prefix="KARL_", env_nested_delimiter="__")
+  logging: LoggingConfig = LoggingConfig()
   app: AppConfig = AppConfig()
   git: GitConfig = GitConfig()
   kp: KeePassConfig = KeePassConfig()

app/main.py

@@ -4,8 +4,7 @@ from fastapi import FastAPI
 from injectable import load_injection_container
 
 from app.config import get_settings
-from app.core.core import WebhookProcessor
+from app.util.logging import HandlerFactory
-from app.util.logging import LoggingHandler, ExternalLoggingHandler
 
 
 class KarlApplication:
@@ -13,6 +12,7 @@ class KarlApplication:
   def __init__(self) -> None:
     self._set_logging()
     _app = FastAPI(title="Karl", version="0.1.0")
+    self._set_middlewares(_app)
     self._set_routes(_app)
     self._set_events(_app)
     self._init_services()
@@ -23,7 +23,12 @@ class KarlApplication:
     await self._app.__call__(scope, receive, send)
 
   def _set_logging(self):
-    logging.basicConfig(level=logging.INFO, handlers=[LoggingHandler()])
+    settings = get_settings()
+    logging.addLevelName(5, "TRACE")
+    logging.Logger.trace = lambda s, msg, *args, **kwargs: s.log(5, msg, *args, **kwargs)
+    logging.basicConfig(level=settings.logging.level,
+                        handlers=HandlerFactory.create(HandlerFactory.Target.ALL, handler_prefix='karl.',
+                                                       file_path=settings.logging.path))
 
     loggers = (
       "uvicorn",
@@ -33,12 +38,16 @@ class KarlApplication:
       "asyncio",
       "starlette",
     )
-    external_handler = ExternalLoggingHandler()
+    external_handlers = HandlerFactory.create(HandlerFactory.Target.ALL, file_path=settings.logging.path)
     for logger_name in loggers:
       logging_logger = logging.getLogger(logger_name)
-      logging_logger.handlers = [external_handler]
+      logging_logger.handlers = external_handlers
       logging_logger.propagate = False
 
+  def _set_middlewares(self, app: FastAPI):
+    from app.web.middlewares import LoggingMiddleware
+    app.add_middleware(LoggingMiddleware)
+
   def _set_routes(self, app: FastAPI):
     from app.core.router import router as core_router
     app.include_router(core_router)
@@ -52,11 +61,9 @@ class KarlApplication:
   def _init_services(self):
     logger = logging.getLogger(__name__)
     load_injection_container()
-    webhook_service = WebhookProcessor()
-    logger.info(webhook_service.health)
 
 
-def app():
+def run():
   return KarlApplication()
 
 
@@ -65,7 +72,7 @@ if __name__ == "__main__":
 
   settings = get_settings()
   uvicorn.run(
-    "app.main:app",
+    "app.main:run",
     factory=True,
     host=settings.app.host,
     port=settings.app.port,

app/util/logging.py

@@ -1,4 +1,8 @@
-from logging import Formatter, StreamHandler
+from enum import Enum, auto
+from logging import Formatter, StreamHandler, Handler
+from logging.handlers import TimedRotatingFileHandler
+from pathlib import Path
+from typing import List
 
 
 class NamingCache:
@@ -37,7 +41,7 @@ class ApplicationFormatter(Formatter):
     from datetime import datetime
     timestamp = datetime.fromtimestamp(record.created).isoformat(sep=' ', timespec='milliseconds')
     level = record.levelname.replace('WARNING', 'WARN').rjust(5)
-    thread_name = record.threadName.replace(' (', '#').replace(')', '').rjust(16)[-16:] # TODO: NamingCache?
+    thread_name = record.threadName.replace(' (', '#').replace(')', '').rjust(16)[-16:]  # TODO: NamingCache?
     logger_name = self._logger_names[f"{self._handler_prefix}{record.name}"]
     message = record.getMessage()
     formatted = f"{timestamp} {level} [{thread_name}] {logger_name} : {message}"
@@ -48,12 +52,35 @@ class ApplicationFormatter(Formatter):
     return formatted
 
 
-class LoggingHandler(StreamHandler):
+class HandlerFactory:
-  def __init__(self):
+  class Target(Enum):
-    super().__init__()
+    CONSOLE = auto()
-    self.setFormatter(ApplicationFormatter(handler_prefix='karl.'))
+    FILE = auto()
+    ALL = auto()
 
-class ExternalLoggingHandler(StreamHandler):
+  @staticmethod
-  def __init__(self):
+  def create(target: Target, handler_prefix: str = '', file_path: Path = None) -> List[Handler]:
-    super().__init__()
+    def console_handler(prefix: str = ''):
-    self.setFormatter(ApplicationFormatter())
+      handler = StreamHandler()
+      handler.setFormatter(ApplicationFormatter(prefix))
+      handler.setLevel('INFO')
+      return handler
+
+    def file_handler(prefix: str = ''):
+      handler = TimedRotatingFileHandler(file_path, when='midnight', backupCount=30)
+      handler.setFormatter(ApplicationFormatter(prefix))
+      handler.setLevel('TRACE')
+      return handler
+
+    handlers = []
+    match target:
+      case HandlerFactory.Target.CONSOLE:
+        handlers.append(console_handler(handler_prefix))
+      case HandlerFactory.Target.FILE:
+        handlers.append(file_handler(handler_prefix))
+      case HandlerFactory.Target.ALL:
+        handlers.append(file_handler(handler_prefix))
+        handlers.append(console_handler(handler_prefix))
+      case _:
+        raise ValueError(f"Unknown target: {target}")
+    return handlers

app/web/middlewares.py

@@ -0,0 +1,24 @@
+import logging
+
+from starlette.middleware.base import BaseHTTPMiddleware
+from starlette.requests import Request
+
+logger = logging.getLogger(__name__)
+
+
+class LoggingMiddleware(BaseHTTPMiddleware):
+  async def dispatch(self, request: Request, call_next):
+    client = f"{request.client.host}:{request.client.port}"
+    match request.method:
+      case "POST" | "PUT" | "DELETE" if request.headers.get("Content-Type") == "application/json":
+        body = await request.body()
+        logger.trace(f"Request from {client}: {body.decode()}")
+      case "GET":
+        logger.trace(f"Request from {client}")
+      case _:
+        logger.trace(f"Request from {client} (content-type:{request.headers.get("Content-Type")})")
+
+    response = await call_next(request)
+    logger.trace(f"Respone: {response.status_code} {type(response)}")
+
+    return response

config/config.yaml

@@ -1,3 +1,6 @@
+logging:
+    level: "TRACE"
+    path: "logs/karl.log"
 app:
     host: "127.0.0.1"
     port: 8081

run.sh

@@ -1 +1 @@
-uvicorn app.main:app --factory --reload
+uvicorn app.main:run --factory --reload