From 6f66e0ff3d295e11e9ba699b92be2f53309d8459 Mon Sep 17 00:00:00 2001 From: Matthew Elwell Date: Thu, 28 Mar 2024 12:23:50 +0100 Subject: [PATCH] fix: rollback json access logging (#3694) --- api/Makefile | 2 +- api/app/settings/common.py | 4 +- api/scripts/gunicorn.conf.py | 16 ----- api/scripts/run-docker.sh | 11 ++- api/tests/unit/util/test_logging.py | 48 +++++++++++-- api/util/logging.py | 77 +++++---------------- docs/docs/deployment/hosting/docker.md | 7 +- docs/docs/deployment/hosting/locally-api.md | 8 +-- 8 files changed, 77 insertions(+), 96 deletions(-) delete mode 100644 api/scripts/gunicorn.conf.py diff --git a/api/Makefile b/api/Makefile index d0f0dffaa5fa..ee8c91850d4c 100644 --- a/api/Makefile +++ b/api/Makefile @@ -83,7 +83,7 @@ django-collect-static: .PHONY: serve serve: - poetry run gunicorn --config scripts/gunicorn.conf.py --bind 0.0.0.0:8000 app.wsgi --reload + poetry run gunicorn --bind 0.0.0.0:8000 app.wsgi --reload .PHONY: generate-ld-client-types generate-ld-client-types: diff --git a/api/app/settings/common.py b/api/app/settings/common.py index 48140ad9d626..adfc971535bc 100644 --- a/api/app/settings/common.py +++ b/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, diff --git a/api/scripts/gunicorn.conf.py b/api/scripts/gunicorn.conf.py deleted file mode 100644 index 7e33d4f510db..000000000000 --- a/api/scripts/gunicorn.conf.py +++ /dev/null @@ -1,16 +0,0 @@ -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.GunicornJsonCapableLogger" -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") diff --git a/api/scripts/run-docker.sh b/api/scripts/run-docker.sh index 1f8f2dbd5d63..79133d4254a1 100755 --- a/api/scripts/run-docker.sh +++ b/api/scripts/run-docker.sh @@ -17,8 +17,15 @@ function serve() { python manage.py waitfordb exec gunicorn --bind 0.0.0.0:8000 \ - --worker-tmp-dir=/dev/shm \ - --config=/app/scripts/gunicorn.conf.py \ + --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} \ app.wsgi } function run_task_processor() { diff --git a/api/tests/unit/util/test_logging.py b/api/tests/unit/util/test_logging.py index 2e85a7eb2f10..296c3997148e 100644 --- a/api/tests/unit/util/test_logging.py +++ b/api/tests/unit/util/test_logging.py @@ -4,7 +4,7 @@ from util.logging import JsonFormatter -def test_json_formatter__outputs_expected(): +def test_json_formatter(): json_formatter = JsonFormatter() log_record = logging.LogRecord( @@ -12,8 +12,8 @@ def test_json_formatter__outputs_expected(): level=logging.INFO, pathname="test.py", lineno=42, - msg="This is a test message with args: %s and %s", - args=("arg1", "arg2"), + msg="This is a test.", + args=(), exc_info=None, ) formatted_message = json_formatter.format(log_record) @@ -25,4 +25,44 @@ def test_json_formatter__outputs_expected(): assert "logger_name" in json_message assert "process_id" in json_message assert "thread_name" in json_message - assert json_message["message"] == "This is a test message with args: arg1 and arg2" + + +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" + ) diff --git a/api/util/logging.py b/api/util/logging.py index 0ab632564a3f..b274f92b449b 100644 --- a/api/util/logging.py +++ b/api/util/logging.py @@ -1,68 +1,27 @@ import json import logging -import os -import sys -from datetime import datetime -from typing import Any - -from gunicorn.config import Config -from gunicorn.glogging import Logger as GunicornLogger class JsonFormatter(logging.Formatter): """Custom formatter for json logs.""" - 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: + def format(self, record): + """ + %s is replaced with {} because legacy string formatting + conventions in django-axes module prevent correct + interpolation of arguments when using this formatter. + """ try: - return json.dumps(self.get_json_record(record)) + 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) except (ValueError, TypeError) as e: - return json.dumps({"message": f"{e} when dumping log"}) - - -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 GunicornJsonCapableLogger(GunicornLogger): - def setup(self, cfg: Config) -> None: - super().setup(cfg) - if os.getenv("LOG_FORMAT") == "json": - self._set_handler( - self.error_log, - cfg.errorlog, - JsonFormatter(), - ) - self._set_handler( - self.access_log, - cfg.accesslog, - GunicornAccessLogJsonFormatter(), - stream=sys.stdout, - ) + return f"Error formatting log record: {str(e)}" diff --git a/docs/docs/deployment/hosting/docker.md b/docs/docs/deployment/hosting/docker.md index b1c3d20482fc..18ce7df565c5 100644 --- a/docs/docs/deployment/hosting/docker.md +++ b/docs/docs/deployment/hosting/docker.md @@ -20,18 +20,13 @@ new account at [http://localhost:8000/signup](http://localhost:8000/signup) As well as the Environment Variables specified in the [API](/deployment/hosting/locally-api#environment-variables) and [Front End](/deployment/hosting/locally-frontend#environment-variables) you can also specify the following: -- `GUNICORN_CMD_ARGS`: Gunicorn command line arguments. Overrides Flagsmith's defaults. See - [Gunicorn documentation](https://docs.gunicorn.org/en/stable/settings.html) for reference. - `GUNICORN_WORKERS`: The number of [Gunicorn Workers](https://docs.gunicorn.org/en/stable/settings.html#workers) that are created - `GUNICORN_THREADS`: The number of [Gunicorn Threads per Worker](https://docs.gunicorn.org/en/stable/settings.html#threads) - `GUNICORN_TIMEOUT`: The number of seconds before the [Gunicorn times out](https://docs.gunicorn.org/en/stable/settings.html#timeout) -- `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 write access logs to. If not set, or set to `-`, the logs will be sent to - `stdout` +- `ACCESS_LOG_LOCATION`: The location to write access logs to ## Platform Architectures diff --git a/docs/docs/deployment/hosting/locally-api.md b/docs/docs/deployment/hosting/locally-api.md index e72314552858..b5f28bcd8cb8 100644 --- a/docs/docs/deployment/hosting/locally-api.md +++ b/docs/docs/deployment/hosting/locally-api.md @@ -150,12 +150,8 @@ 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`. -- `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 not set, or set to `-`, the logs will be sent to `stdout`. +- `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, organisation, and project.