From b5a243b1419f36e1a3c10b7cdbb7896c5f24728b Mon Sep 17 00:00:00 2001 From: Daniel Egger Date: Tue, 8 Feb 2022 18:50:56 +0100 Subject: [PATCH] Configure logging --- caprover_deploy.sh | 1 - server/config/settings/base.py | 42 ++++++++++--------- server/example.env | 2 +- server/log/.keep | 0 server/requirements/requirements-dev.txt | 2 + server/requirements/requirements.in | 1 + server/requirements/requirements.txt | 2 + .../vbv_lernwelt/core/middleware/security.py | 32 ++++++++++++++ server/vbv_lernwelt/core/utils.py | 17 +++++++- server/vbv_lernwelt/simpletodo/serializers.py | 5 +++ 10 files changed, 81 insertions(+), 23 deletions(-) delete mode 100644 server/log/.keep diff --git a/caprover_deploy.sh b/caprover_deploy.sh index ca81b52a..292cf0d7 100755 --- a/caprover_deploy.sh +++ b/caprover_deploy.sh @@ -6,4 +6,3 @@ docker push iterativ/vbv-lernwelt-django # deploy to caprover caprover deploy -h https://captain.control.iterativ.ch -a vbv-lernwelt -i docker.io/iterativ/vbv-lernwelt-django - diff --git a/server/config/settings/base.py b/server/config/settings/base.py index ede9cd1e..1ec76e78 100644 --- a/server/config/settings/base.py +++ b/server/config/settings/base.py @@ -7,7 +7,7 @@ from pathlib import Path import structlog from environs import Env -from vbv_lernwelt.core.utils import add_app_info +from vbv_lernwelt.core.utils import structlog_add_app_info SERVER_ROOT_DIR = Path(__file__).resolve(strict=True).parent.parent.parent # vbv_lernwelt/ @@ -135,6 +135,7 @@ AUTH_PASSWORD_VALIDATORS = [ # ------------------------------------------------------------------------------ # https://docs.djangoproject.com/en/dev/ref/settings/#middleware MIDDLEWARE = [ + "vbv_lernwelt.core.middleware.security.GetIpBehindReverseProxyMiddleWare", "django.middleware.security.SecurityMiddleware", "corsheaders.middleware.CorsMiddleware", "whitenoise.middleware.WhiteNoiseMiddleware", @@ -248,10 +249,6 @@ VBV_DJANGO_LOGGING_CONF = env( if VBV_DJANGO_LOGGING_CONF == "VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR": timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S") - pre_chain = [ - structlog.stdlib.add_log_level, - timestamper, - ] LOGGING = { "version": 1, "disable_existing_loggers": False, @@ -259,7 +256,10 @@ if VBV_DJANGO_LOGGING_CONF == "VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR": "colored": { "()": structlog.stdlib.ProcessorFormatter, "processor": structlog.dev.ConsoleRenderer(colors=True), - "foreign_pre_chain": pre_chain, + "foreign_pre_chain": [ + structlog.stdlib.add_log_level, + timestamper, + ], }, }, "handlers": { @@ -298,14 +298,25 @@ if VBV_DJANGO_LOGGING_CONF == "VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR": cache_logger_on_first_use=True, ) else: + shared_processors = [ + structlog.threadlocal.merge_threadlocal, + structlog.stdlib.add_log_level, + structlog.stdlib.add_logger_name, + structlog_add_app_info, + structlog.processors.TimeStamper(fmt="iso"), + ] + LOGGING = { "version": 1, "disable_existing_loggers": True, "formatters": { "json": { - "()": "pythonjsonlogger.jsonlogger.JsonFormatter", - "format": "%(asctime)s %(msecs)03d %(process)d %(thread)d %(levelname)s %(name)s %(filename)s %(lineno)d %(funcName)s %(message)s", # noqa I004 - "datefmt": "%Y-%m-%dT%H:%M:%S", + "()": structlog.stdlib.ProcessorFormatter, + "processors": [ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + structlog.processors.JSONRenderer() + ], + "foreign_pre_chain": shared_processors, }, }, "handlers": { @@ -332,7 +343,7 @@ else: "level": "WARNING", "propagate": False, }, - "vbc_lernwelt": { + "vbv_lernwelt": { "handlers": ["console", "file"], "level": "DEBUG", "propagate": False, @@ -346,16 +357,7 @@ else: } structlog.configure( - processors=[ - structlog.threadlocal.merge_threadlocal, - structlog.stdlib.filter_by_level, - add_app_info, - structlog.stdlib.PositionalArgumentsFormatter(), - structlog.processors.StackInfoRenderer(), - structlog.processors.format_exc_info, - structlog.processors.UnicodeDecoder(), - structlog.stdlib.render_to_log_kwargs, - ], + processors=shared_processors + [structlog.stdlib.ProcessorFormatter.wrap_for_formatter,], context_class=dict, logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, diff --git a/server/example.env b/server/example.env index 1c3ab747..f5e90aee 100644 --- a/server/example.env +++ b/server/example.env @@ -1,3 +1,3 @@ export VBV_DATABASE_URL='postgres://vbv_lernwelt@localhost:5432/vbv_lernwelt' -export VBV_DJANGO_LOGGING_CONF=VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR +#export VBV_DJANGO_LOGGING_CONF=VBV_DJANGO_LOGGING_CONF_CONSOLE_COLOR export VBV_DJANGO_DEBUG=True diff --git a/server/log/.keep b/server/log/.keep deleted file mode 100644 index e69de29b..00000000 diff --git a/server/requirements/requirements-dev.txt b/server/requirements/requirements-dev.txt index 45cb530a..b0cfb994 100644 --- a/server/requirements/requirements-dev.txt +++ b/server/requirements/requirements-dev.txt @@ -89,6 +89,8 @@ django-extensions==3.1.5 # via -r requirements-dev.in django-htmx==1.8.0 # via -r requirements.in +django-ipware==4.0.2 + # via -r requirements.in django-model-utils==4.2.0 # via -r requirements.in django-ratelimit==3.0.1 diff --git a/server/requirements/requirements.in b/server/requirements/requirements.in index e4912c88..ac184ff0 100644 --- a/server/requirements/requirements.in +++ b/server/requirements/requirements.in @@ -22,6 +22,7 @@ django-htmx dj-database-url django-click django-ratelimit +django-ipware psycopg2-binary gunicorn diff --git a/server/requirements/requirements.txt b/server/requirements/requirements.txt index 832163d7..5b212856 100644 --- a/server/requirements/requirements.txt +++ b/server/requirements/requirements.txt @@ -43,6 +43,8 @@ django-cors-headers==3.11.0 # via -r requirements.in django-htmx==1.8.0 # via -r requirements.in +django-ipware==4.0.2 + # via -r requirements.in django-model-utils==4.2.0 # via -r requirements.in django-ratelimit==3.0.1 diff --git a/server/vbv_lernwelt/core/middleware/security.py b/server/vbv_lernwelt/core/middleware/security.py index 6afd5472..5db8725f 100644 --- a/server/vbv_lernwelt/core/middleware/security.py +++ b/server/vbv_lernwelt/core/middleware/security.py @@ -1,6 +1,9 @@ import uuid import structlog +from django.core.exceptions import PermissionDenied +from django.http import Http404 +from ipware import get_client_ip from structlog.threadlocal import bind_threadlocal, clear_threadlocal from vbv_lernwelt.core.models import SecurityRequestResponseLog @@ -8,6 +11,19 @@ from vbv_lernwelt.core.models import SecurityRequestResponseLog logger = structlog.get_logger(__name__) +class GetIpBehindReverseProxyMiddleWare: + def __init__(self, get_response): + self.get_response = get_response + + def __call__(self, request): + client_ip, _is_routable = get_client_ip(request) + request.META['REMOTE_ADDR'] = client_ip + + response = self.get_response(request) + + return response + + class SecurityRequestResponseLoggingMiddleware: def __init__(self, get_response): self.get_response = get_response @@ -74,3 +90,19 @@ class SecurityRequestResponseLoggingMiddleware: def __call__(self, request): return self.log_request_response(request) + + def process_exception(self, request, exception): + if isinstance(exception, (Http404, PermissionDenied)): + # We don't log an exception here, and we don't set that we handled + # an error as we want the standard `request_finished` log message + # to be emitted. + return + + self._raised_exception = True + + self.bind_user_id(request), + logger.exception( + "request_failed", + code=500, + request=self.format_request(request), + ) diff --git a/server/vbv_lernwelt/core/utils.py b/server/vbv_lernwelt/core/utils.py index f4fc348d..ab4e3eba 100644 --- a/server/vbv_lernwelt/core/utils.py +++ b/server/vbv_lernwelt/core/utils.py @@ -1,11 +1,12 @@ import logging +import structlog from django.conf import settings from rest_framework.throttling import UserRateThrottle from structlog.types import EventDict -def add_app_info( +def structlog_add_app_info( logger: logging.Logger, method_name: str, event_dict: EventDict ) -> EventDict: event_dict["django_app"] = "vbv_lernwelt" @@ -15,6 +16,20 @@ def add_app_info( return event_dict +def structlog_inject_context_dict(test, level, event_dict): + """ + Add the structlog context dict to log events generated by the stdlib logging library. + """ + context_class = structlog.get_config().get('context_class') + + if context_class: + for key, value in context_class().items(): + if key not in event_dict: + event_dict[key] = value + + return event_dict + + class HourUserRateThrottle(UserRateThrottle): scope = "hour-throttle" diff --git a/server/vbv_lernwelt/simpletodo/serializers.py b/server/vbv_lernwelt/simpletodo/serializers.py index 4415b904..a4e86afb 100644 --- a/server/vbv_lernwelt/simpletodo/serializers.py +++ b/server/vbv_lernwelt/simpletodo/serializers.py @@ -1,8 +1,11 @@ +import structlog from rest_framework import serializers from rest_framework.serializers import ModelSerializer from vbv_lernwelt.simpletodo.models import SimpleTask, SimpleList +logger = structlog.get_logger(__name__) + class SimpleTaskSerializer(ModelSerializer): list_title = serializers.CharField(max_length=100) @@ -27,4 +30,6 @@ class SimpleTaskSerializer(ModelSerializer): simple_list, _ = SimpleList.objects.get_or_create(title=list_title, user=user) validated_data["list"] = simple_list + + logger.debug("Creating task", title=validated_data.get('title'), list_title=list_title) return super().create(validated_data)