feat: JSON logging (#97)

* feat: JSON logging

config.json

@@ -14,5 +14,10 @@
     "identities": {
       "use_cache": false
     }
+  },
+  "logging": {
+    "log_level": "INFO",
+    "log_format": "generic",
+    "enable_access_log": false
   }
-}
+}

requirements.in

@@ -5,5 +5,6 @@ flagsmith-flag-engine
 python-decouple
 python-dotenv
 pydantic
+structlog
 orjson
 httpx

requirements.txt

@@ -1,5 +1,5 @@
 #
-# This file is autogenerated by pip-compile with Python 3.12
+# This file is autogenerated by pip-compile with Python 3.10
 # by the following command:
 #
 #    pip-compile requirements.in
@@ -14,6 +14,8 @@ certifi==2023.7.22
     #   httpx
 click==8.1.7
     # via uvicorn
+exceptiongroup==1.2.0
+    # via anyio
 fastapi==0.109.1
     # via -r requirements.in
 flagsmith-flag-engine==4.1.0
@@ -57,10 +59,13 @@ sniffio==1.3.0
     #   httpx
 starlette==0.35.0
     # via fastapi
+structlog==24.1.0
+    # via -r requirements.in
 typing-extensions==4.8.0
     # via
     #   fastapi
     #   pydantic
     #   pydantic-collections
+    #   uvicorn
 uvicorn==0.23.2
     # via -r requirements.in

src/cache.py

@@ -1,9 +1,6 @@
-import logging
 import typing
 from abc import ABC
 
-logger = logging.getLogger(__name__)
-
 
 class BaseEnvironmentsCache(ABC):
     def __init__(self, *args, **kwargs):

src/environments.py

@@ -1,9 +1,9 @@
-import logging
 import typing
 from datetime import datetime
 from functools import lru_cache
 
 import httpx
+import structlog
 from flag_engine.engine import (
     get_environment_feature_state,
     get_environment_feature_states,
@@ -24,7 +24,7 @@
 from src.models import IdentityWithTraits
 from src.settings import Settings
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(__name__)
 
 
 class EnvironmentService:
@@ -64,7 +64,7 @@ async def refresh_environment_caches(self):
                     await self._clear_endpoint_caches()
             except (httpx.HTTPError, orjson.JSONDecodeError):
                 logger.exception(
-                    f"Failed to fetch document for {key_pair.client_side_key}"
+                    "error_fetching_document", client_side_key=key_pair.client_side_key
                 )
                 received_error = True
         if not received_error:

src/logging.py

@@ -0,0 +1,95 @@
+import logging
+import logging.handlers
+
+import structlog
+
+from .settings import LogFormat, LoggingSettings
+
+
+def _extract_gunicorn_access_log_event(
+    record: logging.LogRecord,
+    name: str,
+    event_dict: structlog.types.EventDict,
+) -> structlog.types.EventDict:
+    # Extract logger args from Gunicorn access log entry
+    # and map them to Flagsmith's JSON log format.
+    # Argument positions taken from
+    # https://github.com/encode/uvicorn/blob/a2219eb2ed2bbda4143a0fb18c4b0578881b1ae8/uvicorn/logging.py#L99-L105
+    if event_dict.get("logger") == "uvicorn.access":
+        remote_ip, method, path, _, status = event_dict["positional_args"]
+        event_dict["remote_ip"] = remote_ip
+        event_dict["method"] = method
+        event_dict["path"] = path
+        event_dict["status"] = status
+    return event_dict
+
+
+def setup_logging(settings: LoggingSettings) -> None:
+    """
+    Configure stdlib logger to use structlog processors and formatters so that
+    uvicorn and application logs are consistent.
+    """
+    is_generic_format = settings.log_format is LogFormat.GENERIC
+
+    processors: list[structlog.types.Processor] = [
+        structlog.contextvars.merge_contextvars,
+        structlog.stdlib.add_logger_name,
+        structlog.stdlib.add_log_level,
+        _extract_gunicorn_access_log_event,
+        structlog.stdlib.PositionalArgumentsFormatter(),
+        structlog.stdlib.ExtraAdder(),
+        structlog.processors.StackInfoRenderer(),
+        structlog.processors.TimeStamper(fmt="iso"),
+    ]
+
+    if is_generic_format:
+        # For `generic` format, set `exc_info` on the log event if the log method is
+        # `exception` and `exc_info` is not already set.
+        #
+        # Rendering of `exc_info` is handled by ConsoleRenderer.
+        processors.append(structlog.dev.set_exc_info)
+    else:
+        # For `json` format `exc_info` must be set explicitly when
+        # needed, and is translated into a formatted `exception` field.
+        processors.append(structlog.processors.format_exc_info)
+
+    processors.append(structlog.processors.EventRenamer(settings.log_event_field_name))
+
+    structlog.configure(
+        processors=processors
+        + [structlog.stdlib.ProcessorFormatter.wrap_for_formatter],
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        cache_logger_on_first_use=True,
+    )
+
+    if is_generic_format:
+        log_renderer = structlog.dev.ConsoleRenderer(
+            event_key=settings.log_event_field_name
+        )
+    else:
+        log_renderer = structlog.processors.JSONRenderer()
+
+    formatter = structlog.stdlib.ProcessorFormatter(
+        use_get_message=False,
+        pass_foreign_args=True,
+        foreign_pre_chain=processors,
+        processors=[
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            log_renderer,
+        ],
+    )
+
+    handler = logging.StreamHandler()
+    handler.setFormatter(formatter)
+
+    root = logging.getLogger()
+    root.addHandler(handler)
+    root.setLevel(settings.log_level.to_logging_log_level())
+
+    # Propagate uvicorn logs instead of letting uvicorn configure the format
+    for name in ["uvicorn", "uvicorn.error"]:
+        logging.getLogger(name).handlers.clear()
+        logging.getLogger(name).propagate = True
+
+    logging.getLogger("uvicorn.access").handlers.clear()
+    logging.getLogger("uvicorn.access").propagate = settings.enable_access_log

src/main.py

@@ -1,8 +1,8 @@
-import logging
 from contextlib import suppress
 from datetime import datetime
 
 import httpx
+import structlog
 from fastapi import FastAPI, Header
 from fastapi.middleware.cors import CORSMiddleware
 from fastapi.middleware.gzip import GZipMiddleware
@@ -13,16 +13,18 @@
 from .cache import LocalMemEnvironmentsCache
 from .environments import EnvironmentService
 from .exceptions import FeatureNotFoundError, FlagsmithUnknownKeyError
+from .logging import setup_logging
 from .models import IdentityWithTraits
 from .settings import Settings
 
-app = FastAPI()
 settings = Settings()
+setup_logging(settings.logging)
 environment_service = EnvironmentService(
     LocalMemEnvironmentsCache(),
     httpx.AsyncClient(timeout=settings.api_poll_timeout),
     settings,
 )
+app = FastAPI()
 
 
 @app.exception_handler(FlagsmithUnknownKeyError)
@@ -77,7 +79,7 @@ async def identity(
 @repeat_every(
     seconds=settings.api_poll_frequency,
     raise_exceptions=True,
-    logger=logging.getLogger(__name__),
+    logger=structlog.get_logger(__name__),
 )
 async def refresh_cache():
     await environment_service.refresh_environment_caches()

src/settings.py

@@ -1,11 +1,30 @@
 import json
+import logging
+from enum import Enum
 from pathlib import Path
 from typing import Any, Dict, List, Tuple
 
 from pydantic import BaseModel, BaseSettings, HttpUrl
 from pydantic.env_settings import SettingsSourceCallable
 
 
+class LogFormat(Enum):
+    GENERIC = "generic"
+    JSON = "json"
+
+
+class LogLevel(Enum):
+    CRITICAL = "CRITICAL"
+    ERROR = "ERROR"
+    WARNING = "WARNING"
+    INFO = "INFO"
+    DEBUG = "DEBUG"
+    NOTSET = "NOTSET"
+
+    def to_logging_log_level(self) -> int:
+        return getattr(logging, self.value)
+
+
 def json_config_settings_source(settings: BaseSettings) -> Dict[str, Any]:
     """
     A simple settings source that loads variables from a JSON file
@@ -31,13 +50,21 @@ class EndpointCachesSettings(BaseModel):
     identities: EndpointCacheSettings = EndpointCacheSettings(use_cache=False)
 
 
+class LoggingSettings(BaseModel):
+    enable_access_log: bool = False
+    log_format: LogFormat = LogFormat.GENERIC
+    log_level: LogLevel = LogLevel.INFO
+    log_event_field_name: str = "message"
+
+
 class Settings(BaseSettings):
     environment_key_pairs: List[EnvironmentKeyPair]
     api_url: HttpUrl = "https://edge.api.flagsmith.com/api/v1"
     api_poll_frequency: int = 10  # seconds
     api_poll_timeout: int = 5  # seconds
     endpoint_caches: EndpointCachesSettings | None = None
     allow_origins: List[str] = ["*"]
+    logging: LoggingSettings = LoggingSettings()
 
     class Config:
         @classmethod