diff --git a/.gitignore b/.gitignore index 0febfb9d..605e915f 100644 --- a/.gitignore +++ b/.gitignore @@ -30,6 +30,7 @@ local.py /static/ /mail/ /log/*.log* +/log/*.jsonl* /log/nginx/*.log* .env diff --git a/CHANGELOG.rst b/CHANGELOG.rst index b50914f4..2b3cc80a 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -33,8 +33,8 @@ Change history * Upgrade npm packages to fix vulnerabilities * Fixed admin logout button * [:objects-api:`550`] Implement cache for objecttypes -* [:objects-api:`550`] add OBJECTTYPE_VERSION_CACHE_TIMEOUT environment variable `documentation `_ -* [:objects-api:`572`] Add db connection pooling environment variables `documentation `_ +* [:objects-api:`550`] add OBJECTTYPE_VERSION_CACHE_TIMEOUT environment variable (see `documentation for environment variables for caching `_) +* [:objects-api:`572`] Add db connection pooling environment variables (see `documentation for environment variables for database `_) * DB_POOL_ENABLED * DB_POOL_MIN_SIZE @@ -46,7 +46,7 @@ Change history * DB_POOL_RECONNECT_TIMEOUT * DB_POOL_NUM_WORKERS -* [:objects-api:`566`] Add DB_CONN_MAX_AGE environment variable `documentation `_ +* [:objects-api:`566`] Add DB_CONN_MAX_AGE environment variable (see `documentation for environment variables for database `_) 3.0.3 (2025-04-03) ------------------ @@ -132,8 +132,7 @@ Change history .. warning:: Previous configuration files used for ``setup_configuration`` do not work. - See the `documentation `_ - for the available settings that can now be configured through ``setup_configuration``. + See :ref:`installation_config_cli` for the available settings that can now be configured through ``setup_configuration``. * added support for configuring permissions through ``django-setup-configuration`` version ``0.4.0`` [#497] diff --git a/Dockerfile b/Dockerfile index 88e206bc..372bd92f 100644 --- a/Dockerfile +++ b/Dockerfile @@ -6,6 +6,9 @@ RUN apt-get update && apt-get upgrade -y && apt-get install -y --no-install-reco build-essential \ git \ libpq-dev \ + # required for (log) routing support in uwsgi + libpcre3 \ + libpcre3-dev \ && rm -rf /var/lib/apt/lists/* @@ -44,6 +47,7 @@ RUN apt-get update && apt-get upgrade -y && apt-get install -y --no-install-reco gdal-bin \ libgdal-dev \ gettext \ + libpcre3 \ && rm -rf /var/lib/apt/lists/* RUN pip install pip "setuptools>=70.0.0" @@ -60,6 +64,7 @@ COPY ./bin/celery_worker.sh /celery_worker.sh COPY ./bin/celery_flower.sh /celery_flower.sh COPY ./bin/check_celery_worker_liveness.py ./bin/ COPY ./bin/setup_configuration.sh /setup_configuration.sh +COPY ./bin/uwsgi.ini / RUN mkdir /app/log /app/config /app/tmp # copy frontend build statics diff --git a/bin/docker_start.sh b/bin/docker_start.sh index 4e18b176..af26ca03 100755 --- a/bin/docker_start.sh +++ b/bin/docker_start.sh @@ -50,6 +50,7 @@ fi # Start server >&2 echo "Starting server" uwsgi \ + --ini "${SCRIPTPATH}/uwsgi.ini" \ --http :$uwsgi_port \ --http-keepalive \ --manage-script-name \ diff --git a/bin/uwsgi.ini b/bin/uwsgi.ini new file mode 100644 index 00000000..7ad34bad --- /dev/null +++ b/bin/uwsgi.ini @@ -0,0 +1,32 @@ +; Docs: +; * https://uwsgi-docs.readthedocs.io/en/latest/Logging.html +; * https://uwsgi-docs.readthedocs.io/en/latest/LogEncoders.html +; Reference article: https://blog.rama.io/json-logging-with-uwsgi +[uwsgi] +; logger definition for the django app logs, which are already structured +logger = djangologger stdio +; logger definition for the uwsgi server logs +logger = uwsgilogger stdio + +; any message starting with { is assumed to already be structured -> +; send it to the djangologger +log-route = djangologger ^{.*$ +; send any message not starting with { to the uwsgilogger +log-route = uwsgilogger ^((?!\{).)*$ + +; leave already JSON formatted django logs as is +log-encoder = format:djangologger ${msg} +; Encode uWSGI server logs as JSON +log-encoder = json:uwsgilogger {"source": "uwsgi", "type": "server", "timestamp": "${strftime:%%Y-%%m-%%dT%%H:%%M:%%S%%z}", "event": "${msg}", "level": "info"} + +; these are uwsgi's own request logs (not to be confused with the request logs emitted +; by the application!) +logger-req = stdio +; pragamatic approach - these variables are *not* JSON escaped and can lead to broken +; output lines. there's no security risk involved there, at worst a log scraper fails to +; parse the message as json +; TODO: perhaps we can extract trace IDs here for spans -> using uwsgi vars! +log-format = {"source": "uwsgi", "event": "request", "method": "%(method)", "path": "%(uri)", "duration_in_ms": %(msecs), "status": %(status), "bytes": %(rsize), "referer": "%(referer)", "host": "%(host)", "timestamp": "%(iso8601timestamp)", "remote_ip": "%(addr)", "level": "info"} + +; finally, ensure that all log lines are separated with a newline +log-encoder = nl diff --git a/docs/installation/config.rst b/docs/installation/config.rst index ec64fb3d..2a9c12e5 100644 --- a/docs/installation/config.rst +++ b/docs/installation/config.rst @@ -43,22 +43,38 @@ Database * ``DB_POOL_NUM_WORKERS``: Number of background worker threads used to maintain the pool state. Background workers are used for example to create new connections and to clean up connections when they are returned to the pool. Defaults to: ``3``. -Cross-Origin-Resource-Sharing ------------------------------ +Logging +------- -* ``CORS_ALLOW_ALL_ORIGINS``: allow cross-domain access from any client. Defaults to: ``False``. -* ``CORS_ALLOWED_ORIGINS``: explicitly list the allowed origins for cross-domain requests. Example: http://localhost:3000,https://some-app.gemeente.nl. Defaults to: ``[]``. -* ``CORS_ALLOWED_ORIGIN_REGEXES``: same as ``CORS_ALLOWED_ORIGINS``, but supports regular expressions. Defaults to: ``[]``. -* ``CORS_EXTRA_ALLOW_HEADERS``: headers that are allowed to be sent as part of the cross-domain request. By default, Authorization, Accept-Crs and Content-Crs are already included. The value of this variable is added to these already included headers. Defaults to: ``[]``. +* ``LOG_STDOUT``: whether to log to stdout or not. Defaults to: ``True``. +* ``LOG_LEVEL``: control the verbosity of logging output. Available values are ``CRITICAL``, ``ERROR``, ``WARNING``, ``INFO`` and ``DEBUG``. Defaults to: ``WARNING``. +* ``LOG_QUERIES``: enable (query) logging at the database backend level. Note that you must also set ``DEBUG=1``, which should be done very sparingly!. Defaults to: ``False``. +* ``LOG_REQUESTS``: enable logging of the outgoing requests. Defaults to: ``False``. +* ``LOG_OUTGOING_REQUESTS_EMIT_BODY``: Whether or not outgoing request bodies should be logged. Defaults to: ``True``. +* ``LOG_OUTGOING_REQUESTS_DB_SAVE``: Whether or not outgoing request logs should be saved to the database. Defaults to: ``False``. +* ``LOG_OUTGOING_REQUESTS_DB_SAVE_BODY``: Whether or not outgoing request bodies should be saved to the database. Defaults to: ``True``. +* ``LOG_OUTGOING_REQUESTS_MAX_AGE``: The amount of time after which request logs should be deleted from the database. Defaults to: ``7``. +* ``ENABLE_STRUCTLOG_REQUESTS``: enable structured logging of requests. Defaults to: ``True``. +* ``LOG_FORMAT_CONSOLE``: The format for the console logging handler, possible options: ``json``, ``plain_console``. Defaults to: ``json``. Celery ------ +* ``CELERY_LOGLEVEL``: control the verbosity of logging output for celery, independent of ``LOG_LEVEL``. Available values are ``CRITICAL``, ``ERROR``, ``WARNING``, ``INFO`` and ``DEBUG``. Defaults to: ``INFO``. * ``CELERY_RESULT_BACKEND``: the URL of the backend/broker that will be used by Celery to send the notifications. Defaults to: ``redis://localhost:6379/1``. * ``CELERY_TASK_HARD_TIME_LIMIT``: Task hard time limit in seconds. The worker processing the task will be killed and replaced with a new one when this is exceeded. Defaults to: ``900``. +Cross-Origin-Resource-Sharing +----------------------------- + +* ``CORS_ALLOW_ALL_ORIGINS``: allow cross-domain access from any client. Defaults to: ``False``. +* ``CORS_ALLOWED_ORIGINS``: explicitly list the allowed origins for cross-domain requests. Example: http://localhost:3000,https://some-app.gemeente.nl. Defaults to: ``[]``. +* ``CORS_ALLOWED_ORIGIN_REGEXES``: same as ``CORS_ALLOWED_ORIGINS``, but supports regular expressions. Defaults to: ``[]``. +* ``CORS_EXTRA_ALLOW_HEADERS``: headers that are allowed to be sent as part of the cross-domain request. By default, Authorization, Accept-Crs and Content-Crs are already included. The value of this variable is added to these already included headers. Defaults to: ``[]``. + + Elastic APM ----------- @@ -98,11 +114,6 @@ Optional * ``EMAIL_HOST_PASSWORD``: password to connect to the mail server. Defaults to: ``(empty string)``. * ``EMAIL_USE_TLS``: whether to use TLS or not to connect to the mail server. Should be True if you're changing the ``EMAIL_PORT`` to 487. Defaults to: ``False``. * ``DEFAULT_FROM_EMAIL``: The default email address from which emails are sent. Defaults to: ``objects@example.com``. -* ``LOG_STDOUT``: whether to log to stdout or not. Defaults to: ``True``. -* ``LOG_LEVEL``: control the verbosity of logging output. Available values are ``CRITICAL``, ``ERROR``, ``WARNING``, ``INFO`` and ``DEBUG``. Defaults to: ``WARNING``. -* ``LOG_QUERIES``: enable (query) logging at the database backend level. Note that you must also set ``DEBUG=1``, which should be done very sparingly!. Defaults to: ``False``. -* ``LOG_REQUESTS``: enable logging of the outgoing requests. Defaults to: ``False``. -* ``CELERY_LOGLEVEL``: control the verbosity of logging output for celery, independent of ``LOG_LEVEL``. Available values are ``CRITICAL``, ``ERROR``, ``WARNING``, ``INFO`` and ``DEBUG``. Defaults to: ``INFO``. * ``SESSION_COOKIE_AGE``: For how long, in seconds, the session cookie will be valid. Defaults to: ``1209600``. * ``SESSION_COOKIE_SAMESITE``: The value of the SameSite flag on the session cookie. This flag prevents the cookie from being sent in cross-site requests thus preventing CSRF attacks and making some methods of stealing session cookie impossible.Currently interferes with OIDC. Keep the value set at Lax if used. Defaults to: ``Lax``. * ``CSRF_COOKIE_SAMESITE``: The value of the SameSite flag on the CSRF cookie. This flag prevents the cookie from being sent in cross-site requests. Defaults to: ``Strict``. @@ -115,10 +126,6 @@ Optional * ``SITE_DOMAIN``: Defines the primary domain where the application is hosted. Defaults to: ``(empty string)``. * ``SENTRY_DSN``: URL of the sentry project to send error reports to. Default empty, i.e. -> no monitoring set up. Highly recommended to configure this. * ``DISABLE_2FA``: Whether or not two factor authentication should be disabled. Defaults to: ``False``. -* ``LOG_OUTGOING_REQUESTS_EMIT_BODY``: Whether or not outgoing request bodies should be logged. Defaults to: ``True``. -* ``LOG_OUTGOING_REQUESTS_DB_SAVE``: Whether or not outgoing request logs should be saved to the database. Defaults to: ``False``. -* ``LOG_OUTGOING_REQUESTS_DB_SAVE_BODY``: Whether or not outgoing request bodies should be saved to the database. Defaults to: ``True``. -* ``LOG_OUTGOING_REQUESTS_MAX_AGE``: The amount of time after which request logs should be deleted from the database. Defaults to: ``7``. diff --git a/requirements/base.in b/requirements/base.in index b87255f4..6bff8e6e 100644 --- a/requirements/base.in +++ b/requirements/base.in @@ -1,11 +1,13 @@ open-api-framework - # Core python libraries glom # data represenation based on spec jsonschema furl +# Django libraries +django-structlog[celery] + # Common ground libraries django-setup-configuration>=0.5.0 notifications-api-common[setup-configuration] diff --git a/requirements/base.txt b/requirements/base.txt index 28183631..a3bf50f7 100644 --- a/requirements/base.txt +++ b/requirements/base.txt @@ -14,6 +14,7 @@ asgiref==3.8.1 # django # django-axes # django-cors-headers + # django-structlog asn1crypto==1.5.1 # via webauthn attrs==20.3.0 @@ -32,6 +33,7 @@ cbor2==5.6.2 # via webauthn celery==5.4.0 # via + # django-structlog # flower # notifications-api-common # open-api-framework @@ -94,6 +96,7 @@ django==5.2.1 # django-setup-configuration # django-simple-certmanager # django-solo + # django-structlog # django-two-factor-auth # djangorestframework # djangorestframework-inclusions @@ -122,6 +125,8 @@ django-filter==24.2 # open-api-framework django-formtools==2.3 # via django-two-factor-auth +django-ipware==7.0.1 + # via django-structlog django-jsonform==2.22.0 # via # mozilla-django-oidc-db @@ -164,6 +169,8 @@ django-solo==2.2.0 # mozilla-django-oidc-db # notifications-api-common # zgw-consumers +django-structlog==9.1.1 + # via -r requirements/base.in django-two-factor-auth==1.17.0 # via maykin-2fa djangorestframework==3.15.2 @@ -246,7 +253,7 @@ notifications-api-common==0.7.2 # via # -r requirements/base.in # commonground-api-common -open-api-framework==0.9.6 +open-api-framework==0.10.0 # via -r requirements/base.in orderedmultidict==1.0.1 # via furl @@ -295,6 +302,8 @@ python-dotenv==1.0.0 # via # open-api-framework # pydantic-settings +python-ipware==3.0.0 + # via django-ipware pytz==2024.1 # via flower pyyaml==6.0.1 @@ -335,6 +344,8 @@ six==1.16.0 # qrcode sqlparse==0.5.0 # via django +structlog==25.3.0 + # via django-structlog tornado==6.5 # via flower typing-extensions==4.9.0 diff --git a/requirements/ci.txt b/requirements/ci.txt index e67e496f..73d9672b 100644 --- a/requirements/ci.txt +++ b/requirements/ci.txt @@ -26,6 +26,7 @@ asgiref==3.8.1 # django # django-axes # django-cors-headers + # django-structlog asn1crypto==1.5.1 # via # -c requirements/base.txt @@ -173,6 +174,7 @@ django==5.2.1 # django-setup-configuration # django-simple-certmanager # django-solo + # django-structlog # django-two-factor-auth # djangorestframework # djangorestframework-inclusions @@ -221,6 +223,11 @@ django-formtools==2.3 # -c requirements/base.txt # -r requirements/base.txt # django-two-factor-auth +django-ipware==7.0.1 + # via + # -c requirements/base.txt + # -r requirements/base.txt + # django-structlog django-jsonform==2.22.0 # via # -c requirements/base.txt @@ -301,6 +308,10 @@ django-solo==2.2.0 # mozilla-django-oidc-db # notifications-api-common # zgw-consumers +django-structlog==9.1.1 + # via + # -c requirements/base.txt + # -r requirements/base.txt django-two-factor-auth==1.17.0 # via # -c requirements/base.txt @@ -484,7 +495,7 @@ notifications-api-common==0.7.2 # -c requirements/base.txt # -r requirements/base.txt # commonground-api-common -open-api-framework==0.9.6 +open-api-framework==0.10.0 # via # -c requirements/base.txt # -r requirements/base.txt @@ -612,6 +623,11 @@ python-dotenv==1.0.0 # -r requirements/base.txt # open-api-framework # pydantic-settings +python-ipware==3.0.0 + # via + # -c requirements/base.txt + # -r requirements/base.txt + # django-ipware pytz==2024.1 # via # -c requirements/base.txt @@ -721,6 +737,11 @@ sqlparse==0.5.0 # -c requirements/base.txt # -r requirements/base.txt # django +structlog==25.3.0 + # via + # -c requirements/base.txt + # -r requirements/base.txt + # django-structlog tblib==1.7.0 # via -r requirements/test-tools.in tornado==6.5 diff --git a/requirements/dev.txt b/requirements/dev.txt index a277005a..e3d68d8e 100644 --- a/requirements/dev.txt +++ b/requirements/dev.txt @@ -31,6 +31,7 @@ asgiref==3.8.1 # django # django-axes # django-cors-headers + # django-structlog asn1crypto==1.5.1 # via # -c requirements/ci.txt @@ -211,6 +212,7 @@ django==5.2.1 # django-silk # django-simple-certmanager # django-solo + # django-structlog # django-two-factor-auth # djangorestframework # djangorestframework-inclusions @@ -263,6 +265,11 @@ django-formtools==2.3 # -c requirements/ci.txt # -r requirements/ci.txt # django-two-factor-auth +django-ipware==7.0.1 + # via + # -c requirements/ci.txt + # -r requirements/ci.txt + # django-structlog django-jsonform==2.22.0 # via # -c requirements/ci.txt @@ -345,6 +352,10 @@ django-solo==2.2.0 # mozilla-django-oidc-db # notifications-api-common # zgw-consumers +django-structlog==9.1.1 + # via + # -c requirements/ci.txt + # -r requirements/ci.txt django-two-factor-auth==1.17.0 # via # -c requirements/ci.txt @@ -573,7 +584,7 @@ notifications-api-common==0.7.2 # -c requirements/ci.txt # -r requirements/ci.txt # commonground-api-common -open-api-framework==0.9.6 +open-api-framework==0.10.0 # via # -c requirements/ci.txt # -r requirements/ci.txt @@ -742,6 +753,11 @@ python-dotenv==1.0.0 # -r requirements/ci.txt # open-api-framework # pydantic-settings +python-ipware==3.0.0 + # via + # -c requirements/ci.txt + # -r requirements/ci.txt + # django-ipware pytz==2024.1 # via # -c requirements/ci.txt @@ -901,6 +917,11 @@ sqlparse==0.5.0 # django # django-debug-toolbar # django-silk +structlog==25.3.0 + # via + # -c requirements/ci.txt + # -r requirements/ci.txt + # django-structlog tblib==1.7.0 # via # -c requirements/ci.txt diff --git a/src/objects/api/serializers.py b/src/objects/api/serializers.py index 750d1dfe..6a3007c5 100644 --- a/src/objects/api/serializers.py +++ b/src/objects/api/serializers.py @@ -1,17 +1,20 @@ from django.db import transaction from django.utils.translation import gettext_lazy as _ +import structlog from rest_framework import serializers from rest_framework_gis.serializers import GeometryField from objects.core.models import Object, ObjectRecord, ObjectType -from objects.token.models import Permission +from objects.token.models import Permission, TokenAuth from objects.utils.serializers import DynamicFieldsMixin from .fields import ObjectSlugRelatedField, ObjectTypeField, ObjectUrlField from .utils import merge_patch from .validators import GeometryValidator, IsImmutableValidator, JsonSchemaValidator +logger = structlog.stdlib.get_logger(__name__) + class ObjectRecordSerializer(serializers.ModelSerializer): correctionFor = ObjectSlugRelatedField( @@ -121,6 +124,15 @@ def create(self, validated_data): validated_data["object"] = object record = super().create(validated_data) + token_auth: TokenAuth = self.context["request"].auth + logger.info( + "object_created", + object_uuid=str(object.uuid), + objecttype_uuid=str(object.object_type.uuid), + objecttype_version=record.version, + token_identifier=token_auth.identifier, + token_application=token_auth.application, + ) return record @transaction.atomic @@ -140,6 +152,15 @@ def update(self, instance, validated_data): validated_data["data"] = merge_patch(instance.data, validated_data["data"]) record = super().create(validated_data) + token_auth: TokenAuth = self.context["request"].auth + logger.info( + "object_updated", + object_uuid=str(record.object.uuid), + objecttype_uuid=str(record.object.object_type.uuid), + objecttype_version=record.version, + token_identifier=token_auth.identifier, + token_application=token_auth.application, + ) return record diff --git a/src/objects/celery.py b/src/objects/celery.py index 5103a886..3f0fd3ec 100644 --- a/src/objects/celery.py +++ b/src/objects/celery.py @@ -1,15 +1,22 @@ +import logging # noqa: TID251 - correct use to replace stdlib logging +import logging.config # noqa: TID251 - correct use to replace stdlib logging from pathlib import Path from django.conf import settings +import structlog from celery import Celery, bootsteps from celery.signals import setup_logging, worker_ready, worker_shutdown +from django_structlog.celery.steps import DjangoStructLogInitStep +from open_api_framework.conf.utils import config from .setup import setup_env setup_env() app = Celery("objects") +assert app.steps is not None +app.steps["worker"].add(DjangoStructLogInitStep) app.config_from_object("django.conf:settings", namespace="CELERY") app.conf.ONCE = { "backend": "celery_once.backends.Redis", @@ -24,10 +31,80 @@ # Use django's logging settings as these are reset by Celery by default @setup_logging.connect() -def config_loggers(*args, **kwargs): - from logging.config import dictConfig - - dictConfig(settings.LOGGING) +def receiver_setup_logging( + loglevel, logfile, format, colorize, **kwargs +): # pragma: no cover + formatter = config("LOG_FORMAT_CONSOLE", default="json") + logging.config.dictConfig( + { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "json": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": structlog.processors.JSONRenderer(), + "foreign_pre_chain": [ + structlog.contextvars.merge_contextvars, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + ], + }, + "plain_console": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": structlog.dev.ConsoleRenderer(), + "foreign_pre_chain": [ + structlog.contextvars.merge_contextvars, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + ], + }, + }, + "handlers": { + "console": { + "class": "logging.StreamHandler", + "formatter": formatter, + }, + }, + "loggers": { + "root": { + "handlers": ["console"], + "level": "INFO", + }, + "objects": { + "handlers": ["console"], + "level": "INFO", + }, + "django_structlog": { + "handlers": ["console"], + "level": "INFO", + }, + }, + } + ) + + exception_processors = ( + [structlog.processors.format_exc_info] if formatter == "json" else [] + ) + structlog.configure( + processors=[ + structlog.contextvars.merge_contextvars, + structlog.stdlib.filter_by_level, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + structlog.processors.StackInfoRenderer(), + *exception_processors, + structlog.processors.UnicodeDecoder(), + structlog.stdlib.ProcessorFormatter.wrap_for_formatter, + ], + logger_factory=structlog.stdlib.LoggerFactory(), + cache_logger_on_first_use=True, + ) HEARTBEAT_FILE = Path(settings.BASE_DIR) / "tmp" / "celery_worker_heartbeat" diff --git a/src/objects/conf/base.py b/src/objects/conf/base.py index ee77df00..c1ad35b7 100644 --- a/src/objects/conf/base.py +++ b/src/objects/conf/base.py @@ -1,3 +1,6 @@ +from pathlib import Path + +import structlog from open_api_framework.conf.base import * # noqa from open_api_framework.conf.utils import config @@ -137,6 +140,7 @@ INSTALLED_APPS = INSTALLED_APPS + [ # Optional applications. "django.contrib.gis", + "django_structlog", # `django.contrib.sites` added at the project level because it has been removed at the packages level. # This component is deprecated and should be completely removed. # To determine the project's domain, use the `SITE_DOMAIN` environment variable. @@ -152,6 +156,227 @@ "objects.utils", ] +# XXX: this should be renamed to `LOG_REQUESTS` in the next major release +_log_requests_via_middleware = config( + "ENABLE_STRUCTLOG_REQUESTS", + default=True, + help_text=("enable structured logging of requests"), + group="Logging", +) +if _log_requests_via_middleware: + MIDDLEWARE.insert( + MIDDLEWARE.index("django.contrib.auth.middleware.AuthenticationMiddleware") + 1, + "django_structlog.middlewares.RequestMiddleware", + ) + +# TODO move this back to OAF +# Override LOGGING, because OAF does not yet apply structlog for all components +logging_root_handlers = ["console"] if LOG_STDOUT else ["json_file"] +LOGGING = { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + # structlog - foreign_pre_chain handles logs coming from stdlib logging module, + # while the `structlog.configure` call handles everything coming from structlog. + # They are mutually exclusive. + "json": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": structlog.processors.JSONRenderer(), + "foreign_pre_chain": [ + structlog.contextvars.merge_contextvars, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + ], + }, + "plain_console": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": structlog.dev.ConsoleRenderer(), + "foreign_pre_chain": [ + structlog.contextvars.merge_contextvars, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + ], + }, + "verbose": { + "format": "%(asctime)s %(levelname)s %(name)s %(module)s %(process)d %(thread)d %(message)s" + }, + "timestamped": {"format": "%(asctime)s %(levelname)s %(name)s %(message)s"}, + "simple": {"format": "%(levelname)s %(message)s"}, + "performance": {"format": "%(asctime)s %(process)d | %(thread)d | %(message)s"}, + "db": {"format": "%(asctime)s | %(message)s"}, + "outgoing_requests": {"()": HttpFormatter}, + }, + # TODO can be removed? + "filters": { + "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"}, + }, + "handlers": { + # TODO can be removed? + "mail_admins": { + "level": "ERROR", + "filters": ["require_debug_false"], + "class": "django.utils.log.AdminEmailHandler", + }, + "null": {"level": "DEBUG", "class": "logging.NullHandler"}, + "console": { + "level": LOG_LEVEL, + "class": "logging.StreamHandler", + "formatter": config( + "LOG_FORMAT_CONSOLE", + default="json", + help_text=( + "The format for the console logging handler, possible options: ``json``, ``plain_console``." + ), + group="Logging", + ), + }, + "console_db": { + "level": "DEBUG", + "class": "logging.StreamHandler", + "formatter": "db", + }, + "celery_console": { + "level": CELERY_LOGLEVEL, + "class": "logging.StreamHandler", + "formatter": "timestamped", + }, + "celery_file": { + "level": CELERY_LOGLEVEL, + "class": "logging.handlers.RotatingFileHandler", + "filename": Path(LOGGING_DIR) / "celery.log", + "formatter": "verbose", + "maxBytes": 1024 * 1024 * 10, # 10 MB + "backupCount": 10, + }, + # replaces the "django" and "project" handlers - in containerized applications + # the best practices is to log to stdout (use the console handler). + "json_file": { + "level": LOG_LEVEL, # always debug might be better? + "class": "logging.handlers.RotatingFileHandler", + "filename": Path(LOGGING_DIR) / "application.jsonl", + "formatter": "json", + "maxBytes": 1024 * 1024 * 10, # 10 MB + "backupCount": 10, + }, + "performance": { + "level": "INFO", + "class": "logging.handlers.RotatingFileHandler", + "filename": Path(LOGGING_DIR) / "performance.log", + "formatter": "performance", + "maxBytes": 1024 * 1024 * 10, # 10 MB + "backupCount": 10, + }, + "requests": { + "level": "DEBUG", + "class": "logging.handlers.RotatingFileHandler", + "filename": Path(LOGGING_DIR) / "requests.log", + "formatter": "timestamped", + "maxBytes": 1024 * 1024 * 10, # 10 MB + "backupCount": 10, + }, + "log_outgoing_requests": { + "level": "DEBUG", + "formatter": "outgoing_requests", + "class": "logging.StreamHandler", # to write to stdout + }, + "save_outgoing_requests": { + "level": "DEBUG", + # enabling saving to database + "class": "log_outgoing_requests.handlers.DatabaseOutgoingRequestsHandler", + }, + }, + "loggers": { + "": { + "handlers": logging_root_handlers, + "level": "ERROR", + "propagate": False, + }, + PROJECT_DIRNAME: { + "handlers": logging_root_handlers, + "level": LOG_LEVEL, + "propagate": False, + }, + "mozilla_django_oidc": { + "handlers": logging_root_handlers, + "level": LOG_LEVEL, + }, + f"{PROJECT_DIRNAME}.utils.middleware": { + "handlers": logging_root_handlers, + "level": LOG_LEVEL, + "propagate": False, + }, + "vng_api_common": { + "handlers": ["console"], + "level": LOG_LEVEL, + "propagate": True, + }, + "django.db.backends": { + "handlers": ["console_db"] if LOG_QUERIES else [], + "level": "DEBUG", + "propagate": False, + }, + "django.request": { + "handlers": logging_root_handlers, + "level": LOG_LEVEL, + "propagate": False, + }, + # suppress django.server request logs because those are already emitted by + # django-structlog middleware + "django.server": { + "handlers": ["console"], + "level": "WARNING" if _log_requests_via_middleware else "INFO", + "propagate": False, + }, + "django.template": { + "handlers": ["console"], + "level": "INFO", + "propagate": False, + }, + "log_outgoing_requests": { + "handlers": ( + ["log_outgoing_requests", "save_outgoing_requests"] + if LOG_REQUESTS + else ["save_outgoing_requests"] + ), + "level": "DEBUG", + "propagate": True, + }, + "django_structlog": { + "handlers": logging_root_handlers, + "level": "INFO", + "propagate": False, + }, + "celery": { + "handlers": ["celery_console"] if LOG_STDOUT else ["celery_file"], + "level": CELERY_LOGLEVEL, + "propagate": True, + }, + }, +} + +structlog.configure( + processors=[ + structlog.contextvars.merge_contextvars, + structlog.stdlib.filter_by_level, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + structlog.processors.StackInfoRenderer(), + structlog.processors.format_exc_info, + structlog.processors.UnicodeDecoder(), + # structlog.processors.ExceptionPrettyPrinter(), + structlog.stdlib.ProcessorFormatter.wrap_for_formatter, + ], + logger_factory=structlog.stdlib.LoggerFactory(), + cache_logger_on_first_use=True, +) + + # Internationalization # https://docs.djangoproject.com/en/3.0/topics/i18n/ @@ -230,3 +455,9 @@ ) NOTIFICATIONS_API_GET_DOMAIN = "objects.utils.get_domain" + +# +# DJANGO-STRUCTLOG +# +DJANGO_STRUCTLOG_IP_LOGGING_ENABLED = False +DJANGO_STRUCTLOG_CELERY_ENABLED = True diff --git a/src/objects/conf/ci.py b/src/objects/conf/ci.py index 019c705b..8e000a0b 100644 --- a/src/objects/conf/ci.py +++ b/src/objects/conf/ci.py @@ -2,9 +2,10 @@ Continuous integration settings module. """ -import logging import os +from open_api_framework.conf.utils import mute_logging + os.environ.setdefault("SECRET_KEY", "dummy") os.environ.setdefault("IS_HTTPS", "no") os.environ.setdefault("ENVIRONMENT", "ci") @@ -20,8 +21,7 @@ "oidc": {"BACKEND": "django.core.cache.backends.locmem.LocMemCache"}, } -LOGGING = None # Quiet is nice -logging.disable(logging.CRITICAL) +mute_logging(LOGGING) # diff --git a/src/objects/conf/dev.py b/src/objects/conf/dev.py index 9f2b0adf..78928aac 100644 --- a/src/objects/conf/dev.py +++ b/src/objects/conf/dev.py @@ -11,6 +11,7 @@ os.environ.setdefault("RELEASE", "dev") os.environ.setdefault("ENVIRONMENT", "development") os.environ.setdefault("DISABLE_2FA", "True") +os.environ.setdefault("LOG_FORMAT_CONSOLE", "plain_console") os.environ.setdefault("DB_NAME", "objects"), os.environ.setdefault("DB_USER", "objects"), @@ -29,29 +30,29 @@ "objects": { "handlers": ["console"], "level": "DEBUG", - "propagate": True, + "propagate": False, }, "django": { "handlers": ["console"], "level": "DEBUG", - "propagate": True, + "propagate": False, }, "django.db.backends": { - "handlers": ["django"], + "handlers": ["json_file"], "level": "DEBUG", "propagate": False, }, "performance": { "handlers": ["console"], "level": "INFO", - "propagate": True, + "propagate": False, }, # # See: https://code.djangoproject.com/ticket/30554 # Autoreload logs excessively, turn it down a bit. # "django.utils.autoreload": { - "handlers": ["django"], + "handlers": ["console"], "level": "INFO", "propagate": False, }, diff --git a/src/objects/conf/docker.py b/src/objects/conf/docker.py index 233c1a74..063f80f7 100644 --- a/src/objects/conf/docker.py +++ b/src/objects/conf/docker.py @@ -8,5 +8,6 @@ os.environ.setdefault("DB_HOST", config("DB_HOST", "db")) os.environ.setdefault("ENVIRONMENT", "docker") os.environ.setdefault("LOG_STDOUT", "yes") +os.environ.setdefault("LOG_FORMAT_CONSOLE", "json") from .production import * # noqa isort:skip diff --git a/src/objects/core/admin.py b/src/objects/core/admin.py index 6947a9ea..5b1a085c 100644 --- a/src/objects/core/admin.py +++ b/src/objects/core/admin.py @@ -1,5 +1,3 @@ -import logging - from django import forms from django.contrib import admin from django.contrib.gis.db.models import GeometryField @@ -7,13 +5,14 @@ from django.urls import path import requests +import structlog from vng_api_common.utils import get_help_text from objects.utils.client import get_objecttypes_client from .models import Object, ObjectRecord, ObjectType -logger = logging.getLogger(__name__) +logger = structlog.stdlib.get_logger(__name__) @admin.register(ObjectType) @@ -41,10 +40,8 @@ def versions_view(self, request, objecttype_id): with get_objecttypes_client(objecttype.service) as client: try: versions = client.list_objecttype_versions(objecttype.uuid) - except (requests.RequestException, requests.JSONDecodeError): - logger.exception( - "Something went wrong while fetching objecttype versions" - ) + except (requests.RequestException, requests.JSONDecodeError) as exc: + logger.exception("objecttypes_api_request_failure", exc_info=exc) return JsonResponse(versions, safe=False) diff --git a/src/objects/core/migrations/0022_move_object_types_to_separate_model.py b/src/objects/core/migrations/0022_move_object_types_to_separate_model.py index 030504c3..00c9b777 100644 --- a/src/objects/core/migrations/0022_move_object_types_to_separate_model.py +++ b/src/objects/core/migrations/0022_move_object_types_to_separate_model.py @@ -1,4 +1,4 @@ -import logging +import structlog from urllib.parse import urlsplit, urlunsplit from django.db import migrations @@ -6,7 +6,7 @@ from vng_api_common.utils import get_uuid_from_path -logger = logging.getLogger(__name__) +logger = structlog.stdlib.get_logger(__name__) def get_service(model, url: str): @@ -37,18 +37,18 @@ def move_objecttypes_to_model(apps, _): service = get_service(Service, object.object_type) if not service: logger.warning( - "object %s can't be migrated since it has invalid objecttype %s", - object, - object.object_type, + "missing_service_for_objecttype", + object=object, + object_type=object.object_type, ) continue try: uuid = get_uuid_from_path(object.object_type) except ValueError: logger.warning( - "object %s can't be migrated since it has invalid objecttype %s", - object, - object.object_type, + "invalid_objecttype", + object=object, + object_type=object.object_type, ) continue diff --git a/src/objects/setup.py b/src/objects/setup.py index 5e410b90..9fbafa4d 100644 --- a/src/objects/setup.py +++ b/src/objects/setup.py @@ -12,6 +12,7 @@ import os +import structlog from dotenv import load_dotenv @@ -21,3 +22,5 @@ def setup_env(): load_dotenv(dotenv_path) os.environ.setdefault("DJANGO_SETTINGS_MODULE", "objects.conf.dev") + + structlog.contextvars.bind_contextvars(source="app") diff --git a/src/objects/setup_configuration/steps/token_auth.py b/src/objects/setup_configuration/steps/token_auth.py index 5b0be199..7fcb075e 100644 --- a/src/objects/setup_configuration/steps/token_auth.py +++ b/src/objects/setup_configuration/steps/token_auth.py @@ -1,9 +1,9 @@ -import logging from typing import Any from django.core.exceptions import ObjectDoesNotExist, ValidationError from django.db import IntegrityError +import structlog from django_setup_configuration.configuration import BaseConfigurationStep from django_setup_configuration.exceptions import ConfigurationRunFailed @@ -13,7 +13,7 @@ ) from objects.token.models import Permission, TokenAuth -logger = logging.getLogger(__name__) +logger = structlog.stdlib.get_logger(__name__) class TokenAuthConfigurationStep( @@ -43,7 +43,7 @@ def _full_clean(self, instance: Any) -> None: def _configure_permissions(self, token: TokenAuth, permissions: list) -> None: if len(permissions) == 0: - logger.warning("No permissions provided for %s", token.identifier) + logger.warning("no_permissions_defined", token_identifier=token.identifier) for permission in permissions: try: @@ -82,10 +82,10 @@ def _configure_permissions(self, token: TokenAuth, permissions: list) -> None: def execute(self, model: TokenAuthGroupConfigurationModel) -> None: if len(model.items) == 0: - logger.warning("No tokens provided for configuration") + logger.warning("no_tokens_defined") for item in model.items: - logger.info("Configuring %s", item.identifier) + logger.info("configure_token", token_identifier=item.identifier) token_kwargs = { "identifier": item.identifier, @@ -101,7 +101,7 @@ def execute(self, model: TokenAuthGroupConfigurationModel) -> None: token_instance = TokenAuth(**token_kwargs) self._full_clean(token_instance) try: - logger.debug("Saving %s", item.identifier) + logger.debug("save_token_to_database", token_identifier=item.identifier) token, _ = TokenAuth.objects.update_or_create( identifier=item.identifier, defaults={ @@ -114,8 +114,11 @@ def execute(self, model: TokenAuthGroupConfigurationModel) -> None: self._configure_permissions(token, item.permissions) except IntegrityError as exception: + logger.exception( + "token_configuration_failure", token_identifier=item.identifier + ) raise ConfigurationRunFailed( "Failed configuring token %s" % item.identifier ) from exception - logger.info("Configured %s", item.identifier) + logger.info("token_configuration_success", token_identifier=item.identifier) diff --git a/src/objects/setup_configuration/tests/files/token_auth/no_tokens.yaml b/src/objects/setup_configuration/tests/files/token_auth/no_tokens.yaml new file mode 100644 index 00000000..06447b48 --- /dev/null +++ b/src/objects/setup_configuration/tests/files/token_auth/no_tokens.yaml @@ -0,0 +1,3 @@ +tokenauth_config_enable: true +tokenauth: + items: [] diff --git a/src/objects/setup_configuration/tests/test_token_auth_config.py b/src/objects/setup_configuration/tests/test_token_auth_config.py index 16a5eb49..b78d4557 100644 --- a/src/objects/setup_configuration/tests/test_token_auth_config.py +++ b/src/objects/setup_configuration/tests/test_token_auth_config.py @@ -421,6 +421,15 @@ def test_invalid_empty_identifier(self): self.assertTrue("String should match pattern" in str(command_error.exception)) self.assertEqual(TokenAuth.objects.count(), 0) + def test_valid_without_configured_tokens(self): + execute_single_step( + TokenAuthConfigurationStep, + yaml_source=str(DIR_FILES / "no_tokens.yaml"), + ) + + tokens = TokenAuth.objects.all() + self.assertEqual(tokens.count(), 0) + class TokenAuthConfigurationStepWithPermissionsTests(TokenTestCase): def test_valid_setup_default_without_permissions(self): diff --git a/src/objects/tests/utils.py b/src/objects/tests/utils.py index b4d9d3ea..9f7043f8 100644 --- a/src/objects/tests/utils.py +++ b/src/objects/tests/utils.py @@ -1,10 +1,7 @@ -import logging import os from requests_mock import Mocker -logger = logging.getLogger(__name__) - MOCK_FILES_DIR = os.path.join( os.path.abspath(os.path.dirname(__file__)), "schemas", diff --git a/src/objects/token/migrations/0017_tokenauth_identifier_alter_tokenauth_token.py b/src/objects/token/migrations/0017_tokenauth_identifier_alter_tokenauth_token.py index 544dc073..df2fb4a4 100644 --- a/src/objects/token/migrations/0017_tokenauth_identifier_alter_tokenauth_token.py +++ b/src/objects/token/migrations/0017_tokenauth_identifier_alter_tokenauth_token.py @@ -1,12 +1,12 @@ # Generated by Django 4.2.15 on 2024-12-11 10:07 -import logging +import structlog from django.db import migrations, models from django.db.migrations.state import StateApps import objects.token.validators -logger = logging.getLogger(__name__) +logger = structlog.stdlib.get_logger(__name__) def _generate_unique_identifiers(apps: StateApps, schema_editor) -> None: @@ -19,7 +19,9 @@ def _generate_unique_identifiers(apps: StateApps, schema_editor) -> None: count += 1 identifier = f"token-{count}" - logger.debug(f"Generated {identifier} for token {token.pk}") + logger.debug( + "token_identifier_generated", token_identifier=identifier, token_pk=token.pk + ) token.identifier = identifier token.save(update_fields=("identifier",)) diff --git a/src/objects/utils/serializers.py b/src/objects/utils/serializers.py index 8a69ab3f..dc4e51c4 100644 --- a/src/objects/utils/serializers.py +++ b/src/objects/utils/serializers.py @@ -1,4 +1,3 @@ -import logging from collections import defaultdict from glom import SKIP, GlomError, glom @@ -6,9 +5,6 @@ from objects.token.constants import PermissionModes -logger = logging.getLogger(__name__) - - ALL_FIELDS = ["*"] diff --git a/src/objects/utils/views.py b/src/objects/utils/views.py index 3c9b14a9..cb384c64 100644 --- a/src/objects/utils/views.py +++ b/src/objects/utils/views.py @@ -1,16 +1,15 @@ -import logging - from django import http from django.db.utils import DatabaseError from django.template import TemplateDoesNotExist, loader from django.views.decorators.csrf import requires_csrf_token from django.views.defaults import ERROR_500_TEMPLATE_NAME +import structlog from rest_framework import status from rest_framework.response import Response from rest_framework.views import exception_handler as drf_exception_handler -logger = logging.getLogger(__name__) +logger = structlog.stdlib.get_logger(__name__) @requires_csrf_token @@ -43,6 +42,6 @@ def exception_handler(exc, context): "detail": "This search operation is not supported by the underlying data store." } response = Response(status=status.HTTP_500_INTERNAL_SERVER_ERROR, data=data) - logger.exception(exc) + logger.exception("search_failed_for_datastore", exc_info=exc) return response diff --git a/src/objects/wsgi.py b/src/objects/wsgi.py index 6076faee..c0c0d69f 100644 --- a/src/objects/wsgi.py +++ b/src/objects/wsgi.py @@ -7,10 +7,29 @@ https://docs.djangoproject.com/en/3.0/howto/deployment/wsgi/ """ +from datetime import datetime, timezone + from django.core.wsgi import get_wsgi_application from objects.setup import setup_env +try: + import uwsgi # pyright: ignore[reportMissingModuleSource] uwsgi magic... +except ImportError: + uwsgi = None + setup_env() -application = get_wsgi_application() + +class LogVars: + def __init__(self, application): + self.application = application + + def __call__(self, environ, start_response): + if uwsgi is not None: + now = datetime.now(tz=timezone.utc) + uwsgi.set_logvar("iso8601timestamp", now.isoformat()) + return self.application(environ, start_response) + + +application = LogVars(get_wsgi_application())