feat: JSON logging for Gunicorn

api/Makefile

@@ -83,7 +83,7 @@ django-collect-static:
 
 .PHONY: serve
 serve:
-	poetry run gunicorn --bind 0.0.0.0:8000 app.wsgi --reload
+	poetry run gunicorn --config scripts/gunicorn.conf.py --bind 0.0.0.0:8000 app.wsgi --reload
 
 .PHONY: generate-ld-client-types
 generate-ld-client-types:

api/app/settings/common.py

@@ -535,13 +535,13 @@
 CHARGEBEE_SITE = env("CHARGEBEE_SITE", default=None)
 
 # Logging configuration
+LOG_FORMAT = env.str("LOG_FORMAT", default="generic")
+LOG_LEVEL = env.str("LOG_LEVEL", default="WARNING")
 LOGGING_CONFIGURATION_FILE = env.str("LOGGING_CONFIGURATION_FILE", default=None)
 if LOGGING_CONFIGURATION_FILE:
     with open(LOGGING_CONFIGURATION_FILE, "r") as f:
         LOGGING = json.loads(f.read())
 else:
-    LOG_FORMAT = env.str("LOG_FORMAT", default="generic")
-    LOG_LEVEL = env.str("LOG_LEVEL", default="WARNING")
     LOGGING = {
         "version": 1,
         "disable_existing_loggers": False,

api/scripts/gunicorn.conf.py

@@ -0,0 +1,16 @@
+import os
+
+accesslog = os.getenv("ACCESS_LOG_LOCATION", "-")
+access_log_format = os.getenv("ACCESS_LOG_FORMAT") or (
+    r'%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" '
+    r'"%(a)s" %({origin}i)s %({access-control-allow-origin}o)s'
+)
+keep_alive = os.getenv("GUNICORN_KEEP_ALIVE", 2)
+logger_class = "util.logging.GunicornJsonLogger"
+threads = os.getenv("GUNICORN_THREADS", 2)
+timeout = os.getenv("GUNICORN_TIMEOUT", 30)
+workers = os.getenv("GUNICORN_WORKERS", 3)
+
+if _statsd_host := os.getenv("STATSD_HOST"):
+    statsd_host = f'{_statsd_host}:{os.getenv("STATSD_PORT")}'
+    statsd_prefix = os.getenv("STATSD_PREFIX")

api/scripts/run-docker.sh

@@ -17,15 +17,8 @@ function serve() {
     python manage.py waitfordb
 
     exec gunicorn --bind 0.0.0.0:8000 \
-             --worker-tmp-dir /dev/shm \
-             --timeout ${GUNICORN_TIMEOUT:-30} \
-             --workers ${GUNICORN_WORKERS:-3} \
-             --threads ${GUNICORN_THREADS:-2} \
-             --access-logfile $ACCESS_LOG_LOCATION \
-             --access-logformat '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %({origin}i)s %({access-control-allow-origin}o)s' \
-             --keep-alive ${GUNICORN_KEEP_ALIVE:-2} \
-             ${STATSD_HOST:+--statsd-host $STATSD_HOST:$STATSD_PORT} \
-             ${STATSD_HOST:+--statsd-prefix $STATSD_PREFIX} \
+             --worker-tmp-dir=/dev/shm \
+             --config=/app/scripts/gunicorn.conf.py \
              app.wsgi
 }
 function run_task_processor() {

api/tests/unit/environments/dynamodb/wrappers/test_unit_dynamodb_environment_v2_wrapper.py

@@ -65,9 +65,9 @@ def test_environment_v2_wrapper__get_identity_overrides_by_environment_id__last_
 ) -> None:
     # Given
     wrapper = DynamoEnvironmentV2Wrapper()
-    mocker.patch.object(
-        wrapper, "get_table"
-    ).return_value = table_mock = mocker.MagicMock(spec=flagsmith_environments_v2_table)
+    mocker.patch.object(wrapper, "get_table").return_value = table_mock = (
+        mocker.MagicMock(spec=flagsmith_environments_v2_table)
+    )
 
     last_evaluated_key = "next_page_key"
     override_document = {"test": "document"}

api/tests/unit/util/test_logging.py

@@ -4,16 +4,16 @@
 from util.logging import JsonFormatter
 
 
-def test_json_formatter():
+def test_json_formatter__outputs_expected():
     json_formatter = JsonFormatter()
 
     log_record = logging.LogRecord(
         name="test_logger",
         level=logging.INFO,
         pathname="test.py",
         lineno=42,
-        msg="This is a test.",
-        args=(),
+        msg="This is a test message with args: %s and %s",
+        args=("arg1", "arg2"),
         exc_info=None,
     )
     formatted_message = json_formatter.format(log_record)
@@ -25,44 +25,4 @@ def test_json_formatter():
     assert "logger_name" in json_message
     assert "process_id" in json_message
     assert "thread_name" in json_message
-
-
-def test_json_formatter_with_old_style_placeholders():
-    json_formatter = JsonFormatter()
-
-    log_record = logging.LogRecord(
-        name="test_logger",
-        level=logging.INFO,
-        pathname="example.py",
-        lineno=42,
-        msg="This is a test with old-style placeholders: %s and %s",
-        args=("arg1", "arg2"),
-        exc_info=None,
-    )
-
-    formatted_message = json_formatter.format(log_record)
-    parsed_json = json.loads(formatted_message)
-    assert (
-        parsed_json["message"]
-        == "This is a test with old-style placeholders: arg1 and arg2"
-    )
-
-
-def test_json_formatter_arguments_with_new_style_placeholders():
-    json_formatter = JsonFormatter()
-    log_record = logging.LogRecord(
-        name="test_logger",
-        level=logging.INFO,
-        pathname="example.py",
-        lineno=42,
-        msg="This is a test with new-style placeholders: {} and {}",
-        args=("arg1", "arg2"),
-        exc_info=None,
-    )
-
-    formatted_message = json_formatter.format(log_record)
-    parsed_json = json.loads(formatted_message)
-    assert (
-        parsed_json["message"]
-        == "This is a test with new-style placeholders: arg1 and arg2"
-    )
+    assert json_message["message"] == "This is a test message with args: arg1 and arg2"

api/util/logging.py

@@ -1,27 +1,73 @@
 import json
 import logging
+import sys
+from datetime import datetime
+from typing import Any
+
+from django.conf import settings
+from gunicorn.config import Config
+from gunicorn.glogging import Logger as GunicornLogger
 
 
 class JsonFormatter(logging.Formatter):
     """Custom formatter for json logs."""
 
-    def format(self, record):
+    def get_json_record(self, record: logging.LogRecord) -> dict[str, Any]:
+        formatted_message = record.getMessage()
+        return {
+            "levelname": record.levelname,
+            "message": formatted_message,
+            "timestamp": self.formatTime(record, self.datefmt),
+            "logger_name": record.name,
+            "process_id": record.process,
+            "thread_name": record.threadName,
+        }
+
+    def format(self, record: logging.LogRecord) -> str:
         """
         %s is replaced with {} because legacy string formatting
         conventions in django-axes module prevent correct
         interpolation of arguments when using this formatter.
         """
         try:
-            log_message = record.msg.replace("%s", "{}")
-            formatted_message = log_message.format(*record.args)
-            log_record = {
-                "levelname": record.levelname,
-                "message": formatted_message,
-                "timestamp": self.formatTime(record, self.datefmt),
-                "logger_name": record.name,
-                "process_id": record.process,
-                "thread_name": record.threadName,
-            }
-            return json.dumps(log_record)
+            return json.dumps(self.get_json_record(record))
         except (ValueError, TypeError) as e:
             return f"Error formatting log record: {str(e)}"
+
+
+class GunicornAccessLogJsonFormatter(JsonFormatter):
+    def get_json_record(self, record: logging.LogRecord) -> dict[str, Any]:
+        response_time = datetime.strptime(record.args["t"], "[%d/%b/%Y:%H:%M:%S %z]")
+        url = record.args["U"]
+        if record.args["q"]:
+            url += f"?{record.args['q']}"
+
+        return {
+            **super().get_json_record(record),
+            "time": response_time.isoformat(),
+            "path": url,
+            "remote_ip": record.args["h"],
+            "method": record.args["m"],
+            "status": str(record.args["s"]),
+            "user_agent": record.args["a"],
+            "referer": record.args["f"],
+            "duration_in_ms": record.args["M"],
+            "pid": record.args["p"],
+        }
+
+
+class GunicornJsonLogger(GunicornLogger):
+    def setup(self, cfg: Config) -> None:
+        super().setup(cfg)
+        if settings.LOG_FORMAT == "json":
+            self._set_handler(
+                self.error_log,
+                cfg.errorlog,
+                JsonFormatter(),
+            )
+            self._set_handler(
+                self.access_log,
+                cfg.accesslog,
+                GunicornAccessLogJsonFormatter(),
+                stream=sys.stdout,
+            )

docs/docs/deployment/hosting/locally-api.md

@@ -150,7 +150,11 @@ the below variables will be ignored.
   define a shared DJANGO_SECRET_KEY.
 - `LOG_LEVEL`: DJANGO logging level. Can be one of `DEBUG`, `INFO`, `WARNING`, `ERROR`, `CRITICAL`
 - `LOG_FORMAT`: Can be `generic` (plain-text) or `json`. Defaults to `generic`.
-- `ACCESS_LOG_LOCATION`: The location to store web logs generated by gunicorn if running as a Docker container. If not
+- `GUNICORN_CMD_ARGS`: Gunicorn command line arguments. Overrides Flagsmith's defaults. See
+  [Gunicorn documentation](https://docs.gunicorn.org/en/stable/settings.html) for reference.
+- `ACCESS_LOG_FORMAT`: Message format for Gunicorn's access log. See
+  [variable details](https://docs.gunicorn.org/en/stable/settings.html#access-log-format) to define your own format.
+- `ACCESS_LOG_LOCATION`: The location to store web logs generated by Gunicorn if running as a Docker container. If not
   set, no logs will be stored. If set to `-` the logs will be sent to `stdout`.
 - `DJANGO_SETTINGS_MODULE`: python path to settings file for the given environment, e.g. "app.settings.develop"
 - `ALLOW_ADMIN_INITIATION_VIA_CLI`: Enables the `bootstrap` management command which creates default admin user,