diff --git a/api/.env-ci b/api/.env-ci index aca344b74e0d..cbc64251524f 100644 --- a/api/.env-ci +++ b/api/.env-ci @@ -1,5 +1,4 @@ DATABASE_URL=postgresql://postgres:password@localhost:5432/flagsmith ANALYTICS_DATABASE_URL=postgresql://postgres:password@localhost:5433/analytics PYTEST_ADDOPTS=--cov . --cov-report xml -n auto --ci -GUNICORN_LOGGER_CLASS=util.logging.GunicornJsonCapableLogger COVERAGE_CORE=sysmon diff --git a/api/app/settings/common.py b/api/app/settings/common.py index c75fae2fbf34..cd660dd4b3d7 100644 --- a/api/app/settings/common.py +++ b/api/app/settings/common.py @@ -11,7 +11,7 @@ """ import importlib -import json +import logging import os import warnings from datetime import datetime, time, timedelta @@ -19,7 +19,6 @@ import dj_database_url import django_stubs_ext -import prometheus_client import pytz from common.core import ReplicaReadStrategy from corsheaders.defaults import default_headers # type: ignore[import-untyped] @@ -610,61 +609,11 @@ CHARGEBEE_API_KEY = env("CHARGEBEE_API_KEY", default=None) CHARGEBEE_SITE = env("CHARGEBEE_SITE", default=None) -# Logging configuration -ACCESS_LOG_EXTRA_ITEMS = env.list("ACCESS_LOG_EXTRA_ITEMS", subcast=str, default=[]) -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, - "formatters": { - "generic": {"format": "%(name)-12s %(levelname)-8s %(message)s"}, - "json": { - "()": "util.logging.JsonFormatter", - "datefmt": "%Y-%m-%d %H:%M:%S", - }, - }, - "handlers": { - "console": { - "level": LOG_LEVEL, - "class": "logging.StreamHandler", - "formatter": LOG_FORMAT, - } - }, - "loggers": { - "": {"level": LOG_LEVEL, "handlers": ["console"]}, - # Not sure why the following loggers are necessary, but it doesn't seem to - # write log messages for e.g. features.workflows.core.models without adding - # them explicitly. - # TODO: move all apps to a parent 'apps' directory and configure the logger - # for that dir - "features": { - "level": LOG_LEVEL, - "handlers": ["console"], - "propagate": False, - }, - "task_processor": { - "level": LOG_LEVEL, - "handlers": ["console"], - "propagate": False, - }, - "app_analytics": { - "level": LOG_LEVEL, - "handlers": ["console"], - "propagate": False, - }, - "webhooks": { - "level": LOG_LEVEL, - "handlers": ["console"], - "propagate": False, - }, - }, - } +# Logging is configured by flagsmith-common's setup_logging() in ensure_cli_env(), +# before Django loads. Disable Django's logging config to preserve our setup. +LOGGING_CONFIG = None +LOG_FORMAT = env.str("LOG_FORMAT", default="generic") +LOG_LEVEL = env.str("LOG_LEVEL", default="WARNING") ENABLE_DB_LOGGING = env.bool("DJANGO_ENABLE_DB_LOGGING", default=False) if ENABLE_DB_LOGGING: @@ -672,10 +621,7 @@ warnings.warn("Setting DEBUG=True to ensure DB logging functions correctly.") DEBUG = True - LOGGING["loggers"]["django.db.backends"] = { - "level": "DEBUG", - "handlers": ["console"], - } + logging.getLogger("django.db.backends").setLevel(logging.DEBUG) CACHE_FLAGS_SECONDS = env.int("CACHE_FLAGS_SECONDS", default=0) FLAGS_CACHE_LOCATION = "environment-flags" @@ -1442,12 +1388,6 @@ INSTALLED_APPS.append("licensing") PROMETHEUS_ENABLED = env.bool("PROMETHEUS_ENABLED", False) -PROMETHEUS_HISTOGRAM_BUCKETS = tuple( - env.list( - "PROMETHEUS_HISTOGRAM_BUCKETS", - default=prometheus_client.Histogram.DEFAULT_BUCKETS, - ) -) DOCGEN_MODE = env.bool("DOCGEN_MODE", default=False) diff --git a/api/poetry.lock b/api/poetry.lock index 870e0544c6ab..0b9a5e04f4e9 100644 --- a/api/poetry.lock +++ b/api/poetry.lock @@ -1,4 +1,4 @@ -# This file is automatically @generated by Poetry 2.3.2 and should not be changed by hand. +# This file is automatically @generated by Poetry 2.2.1 and should not be changed by hand. [[package]] name = "annotated-types" @@ -2033,41 +2033,47 @@ resolved_reference = "b7fa1f42c333b443763548ea1fe0054f07cdf641" [[package]] name = "flagsmith-common" -version = "3.3.0" +version = "3.4.0" description = "Flagsmith's common library" optional = false -python-versions = "<4.0,>=3.11" +python-versions = ">=3.11,<4.0" groups = ["main", "dev", "licensing", "workflows"] -files = [ - {file = "flagsmith_common-3.3.0-py3-none-any.whl", hash = "sha256:dcb94458c7fd1bbc7762080d5c11c1d97507beac48a71132209f322112d8c60d"}, - {file = "flagsmith_common-3.3.0.tar.gz", hash = "sha256:e2839eda7091f13794efbaa7e20895110f9fbf5953dd67f70585b93e7c5864fa"}, -] - -[package.dependencies] -backoff = {version = ">=2.2.1,<3.0.0", optional = true, markers = "extra == \"task-processor\""} -django = {version = ">4,<6", optional = true, markers = "extra == \"common-core\" or extra == \"task-processor\""} -django-health-check = {version = "*", optional = true, markers = "extra == \"common-core\" or extra == \"task-processor\""} -djangorestframework = {version = "*", optional = true, markers = "extra == \"common-core\""} -djangorestframework-recursive = {version = "*", optional = true, markers = "extra == \"common-core\""} -drf-spectacular = {version = ">=0.28.0,<1", optional = true, markers = "extra == \"common-core\""} -drf-writable-nested = {version = "*", optional = true, markers = "extra == \"common-core\""} -environs = {version = "<15", optional = true, markers = "extra == \"common-core\""} -flagsmith-flag-engine = {version = ">6", optional = true, markers = "extra == \"flagsmith-schemas\""} -gunicorn = {version = ">=19.1", optional = true, markers = "extra == \"common-core\""} -prometheus-client = {version = ">=0.0.16", optional = true, markers = "extra == \"common-core\" or extra == \"task-processor\""} -psycopg2-binary = {version = ">=2.9,<3", optional = true, markers = "extra == \"common-core\""} -pyfakefs = {version = ">=5,<6", optional = true, markers = "extra == \"test-tools\""} -pytest-django = {version = ">=4,<5", optional = true, markers = "extra == \"test-tools\""} -requests = {version = "*", optional = true, markers = "extra == \"common-core\""} -simplejson = {version = ">=3,<4", optional = true, markers = "extra == \"common-core\" and extra == \"flagsmith-schemas\""} -typing-extensions = {version = "*", optional = true, markers = "extra == \"flagsmith-schemas\""} +files = [] +develop = false + +[package.dependencies] +backoff = {version = ">=2.2.1,<3.0.0", optional = true} +django = {version = ">4,<6", optional = true} +django-health-check = {version = "*", optional = true} +djangorestframework = {version = "*", optional = true} +djangorestframework-recursive = {version = "*", optional = true} +drf-spectacular = {version = ">=0.28.0,<1", optional = true} +drf-writable-nested = {version = "*", optional = true} +environs = {version = "<15", optional = true} +flagsmith-flag-engine = {version = ">6", optional = true} +gunicorn = {version = ">=19.1", optional = true} +prometheus-client = {version = ">=0.0.16", optional = true} +psycopg2-binary = {version = ">=2.9,<3", optional = true} +pyfakefs = {version = ">=5,<6", optional = true} +pytest-django = {version = ">=4,<5", optional = true} +requests = {version = "*", optional = true} +sentry-sdk = {version = ">=2.0.0,<3.0.0", optional = true} +simplejson = {version = ">=3,<4", optional = true} +structlog = {version = ">=24.4,<26", optional = true} +typing_extensions = {version = "*", optional = true} [package.extras] -common-core = ["django (>4,<6)", "django-health-check", "djangorestframework", "djangorestframework-recursive", "drf-spectacular (>=0.28.0,<1)", "drf-writable-nested", "environs (<15)", "gunicorn (>=19.1)", "prometheus-client (>=0.0.16)", "psycopg2-binary (>=2.9,<3)", "requests", "simplejson (>=3,<4)"] -flagsmith-schemas = ["flagsmith-flag-engine (>6)", "simplejson", "typing-extensions"] +common-core = ["django (>4,<6)", "django-health-check", "djangorestframework", "djangorestframework-recursive", "drf-spectacular (>=0.28.0,<1)", "drf-writable-nested", "environs (<15)", "gunicorn (>=19.1)", "prometheus-client (>=0.0.16)", "psycopg2-binary (>=2.9,<3)", "requests", "sentry-sdk (>=2.0.0,<3.0.0)", "simplejson (>=3,<4)", "structlog (>=24.4,<26)", "typing_extensions"] +flagsmith-schemas = ["flagsmith-flag-engine (>6)", "simplejson", "typing_extensions"] task-processor = ["backoff (>=2.2.1,<3.0.0)", "django (>4,<6)", "django-health-check", "prometheus-client (>=0.0.16)"] test-tools = ["pyfakefs (>=5,<6)", "pytest-django (>=4,<5)"] +[package.source] +type = "git" +url = "https://github.com/Flagsmith/flagsmith-common.git" +reference = "feat/logging-improvements" +resolved_reference = "852780f06c77101d841ca3a13e822c096f827cc4" + [[package]] name = "flagsmith-flag-engine" version = "10.0.3" @@ -2187,12 +2193,12 @@ files = [ ] [package.dependencies] -google-api-core = {version = ">=1.21.0,<3.dev0", markers = "python_version >= \"3\""} -google-auth = {version = ">=1.16.0,<3.dev0", markers = "python_version >= \"3\""} +google-api-core = {version = ">=1.21.0,<3dev", markers = "python_version >= \"3\""} +google-auth = {version = ">=1.16.0,<3dev", markers = "python_version >= \"3\""} google-auth-httplib2 = ">=0.0.3" -httplib2 = ">=0.15.0,<1.dev0" -six = ">=1.13.0,<2.dev0" -uritemplate = ">=3.0.0,<4.dev0" +httplib2 = ">=0.15.0,<1dev" +six = ">=1.13.0,<2dev" +uritemplate = ">=3.0.0,<4dev" [[package]] name = "google-auth" @@ -2505,7 +2511,7 @@ files = [ ] [package.dependencies] -certifi = ">=14.5.14" +certifi = ">=14.05.14" python-dateutil = ">=2.5.3" reactivex = ">=4.0.4" urllib3 = ">=1.26.0" @@ -2711,7 +2717,7 @@ files = [ [package.dependencies] attrs = ">=22.2.0" -jsonschema-specifications = ">=2023.3.6" +jsonschema-specifications = ">=2023.03.6" referencing = ">=0.28.4" rpds-py = ">=0.7.1" @@ -3748,7 +3754,7 @@ files = [ ] [package.dependencies] -astroid = ">=2.14.2,<=2.16.0.dev0" +astroid = ">=2.14.2,<=2.16.0-dev0" colorama = {version = ">=0.4.5", markers = "sys_platform == \"win32\""} dill = {version = ">=0.3.6", markers = "python_version >= \"3.11\""} isort = ">=4.2.5,<6" @@ -4255,7 +4261,6 @@ files = [ {file = "PyYAML-6.0.1-cp311-cp311-win_amd64.whl", hash = "sha256:bf07ee2fef7014951eeb99f56f39c9bb4af143d8aa3c21b1677805985307da34"}, {file = "PyYAML-6.0.1-cp312-cp312-macosx_10_9_x86_64.whl", hash = "sha256:855fb52b0dc35af121542a76b9a84f8d1cd886ea97c84703eaa6d88e37a2ad28"}, {file = "PyYAML-6.0.1-cp312-cp312-macosx_11_0_arm64.whl", hash = "sha256:40df9b996c2b73138957fe23a16a4f0ba614f4c0efce1e9406a184b6d07fa3a9"}, - {file = "PyYAML-6.0.1-cp312-cp312-manylinux_2_17_aarch64.manylinux2014_aarch64.whl", hash = "sha256:a08c6f0fe150303c1c6b71ebcd7213c2858041a7e01975da3a99aed1e7a378ef"}, {file = "PyYAML-6.0.1-cp312-cp312-manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:6c22bec3fbe2524cde73d7ada88f6566758a8f7227bfbf93a408a9d86bcc12a0"}, {file = "PyYAML-6.0.1-cp312-cp312-musllinux_1_1_x86_64.whl", hash = "sha256:8d4e9c88387b0f5c7d5f281e55304de64cf7f9c0021a3525bd3b1c542da3b0e4"}, {file = "PyYAML-6.0.1-cp312-cp312-win32.whl", hash = "sha256:d483d2cdf104e7c9fa60c544d92981f12ad66a457afae824d146093b8c294c54"}, @@ -4769,10 +4774,10 @@ files = [ ] [package.dependencies] -botocore = ">=1.33.2,<2.0a0" +botocore = ">=1.33.2,<2.0a.0" [package.extras] -crt = ["botocore[crt] (>=1.33.2,<2.0a0)"] +crt = ["botocore[crt] (>=1.33.2,<2.0a.0)"] [[package]] name = "segment-analytics-python" @@ -5413,7 +5418,6 @@ files = [ {file = "tzdata-2024.1-py2.py3-none-any.whl", hash = "sha256:9068bc196136463f5245e51efda838afa15aaeca9903f49050dfa2679db4d252"}, {file = "tzdata-2024.1.tar.gz", hash = "sha256:2674120f8d891909751c38abcdfd386ac0a5a1127954fbc332af6b5ceae07efd"}, ] -markers = {auth-controller = "sys_platform == \"win32\"", dev = "sys_platform == \"win32\"", ldap = "sys_platform == \"win32\"", workflows = "sys_platform == \"win32\""} [[package]] name = "uritemplate" @@ -5671,4 +5675,4 @@ files = [ [metadata] lock-version = "2.1" python-versions = ">3.11,<3.14" -content-hash = "83fc1419a52f7553b9c7dbbe1405cb3be83d2727e8a9661450e391282d858ea0" +content-hash = "b4db9a33ad0dcb46b91947ab4921bce488296d2c34e7fa89eb5ec62c4c3b5594" diff --git a/api/pyproject.toml b/api/pyproject.toml index f55101f91ad6..e89e5f565c0d 100644 --- a/api/pyproject.toml +++ b/api/pyproject.toml @@ -163,7 +163,7 @@ pygithub = "~2.8" hubspot-api-client = "^12.0.0" djangorestframework-dataclasses = "^1.3.1" pyotp = "^2.9.0" -flagsmith-common = { version = "^3.3.0", extras = [ +flagsmith-common = { git = "https://github.com/Flagsmith/flagsmith-common.git", branch = "feat/logging-improvements", extras = [ "common-core", "flagsmith-schemas", "task-processor", diff --git a/api/tests/unit/util/test_logging.py b/api/tests/unit/util/test_logging.py deleted file mode 100644 index c8c81603fe1e..000000000000 --- a/api/tests/unit/util/test_logging.py +++ /dev/null @@ -1,140 +0,0 @@ -import json -import logging -import logging.config -import os -from datetime import datetime - -import pytest -from gunicorn.config import AccessLogFormat, Config # type: ignore[import-untyped] -from pytest_django.fixtures import SettingsWrapper - -from util.logging import GunicornAccessLogJsonFormatter, JsonFormatter - - -@pytest.mark.freeze_time("2023-12-08T06:05:47.000000+00:00") -def test_json_formatter__info_and_error_logs__outputs_expected_json( - inspecting_handler: logging.Handler, - request: pytest.FixtureRequest, -) -> None: - # Given - json_formatter = JsonFormatter() - - inspecting_handler.setFormatter(json_formatter) - logger = logging.getLogger("test_json_formatter__outputs_expected") - logger.addHandler(inspecting_handler) - logger.setLevel(logging.INFO) - - expected_pid = os.getpid() - expected_module_path = os.path.abspath(request.path) - expected_tb_string = ( - "Traceback (most recent call last):\n" - f' File "{expected_module_path}",' - " line 38, in _log_traceback\n" - " raise Exception()\nException" - ) - - def _log_traceback() -> None: - try: - raise Exception() - except Exception as exc: - logger.error("this is an error", exc_info=exc) - - # When - logger.info("hello %s, %d", "arg1", 22.22) - _log_traceback() - - # Then - assert [json.loads(message) for message in inspecting_handler.messages] == [ # type: ignore[attr-defined] - { - "levelname": "INFO", - "message": "hello arg1, 22", - "timestamp": "2023-12-08 06:05:47,000", - "logger_name": "test_json_formatter__outputs_expected", - "process_id": expected_pid, - "thread_name": "MainThread", - }, - { - "levelname": "ERROR", - "message": "this is an error", - "timestamp": "2023-12-08 06:05:47,000", - "logger_name": "test_json_formatter__outputs_expected", - "process_id": expected_pid, - "thread_name": "MainThread", - "exc_info": expected_tb_string, - }, - ] - - -@pytest.mark.freeze_time("2023-12-08T06:05:47.000000+00:00") -def test_gunicorn_access_log_json_formatter__access_log_record__outputs_expected_json() -> ( - None -): - # Given - gunicorn_access_log_json_formatter = GunicornAccessLogJsonFormatter() - log_record = logging.LogRecord( - name="gunicorn.access", - level=logging.INFO, - pathname="", - lineno=1, - msg=AccessLogFormat.default, - args={ - "a": "requests", - "b": "-", - "B": None, - "D": 1000000, - "f": "-", - "h": "192.168.0.1", - "H": None, - "l": "-", - "L": "1.0", - "m": "GET", - "M": 1000, - "p": "<42>", - "q": "foo=bar", - "r": "GET", - "s": 200, - "T": 1, - "t": datetime.fromisoformat("2023-12-08T06:05:47.000+00:00").strftime( - "[%d/%b/%Y:%H:%M:%S %z]" - ), - "u": "-", - "U": "/test", - }, - exc_info=None, - ) - expected_pid = os.getpid() - - # When - json_log = gunicorn_access_log_json_formatter.get_json_record(log_record) - - # Then - assert json_log == { - "duration_in_ms": 1000, - "levelname": "INFO", - "logger_name": "gunicorn.access", - "message": '192.168.0.1 - - [08/Dec/2023:06:05:47 +0000] "GET" 200 - "-" "requests"', - "method": "GET", - "path": "/test?foo=bar", - "pid": "<42>", - "process_id": expected_pid, - "referer": "-", - "remote_ip": "192.168.0.1", - "status": "200", - "thread_name": "MainThread", - "time": "2023-12-08T06:05:47+00:00", - "timestamp": "2023-12-08 06:05:47,000", - "user_agent": "requests", - } - - -def test_gunicorn_json_capable_logger__non_existent_setting__not_raises( - settings: SettingsWrapper, -) -> None: - # Given - del settings.LOG_FORMAT - config = Config() - - # When & Then - from util.logging import GunicornJsonCapableLogger - - GunicornJsonCapableLogger(config) diff --git a/api/util/logging.py b/api/util/logging.py deleted file mode 100644 index ae986132fcbd..000000000000 --- a/api/util/logging.py +++ /dev/null @@ -1,70 +0,0 @@ -import json -import logging -import sys -from datetime import datetime -from typing import Any - -from django.conf import settings -from gunicorn.config import Config # type: ignore[import-untyped] -from gunicorn.instrument.statsd import ( # type: ignore[import-untyped] - Statsd 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() - json_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, - } - if record.exc_info: - json_record["exc_info"] = self.formatException(record.exc_info) - return json_record - - def format(self, record: logging.LogRecord) -> str: - return json.dumps(self.get_json_record(record)) - - -class GunicornAccessLogJsonFormatter(JsonFormatter): - def get_json_record(self, record: logging.LogRecord) -> dict[str, Any]: - args = record.args - url = args["U"] # type: ignore[call-overload,index] - if q := args["q"]: # type: ignore[call-overload,index] - url += f"?{q}" # type: ignore[operator] - - return { - **super().get_json_record(record), - "time": datetime.strptime(args["t"], "[%d/%b/%Y:%H:%M:%S %z]").isoformat(), # type: ignore[arg-type,call-overload,index] # noqa: E501 # noqa: E501 - "path": url, - "remote_ip": args["h"], # type: ignore[call-overload,index] - "method": args["m"], # type: ignore[call-overload,index] - "status": str(args["s"]), # type: ignore[call-overload,index] - "user_agent": args["a"], # type: ignore[call-overload,index] - "referer": args["f"], # type: ignore[call-overload,index] - "duration_in_ms": args["M"], # type: ignore[call-overload,index] - "pid": args["p"], # type: ignore[call-overload,index] - } - - -class GunicornJsonCapableLogger(GunicornLogger): # type: ignore[misc] - def setup(self, cfg: Config) -> None: - super().setup(cfg) - if getattr(settings, "LOG_FORMAT", None) == "json": - self._set_handler( - self.error_log, - cfg.errorlog, - JsonFormatter(), - ) - self._set_handler( - self.access_log, - cfg.accesslog, - GunicornAccessLogJsonFormatter(), - stream=sys.stdout, - )