Add log file handler for both app loggers and uvicorn loggers

app/log_config.py

@@ -1,85 +1,45 @@
+import logging
 import logging.config
+import logging.handlers
 import os
 from pathlib import Path
 
 from asgi_correlation_id import CorrelationIdFilter
 
-HOME_PATH = os.path.expanduser("~")
-LOG_FILE_PATH = Path(HOME_PATH + "/logs/app.log")
-LOG_FILE_PATH.parent.mkdir(exist_ok=True, parents=True)
+LOG_LEVEL = "INFO"
+
+# time | log level | logger name | trace id | process id | thread id | message
+# %(levelname)8s: max 8 characters for "CRITICAL"
+# ref: https://docs.python.org/3/library/logging.html#logrecord-attributes
+LOG_FORMAT_PATTERN = "%(asctime)s|%(levelname)-8s|%(name)s|%(correlation_id)s|%(process)d|%(thread)d| %(message)s"
 
 TRACE_ID_FILTER = CorrelationIdFilter(name="trace_id_filter", uuid_length=16, default_value="-")
 
-LOG_FORMAT_PATTERN = "%(asctime)s|%(levelname)-8s|%(name)s|%(correlation_id)s|%(process)d|%(thread)d| %(message)s"
+_HOME_PATH = os.path.expanduser("~")
+_LOG_FILE_PATH = Path(_HOME_PATH + "/logs/app.log")
+# create parent directories of log file if these do not exist
+_LOG_FILE_PATH.parent.mkdir(exist_ok=True, parents=True)
 
-LOGGING_CONFIG = {
-    "version": 1,
-    "disable_existing_loggers": False,
-    "filters": {
-        "correlation_id": {
-            "()": "asgi_correlation_id.CorrelationIdFilter",
-            "uuid_length": 16,
-            "default_value": "-",
-        },
-    },
-    "formatters": {
-        "default": {
-            # time | log level | logger name | trace id | process id | thread id | message
-            # %(levelname)8s: max 8 characters for "CRITICAL"
-            # ref: https://docs.python.org/3/library/logging.html#logrecord-attributes
-            "format": LOG_FORMAT_PATTERN,
-        },
-        "access": {
-            # time | log level | logger name | trace id | process id | thread id | message
-            # %(levelname)8s: max 8 characters for "CRITICAL"
-            # ref: https://docs.python.org/3/library/logging.html#logrecord-attributes
-            "format": LOG_FORMAT_PATTERN,
-        }
-    },
-    "handlers": {
-        "console": {
-            "formatter": "default",
-            "class": "logging.StreamHandler",
-            "stream": "ext://sys.stdout",
-        },
-        "file": {
-            "formatter": "default",
-            # ref: https://docs.python.org/3/library/logging.handlers.html#timedrotatingfilehandler
-            "class": "logging.handlers.TimedRotatingFileHandler",
-            "filename": LOG_FILE_PATH,
-            "when": "midnight",
-            "interval": 1,
-            "backupCount": 7,
-            "encoding": "utf-8",
-        },
-    },
-    "loggers": {
-        "uvicorn.error": {
-            "level": "INFO",
-            "handlers": ["console", "file"],
-            "filters": ["correlation_id"],
-            "propagate": "no",
-        },
-        "uvicorn.access": {
-            "level": "INFO",
-            "handlers": ["console", "file"],
-            "filters": ["correlation_id"],
-            "propagate": "no",
-        }
-    },
-    "root": {
-        "level": "DEBUG",
-        "handlers": ["console", "file"],
-        "filters": ["correlation_id"],
-        "propagate": "no",
-    }
+# It will be added to logging config as "file_handler" for uvicorn config initializing
+FILE_HANDLER_CONFIG = {
+    "formatter": "default",
+    # ref: https://docs.python.org/3/library/logging.handlers.html#timedrotatingfilehandler
+    "class": "logging.handlers.TimedRotatingFileHandler",
+    "filename": _LOG_FILE_PATH,
+    "when": "midnight",
+    "backupCount": 7,
+    "encoding": "utf-8",
 }
 
 
-def config_app_logging() -> None:
+def configure_app_logging(file_handler: logging.Handler) -> None:
+    """
+    :param file_handler: Reuse the file handler instance created by uvicorn
+    """
+
     console_handler = logging.StreamHandler()
     console_handler.addFilter(TRACE_ID_FILTER)
     logging.basicConfig(
-        handlers=[console_handler],
-        level="INFO",
+        handlers=[console_handler, file_handler],
+        level=LOG_LEVEL,
         format=LOG_FORMAT_PATTERN)

app/main.py

@@ -1,7 +1,10 @@
 import logging
+import logging.config
+import logging.handlers
+from contextlib import asynccontextmanager
 
 import uvicorn
-from asgi_correlation_id import CorrelationIdMiddleware, correlation_id
+from asgi_correlation_id import correlation_id, CorrelationIdMiddleware
 from fastapi import FastAPI, HTTPException, Request
 from fastapi.exception_handlers import http_exception_handler
 from pydantic import BaseModel
@@ -10,18 +13,39 @@
 
 import log_config
 
-app = FastAPI()
-app.add_middleware(CorrelationIdMiddleware)
-
-log_config.config_app_logging()
-log = logging.getLogger(__name__)
+log: logging.Logger
 
 
 class Item(BaseModel):
     name: str
     price: float
 
 
+FILE_HANDLER_NAME = "file_handler"
+
+
+def find_log_file_handler() -> logging.Handler:
+    # ref: https://stackoverflow.com/a/55400327/11397457
+    l = logging.Logger.manager.loggerDict["uvicorn"]
+    for h in l.handlers:
+        if isinstance(h, logging.handlers.TimedRotatingFileHandler):
+            return h
+    raise Exception("Can not found file handler.")
+
+
+@asynccontextmanager
+async def lifespan(app: FastAPI):
+    # We must configure app logging after uvicorn started, thus the file handler should exists for reusing.
+    log_config.configure_app_logging(find_log_file_handler())
+    global log
+    log = logging.getLogger(__name__)
+    yield
+
+
+app = FastAPI(lifespan=lifespan)
+app.add_middleware(CorrelationIdMiddleware)
+
+
 @app.get("/")
 def read_root():
     log.info("info log")
@@ -54,13 +78,19 @@ async def unhandled_exception_handler(request: Request, exc: Exception) -> Respo
         ))
 
 
-def config_uvicorn_logging():
-    LOGGING_CONFIG["handlers"]["access"]["filters"] = [log_config.TRACE_ID_FILTER]
-    LOGGING_CONFIG["handlers"]["default"]["filters"] = [log_config.TRACE_ID_FILTER]
-    LOGGING_CONFIG["formatters"]["access"]["fmt"] = log_config.LOG_FORMAT_PATTERN
-    LOGGING_CONFIG["formatters"]["default"]["fmt"] = log_config.LOG_FORMAT_PATTERN
+def configure_uvicorn_logging():
+    extra_filters = [log_config.TRACE_ID_FILTER]
+    for handler in LOGGING_CONFIG["handlers"].values():
+        handler["filters"] = handler["filters"] + extra_filters if "filters" in handler else extra_filters
+    for formatter in LOGGING_CONFIG["formatters"].values():
+        formatter["fmt"] = log_config.LOG_FORMAT_PATTERN
+
+    LOGGING_CONFIG["handlers"][FILE_HANDLER_NAME] = log_config.FILE_HANDLER_CONFIG
+    for logger in LOGGING_CONFIG["loggers"].values():
+        if "handlers" in logger:
+            logger["handlers"] += [FILE_HANDLER_NAME]
 
 
 if __name__ == "__main__":
-    config_uvicorn_logging()
+    configure_uvicorn_logging()
     uvicorn.run("main:app", port=8000, reload=True)