diff --git a/.envs/.local/.django b/.envs/.local/.django index cc8243ac..ec36f614 100644 --- a/.envs/.local/.django +++ b/.envs/.local/.django @@ -11,3 +11,4 @@ CELERY_RESULT_BACKEND="redis://redis:6379/0" CELERY_FLOWER_USER=debug CELERY_FLOWER_PASSWORD=debug +DJANGO_STRUCTLOG_CACHE="redis://redis:6379/0" diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml index 69606070..e6ff8ef3 100644 --- a/.github/workflows/main.yml +++ b/.github/workflows/main.yml @@ -32,6 +32,7 @@ jobs: - name: Test demo app env: CELERY_BROKER_URL: redis://0.0.0.0:6379 + DJANGO_STRUCTLOG_CACHE: redis://0.0.0.0:6379 DJANGO_SETTINGS_MODULE: config.settings.test_demo_app run: pytest --cov=./django_structlog_demo_project --cov-append django_structlog_demo_project - uses: codecov/codecov-action@v5 diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index bda50b46..ee4f0fc4 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -20,7 +20,7 @@ repos: args: [--no-incremental] additional_dependencies: [ celery-types==0.23.0, - "django-stubs[compatible-mypy]==5.2.5", + "django-stubs[compatible-mypy]==5.2.8", structlog==25.2.0, django-extensions==4.1, django-ipware==7.0.1, diff --git a/README.rst b/README.rst index b8016dba..216dfa59 100644 --- a/README.rst +++ b/README.rst @@ -328,7 +328,7 @@ In your formatters, add the ``foreign_pre_chain`` section, and then add ``struct ], }, }, - ... + #... } @@ -357,7 +357,7 @@ Flat lines file (\ ``logs/flat_lines.log``\ ) Json file (\ ``logs/json.log``\ ) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ -.. code-block:: json +.. code-block:: jsonl {"request_id": "c53dff1d-3fc5-4257-a78a-9a567c937561", "user_id": 1, "ip": "0.0.0.0", "request": "GET /", "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.86 Safari/537.36", "event": "request_started", "timestamp": "2019-04-13T19:39:29.321453Z", "logger": "django_structlog.middlewares.request", "level": "info"} {"request_id": "c53dff1d-3fc5-4257-a78a-9a567c937561", "user_id": 1, "ip": "0.0.0.0", "code": 200, "event": "request_finished", "timestamp": "2019-04-13T19:39:29.345207Z", "logger": "django_structlog.middlewares.request", "level": "info"} @@ -624,7 +624,7 @@ Changes you need to do ], }, }, - ... + #... } @@ -662,8 +662,8 @@ Note: For the moment redis is needed to run the tests. The easiest way is to sta docker compose up -d redis pip install -r requirements.txt - env CELERY_BROKER_URL=redis://0.0.0.0:6379 DJANGO_SETTINGS_MODULE=config.settings.test pytest test_app - env CELERY_BROKER_URL=redis://0.0.0.0:6379 DJANGO_SETTINGS_MODULE=config.settings.test_demo_app pytest django_structlog_demo_project + env DJANGO_SETTINGS_MODULE=config.settings.test pytest test_app + env DJANGO_SETTINGS_MODULE=config.settings.test_demo_app pytest django_structlog_demo_project docker compose stop redis .. inclusion-marker-running-tests-end diff --git a/compose/local/django/entrypoint b/compose/local/django/entrypoint index 9255ee0f..122cb315 100644 --- a/compose/local/django/entrypoint +++ b/compose/local/django/entrypoint @@ -4,12 +4,6 @@ set -o errexit set -o pipefail set -o nounset - - -# N.B. If only .env files supported variable expansion... -export CELERY_BROKER_URL="${CELERY_BROKER_URL}" - - if [ -z "${POSTGRES_USER}" ]; then base_postgres_image_default_user='postgres' export POSTGRES_USER="${base_postgres_image_default_user}" diff --git a/config/settings/base.py b/config/settings/base.py index 3ea43200..3cd4d834 100644 --- a/config/settings/base.py +++ b/config/settings/base.py @@ -263,8 +263,27 @@ def serve(self, request): # https://django-allauth.readthedocs.io/en/latest/configuration.html ACCOUNT_ADAPTER = "django_structlog_demo_project.users.adapters.AccountAdapter" - -# Your stuff... +# Django's Tasks Framework # ------------------------------------------------------------------------------ +# https://docs.djangoproject.com/en/dev/topics/tasks/ +TASKS = { + "default": { + # This task backend runs synchronously on the same thread. + # This makes it appear that "django_structlog" works with Django task framework, + # but it's only because they are in the same thread-local context. + "BACKEND": "django.tasks.backends.immediate.ImmediateBackend", + }, +} + +CACHES = { + "default": { + "BACKEND": "django.core.cache.backends.locmem.LocMemCache", + }, + "django_structlog": { + "BACKEND": "django.core.cache.backends.redis.RedisCache", + "LOCATION": env("DJANGO_STRUCTLOG_CACHE"), + }, +} + INSTALLED_APPS += ["django_structlog"] diff --git a/config/settings/local.py b/config/settings/local.py index aa84ba4d..6371127b 100644 --- a/config/settings/local.py +++ b/config/settings/local.py @@ -18,16 +18,6 @@ IS_WORKER = env.bool("IS_WORKER", default=False) -# CACHES -# ------------------------------------------------------------------------------ -# https://docs.djangoproject.com/en/dev/ref/settings/#caches -CACHES = { - "default": { - "BACKEND": "django.core.cache.backends.locmem.LocMemCache", - "LOCATION": "", - } -} - # TEMPLATES # ------------------------------------------------------------------------------ # https://docs.djangoproject.com/en/dev/ref/settings/#templates @@ -168,3 +158,4 @@ DJANGO_STRUCTLOG_CELERY_ENABLED = True DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED = True +DJANGO_STRUCTLOG_DJANGO_TASKS_ENABLED = True diff --git a/config/settings/test.py b/config/settings/test.py index 48dca473..f08fe091 100644 --- a/config/settings/test.py +++ b/config/settings/test.py @@ -47,7 +47,11 @@ "default": { "BACKEND": "django.core.cache.backends.locmem.LocMemCache", "LOCATION": "", - } + }, + "django_structlog": { + "BACKEND": "django.core.cache.backends.locmem.LocMemCache", + "LOCATION": "", + }, } # EMAIL diff --git a/config/urls.py b/config/urls.py index 4eb77072..0f06bd81 100644 --- a/config/urls.py +++ b/config/urls.py @@ -20,6 +20,12 @@ def uncaught_exception_view(request): ), re_path(r"^failing_task$", views.enqueue_failing_task, name="enqueue_failing_task"), re_path(r"^nesting_task$", views.enqueue_nesting_task, name="enqueue_nesting_task"), + re_path(r"^django_task$", views.enqueue_django_task, name="enqueue_django_task"), + re_path( + r"^django_failing_task$", + views.enqueue_django_failing_task, + name="enqueue_django_failing_task", + ), re_path(r"^unknown_task$", views.enqueue_unknown_task, name="enqueue_unknown_task"), re_path( r"^rejected_task$", views.enqueue_rejected_task, name="enqueue_rejected_task" diff --git a/django_structlog/app_settings.py b/django_structlog/app_settings.py index 72e0dd3b..1f202015 100644 --- a/django_structlog/app_settings.py +++ b/django_structlog/app_settings.py @@ -11,6 +11,10 @@ class AppSettings: def CELERY_ENABLED(self) -> bool: return getattr(settings, self.PREFIX + "CELERY_ENABLED", False) + @property + def DJANGO_TASKS_ENABLED(self) -> bool: + return getattr(settings, self.PREFIX + "DJANGO_TASKS_ENABLED", False) + @property def IP_LOGGING_ENABLED(self) -> bool: return getattr(settings, self.PREFIX + "IP_LOGGING_ENABLED", True) diff --git a/django_structlog/apps.py b/django_structlog/apps.py index 4fdb3689..4f635595 100644 --- a/django_structlog/apps.py +++ b/django_structlog/apps.py @@ -18,3 +18,9 @@ def ready(self) -> None: self._django_command_receiver = DjangoCommandReceiver() self._django_command_receiver.connect_signals() + + if app_settings.DJANGO_TASKS_ENABLED: + from .tasks.receivers import DjangoTaskReceiver + + self._django_task_receiver = DjangoTaskReceiver() + self._django_task_receiver.connect_signals() diff --git a/django_structlog/celery/receivers.py b/django_structlog/celery/receivers.py index 9d07f321..cb76ce46 100644 --- a/django_structlog/celery/receivers.py +++ b/django_structlog/celery/receivers.py @@ -15,6 +15,7 @@ task_unknown, ) +from ..tasks.receivers import BaseTaskReceiver from . import signals if TYPE_CHECKING: # pragma: no cover @@ -23,7 +24,7 @@ logger = structlog.getLogger(__name__) -class CeleryReceiver: +class CeleryReceiver(BaseTaskReceiver): _priority: Optional[str] def __init__(self) -> None: @@ -41,10 +42,7 @@ def receiver_before_task_publish( if current_app.conf.task_protocol < 2: return - context = structlog.contextvars.get_merged_contextvars(logger) - if "task_id" in context: - context["parent_task_id"] = context.pop("task_id") - + context = self.get_task_context() signals.modify_context_before_task_publish.send( sender=self.receiver_before_task_publish, context=context, @@ -90,7 +88,7 @@ def receiver_task_prerun( structlog.contextvars.clear_contextvars() structlog.contextvars.bind_contextvars(task_id=task_id) metadata = getattr(task.request, "__django_structlog__", {}) - structlog.contextvars.bind_contextvars(**metadata) + self.bind_context(metadata) signals.bind_extra_task_metadata.send( sender=self.receiver_task_prerun, task=task, logger=logger ) diff --git a/django_structlog/tasks/__init__.py b/django_structlog/tasks/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/django_structlog/tasks/receivers.py b/django_structlog/tasks/receivers.py new file mode 100644 index 00000000..14df3b04 --- /dev/null +++ b/django_structlog/tasks/receivers.py @@ -0,0 +1,102 @@ +from typing import TYPE_CHECKING, Any, Type + +import django +import structlog +from django.core.cache import caches + +from django_structlog.tasks import signals + +logger = structlog.getLogger(__name__) + +if TYPE_CHECKING: # pragma: no cover + if django.VERSION >= (6, 0): + from django.tasks.base import TaskResult # type: ignore[import-untyped] + else: + TaskResult = Any + + +class BaseTaskReceiver: + def get_task_context(self) -> dict[str, Any]: + context = structlog.contextvars.get_merged_contextvars(logger) + if "task_id" in context: + context["parent_task_id"] = context.pop("task_id") + return context + + def bind_context(self, context: dict[Any, Any] | Any) -> None: + structlog.contextvars.bind_contextvars(**context) + + +class DjangoTaskReceiver(BaseTaskReceiver): + + def __init__(self) -> None: + self.cache = caches["django_structlog"] + + def receiver_task_enqueued( + self, + sender: Type[Any], + task_result: "TaskResult", + **kwargs: dict[str, str], + ) -> None: + context = self.get_task_context() + logger.info( + "task_enqueued", + task_id=task_result.id, + task_name=task_result.task.module_path, + ) + signals.modify_context_before_task_publish.send( + sender=self.receiver_task_enqueued, + context=context, + ) + self.cache.set(task_result.id, context) + + def receiver_task_started( + self, + sender: Type[Any], + task_result: "TaskResult", + **kwargs: dict[str, str], + ) -> None: + structlog.contextvars.clear_contextvars() + structlog.contextvars.bind_contextvars(task_id=task_result.id) + context = self.cache.get(task_result.id, default={}) + self.bind_context(context) + signals.bind_extra_task_metadata.send( + sender=self.receiver_task_started, task_result=task_result, logger=logger + ) + logger.info( + "task_started", + task=task_result.task.module_path, + ) + + def receiver_task_finished( + self, + sender: Type[Any], + task_result: "TaskResult", + **kwargs: dict[str, str], + ) -> None: + from django.tasks.base import TaskResultStatus + + log_vars: dict[str, Any] = {} + if task_result.status == TaskResultStatus.SUCCESSFUL: + signals.pre_task_succeeded.send( + sender=self.receiver_task_finished, + logger=logger, + task_result=task_result, + ) + logger.info("task_succeeded", **log_vars) + elif task_result.status == TaskResultStatus.FAILED: + if task_result.errors: + last_error = task_result.errors[-1] # Get the last error + log_vars["exception_class"] = last_error.exception_class_path + log_vars["traceback"] = last_error.traceback + logger.error("task_failed", **log_vars) + + def connect_signals(self) -> None: + from django.tasks.signals import ( # type: ignore[import-untyped] + task_enqueued, + task_finished, + task_started, + ) + + task_started.connect(self.receiver_task_started) + task_finished.connect(self.receiver_task_finished) + task_enqueued.connect(self.receiver_task_enqueued) diff --git a/django_structlog/tasks/signals.py b/django_structlog/tasks/signals.py new file mode 100644 index 00000000..f01b3291 --- /dev/null +++ b/django_structlog/tasks/signals.py @@ -0,0 +1,57 @@ +import django.dispatch + +bind_extra_task_metadata = django.dispatch.Signal() +""" Signal to add extra ``structlog`` bindings from ``celery``'s task. + +:param task: the celery task being run +:param logger: the logger to bind more metadata or override existing bound metadata + +>>> from django.dispatch import receiver +>>> from django_structlog.celery import signals +>>> import structlog +>>> +>>> @receiver(signals.bind_extra_task_metadata) +... def receiver_bind_extra_task_metadata(sender, signal, task=None, logger=None, **kwargs): +... structlog.contextvars.bind_contextvars(correlation_id=task.request.correlation_id) + +""" + + +modify_context_before_task_publish = django.dispatch.Signal() +""" Signal to modify context passed over to ``celery`` task's context. You must modify the ``context`` dict. + +:param context: the context dict that will be passed over to the task runner's logger +:param task_routing_key: routing key of the task +:param task_properties: task's message properties + +>>> from django.dispatch import receiver +>>> from django_structlog.celery import signals +>>> +>>> @receiver(signals.modify_context_before_task_publish) +... def receiver_modify_context_before_task_publish(sender, signal, context, task_routing_key=None, task_properties=None, **kwargs): +... keys_to_keep = {"request_id", "parent_task_id"} +... new_dict = { +... key_to_keep: context[key_to_keep] +... for key_to_keep in keys_to_keep +... if key_to_keep in context +... } +... context.clear() +... context.update(new_dict) + +""" + +pre_task_succeeded = django.dispatch.Signal() +""" Signal to add ``structlog`` bindings from ``celery``'s successful task. + +:param logger: the logger to bind more metadata or override existing bound metadata +:param result: result of the succeeding task + +>>> from django.dispatch import receiver +>>> from django_structlog.celery import signals +>>> import structlog +>>> +>>> @receiver(signals.pre_task_succeeded) +... def receiver_pre_task_succeeded(sender, signal, logger=None, result=None, **kwargs): +... structlog.contextvars.bind_contextvars(result=str(result)) + +""" diff --git a/django_structlog_demo_project/home/tests/test_views.py b/django_structlog_demo_project/home/tests/test_views.py index 8c28da59..ef27f236 100644 --- a/django_structlog_demo_project/home/tests/test_views.py +++ b/django_structlog_demo_project/home/tests/test_views.py @@ -93,3 +93,33 @@ def test(self, mocker): assert b"4" == next(response.streaming_content) with pytest.raises(StopIteration): next(response.streaming_content) + + +class TestEnqueueDjangoTask: + def test_django6(self, caplog, mocker): + mock_task = mocker.patch( + "django_structlog_demo_project.home.views.django_task", + ) + + response = views.enqueue_django_task(None) + assert response.status_code == 201 + + mock_task.enqueue.assert_called_once() + + assert len(caplog.records) == 1 + record = caplog.records[0] + assert "Enqueuing Django 6 native task" in record.msg["event"] + + def test_django6_failing(self, caplog, mocker): + mock_task = mocker.patch( + "django_structlog_demo_project.home.views.django_failing_task", + ) + + response = views.enqueue_django_failing_task(None) + assert response.status_code == 201 + + mock_task.enqueue.assert_called_once() + + assert len(caplog.records) == 1 + record = caplog.records[0] + assert "Enqueuing Django 6 native failing task" in record.msg["event"] diff --git a/django_structlog_demo_project/home/views.py b/django_structlog_demo_project/home/views.py index 4dc746a7..7fb03591 100644 --- a/django_structlog_demo_project/home/views.py +++ b/django_structlog_demo_project/home/views.py @@ -11,6 +11,10 @@ rejected_task, successful_task, ) +from django_structlog_demo_project.tasks import ( + django_failing_task, + django_task, +) logger = structlog.get_logger(__name__) @@ -33,6 +37,18 @@ def enqueue_nesting_task(request): return HttpResponse(status=201) +def enqueue_django_task(request): + logger.info("Enqueuing Django 6 native task") + django_task.enqueue() + return HttpResponse(status=201) + + +def enqueue_django_failing_task(request): + logger.info("Enqueuing Django 6 native failing task") + django_failing_task.enqueue() + return HttpResponse(status=201) + + def log_with_standard_logger(request): logging.getLogger("foreign_logger").info("This is a standard logger") return HttpResponse(status=200) diff --git a/django_structlog_demo_project/tasks.py b/django_structlog_demo_project/tasks.py new file mode 100644 index 00000000..0b3ac35e --- /dev/null +++ b/django_structlog_demo_project/tasks.py @@ -0,0 +1,18 @@ +import structlog +from django.tasks import task + +logger = structlog.getLogger(__name__) + + +@task +def django_task(): + logger.info("This is a Django 6 native task using the built-in task framework") + + return "ok" + + +@task +def django_failing_task(): + logger.info("This is a failing Django 6 native task") + + raise ValueError("Intentional failure in Django task") diff --git a/django_structlog_demo_project/templates/pages/home.html b/django_structlog_demo_project/templates/pages/home.html index a37fd15b..5b494e26 100644 --- a/django_structlog_demo_project/templates/pages/home.html +++ b/django_structlog_demo_project/templates/pages/home.html @@ -138,6 +138,24 @@
Celery
+
+
+
Django Task Framework
+
+ + + +
+
+
{% endblock %} diff --git a/django_structlog_demo_project/tests/__init__.py b/django_structlog_demo_project/tests/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/django_structlog_demo_project/tests/test_tasks.py b/django_structlog_demo_project/tests/test_tasks.py new file mode 100644 index 00000000..731d0de2 --- /dev/null +++ b/django_structlog_demo_project/tests/test_tasks.py @@ -0,0 +1,33 @@ +import logging + +import pytest + +from .. import tasks + +pytestmark = pytest.mark.django_db + + +class TestDjangoTask: + def test(self, caplog): + with caplog.at_level( + logging.INFO, logger="django_structlog_demo_project.tasks" + ): + task_result = tasks.django_task.enqueue() + assert task_result.return_value == "ok" + + assert len(caplog.records) == 3 + record = caplog.records[1] + assert ( + record.msg["event"] + == "This is a Django 6 native task using the built-in task framework" + ) + + def test_failing(self, caplog): + with caplog.at_level( + logging.INFO, logger="django_structlog_demo_project.tasks" + ): + tasks.django_failing_task.enqueue() + + assert len(caplog.records) == 3 + record = caplog.records[1] + assert record.msg["event"] == "This is a failing Django 6 native task" diff --git a/pyproject.toml b/pyproject.toml index 93e9c950..b6703f4a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -22,9 +22,8 @@ build-backend = "setuptools.build_meta" "Development Status :: 5 - Production/Stable", "Framework :: Django", "Framework :: Django :: 4.2", - "Framework :: Django :: 5.0", - "Framework :: Django :: 5.1", "Framework :: Django :: 5.2", + "Framework :: Django :: 6.0", "Programming Language :: Python :: 3", "Programming Language :: Python :: 3 :: Only", "Programming Language :: Python :: 3.10", @@ -94,6 +93,10 @@ build-backend = "setuptools.build_meta" [tool.pytest.ini_options] DJANGO_SETTINGS_MODULE = "config.settings.test_demo_app" + env = [ + "D:CELERY_BROKER_URL=redis://0.0.0.0:6379", + "D:DJANGO_STRUCTLOG_CACHE=redis://0.0.0.0:6379" + ] [tool.tox] legacy_tox_ini = """ @@ -103,11 +106,9 @@ build-backend = "setuptools.build_meta" # Also, make sure that all python versions used here are included in ./github/worksflows/main.yml envlist = py{310,311}-django42-celery5{2,3}-redis4-kombu5, - py31{0,1}-django5{0,1,2}-celery5{3,4}-redis4-kombu5, - py312-django{42,50,51,52}-celery5{3,4}-redis4-kombu5, - py313-django51-celery5{3,4}-redis5-kombu5, - py31{3,4}-django52-celery5{3,4}-redis5-kombu5, - + py31{0,1}-django52-celery5{3,4}-redis4-kombu5, + py312-django{42,52,60}-celery5{3,4}-redis4-kombu5, + py31{3,4}-django{52,60}-celery5{3,4}-redis5-kombu5, [gh-actions] python = 3.10: py310 @@ -120,6 +121,7 @@ build-backend = "setuptools.build_meta" setenv = PYTHONPATH={toxinidir} CELERY_BROKER_URL=redis://0.0.0.0:6379 + DJANGO_STRUCTLOG_CACHE: redis://0.0.0.0:6379 CELERY_RESULT_BACKEND=redis://0.0.0.0:6379 DJANGO_SETTINGS_MODULE=config.settings.test pip_pre = True @@ -132,9 +134,8 @@ build-backend = "setuptools.build_meta" celery53: Celery >=5.3, <5.4 celery54: Celery >=5.4, <5.5 django42: Django >=4.2, <5.0 - django50: Django >=5.0, <5.1 - django51: Django >=5.1, <5.2 django52: Django >=5.2, <6.0 + django60: Django >=6.0, <6.1 -r{toxinidir}/requirements/ci.txt commands = pytest --cov=./test_app --cov=./django_structlog --cov-append test_app diff --git a/requirements/ci.txt b/requirements/ci.txt index be169b8b..4580cf10 100644 --- a/requirements/ci.txt +++ b/requirements/ci.txt @@ -14,6 +14,7 @@ psycopg[binary]==3.2.12 # https://github.com/psycopg/psycopg pytest==9.0.2 # https://github.com/pytest-dev/pytest pytest-sugar==1.1.1 # https://github.com/Frozenball/pytest-sugar pytest-cov==7.0.0 +pytest-env==1.2.0 # https://github.com/pytest-dev/pytest-env # Code quality # ------------------------------------------------------------------------------ diff --git a/requirements/local-base.txt b/requirements/local-base.txt index 6a65ccf2..80c73d3d 100644 --- a/requirements/local-base.txt +++ b/requirements/local-base.txt @@ -3,7 +3,7 @@ python-slugify==8.0.4 # https://github.com/un33k/python-slugify # Django # ------------------------------------------------------------------------------ -django==5.2.8 # https://www.djangoproject.com/ +django==6.0 # https://www.djangoproject.com/ django-environ==0.12.0 # https://github.com/joke2k/django-environ django-model-utils==5.0.0 # https://github.com/jazzband/django-model-utils django-allauth==65.13.1 # https://github.com/pennersr/django-allauth @@ -17,7 +17,7 @@ djangorestframework==3.16.1 # https://github.com/encode/django-rest-framework coreapi==2.3.3 # https://github.com/core-api/python-client # django-ninja -django-ninja==1.5.0 # https://github.com/vitalik/django-ninja +django-ninja==1.5.1 # https://github.com/vitalik/django-ninja structlog==25.5.0 colorama==0.4.6 @@ -34,6 +34,7 @@ pytest-sugar==1.1.1 # https://github.com/Frozenball/pytest-sugar pytest-cov==7.0.0 pytest-asyncio==1.3.0 # https://github.com/pytest-dev/pytest-asyncio pytest-mock==3.15.1 # https://github.com/pytest-dev/pytest-mock +pytest-env==1.2.0 # https://github.com/pytest-dev/pytest-env # Code quality # ------------------------------------------------------------------------------ diff --git a/requirements/mypy.txt b/requirements/mypy.txt index d1a881ac..fe5de8ca 100644 --- a/requirements/mypy.txt +++ b/requirements/mypy.txt @@ -1,3 +1,3 @@ mypy==1.18.2 celery-types==0.23.0 -django-stubs[compatible-mypy]==5.2.7 +django-stubs[compatible-mypy]==5.2.8 diff --git a/test_app/tests/tasks/__init__.py b/test_app/tests/tasks/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/test_app/tests/tasks/test_receivers.py b/test_app/tests/tasks/test_receivers.py new file mode 100644 index 00000000..64f090e8 --- /dev/null +++ b/test_app/tests/tasks/test_receivers.py @@ -0,0 +1,392 @@ +import logging +import unittest +from typing import Any, Type +from unittest.mock import Mock, call, patch + +import django +import structlog +from django.core.cache import caches +from django.dispatch import receiver as django_receiver +from django.test import TestCase + +from django_structlog.tasks import receivers, signals + +if django.VERSION >= (6, 0): + from django.tasks.base import ( # type: ignore[import-untyped] + TaskResult, + TaskResultStatus, + ) + + +@unittest.skipIf(django.VERSION < (6, 0), "Django 6.0+ required for native tasks") +class TestReceivers(TestCase): + def setUp(self) -> None: + self.logger = structlog.getLogger(__name__) + self.cache = caches["django_structlog"] + + def tearDown(self) -> None: + structlog.contextvars.clear_contextvars() + self.cache.clear() + + def test_receiver_task_enqueued(self) -> None: + expected_uuid = "00000000-0000-0000-0000-000000000000" + expected_task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + + structlog.contextvars.bind_contextvars(request_id=expected_uuid) + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = expected_task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.INFO + ) as log_results: + receiver.receiver_task_enqueued( + sender=mock_sender, task_result=mock_task_result + ) + + self.assertEqual(1, len(log_results.records)) + record: Any = log_results.records[0] + self.assertEqual("task_enqueued", record.msg["event"]) + self.assertEqual("INFO", record.levelname) + self.assertEqual(expected_task_id, record.msg["task_id"]) + self.assertEqual(expected_task_name, record.msg["task_name"]) + + cached_context = self.cache.get(expected_task_id) + self.assertIsNotNone(cached_context) + self.assertEqual(expected_uuid, cached_context["request_id"]) + + def test_signal_modify_context_before_task_publish(self) -> None: + expected_uuid = "00000000-0000-0000-0000-000000000000" + user_id = "1234" + expected_parent_task_uuid = "11111111-1111-1111-1111-111111111111" + expected_task_id = "22222222-2222-2222-2222-222222222222" + expected_task_name = "test_app.tasks.test_task" + + @django_receiver(signals.modify_context_before_task_publish) + def receiver_modify_context_before_task_publish( + sender: Type[Any], + signal: Any, + context: Any, + **kwargs: Any, + ) -> None: + keys_to_keep = {"request_id", "parent_task_id"} + new_dict = { + key_to_keep: context[key_to_keep] + for key_to_keep in keys_to_keep + if key_to_keep in context + } + context.clear() + context.update(new_dict) + + structlog.contextvars.bind_contextvars( + request_id=expected_uuid, + user_id=user_id, + task_id=expected_parent_task_uuid, + ) + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = expected_task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + receiver.receiver_task_enqueued( + sender=mock_sender, task_result=mock_task_result + ) + + cached_context = self.cache.get(expected_task_id) + self.assertIsNotNone(cached_context) + self.assertEqual(expected_uuid, cached_context["request_id"]) + self.assertEqual(expected_parent_task_uuid, cached_context["parent_task_id"]) + self.assertNotIn("user_id", cached_context) + + def test_receiver_task_started(self) -> None: + expected_request_uuid = "00000000-0000-0000-0000-000000000000" + task_id = "11111111-1111-1111-1111-111111111111" + expected_user_id = "1234" + expected_task_name = "test_app.tasks.test_task" + + self.cache.set( + task_id, + { + "request_id": expected_request_uuid, + "user_id": expected_user_id, + }, + ) + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + + structlog.contextvars.bind_contextvars(foo="bar") + context = structlog.contextvars.get_merged_contextvars(self.logger) + self.assertDictEqual({"foo": "bar"}, context) + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.INFO + ) as log_results: + receiver.receiver_task_started( + sender=mock_sender, task_result=mock_task_result + ) + + context = structlog.contextvars.get_merged_contextvars(self.logger) + self.assertDictEqual( + { + "task_id": task_id, + "request_id": expected_request_uuid, + "user_id": expected_user_id, + }, + context, + ) + + self.assertEqual(1, len(log_results.records)) + record: Any = log_results.records[0] + self.assertEqual("task_started", record.msg["event"]) + self.assertEqual("INFO", record.levelname) + self.assertEqual(expected_task_name, record.msg["task"]) + + def test_signal_bind_extra_task_metadata(self) -> None: + @django_receiver(signals.bind_extra_task_metadata) + def receiver_bind_extra_task_metadata( + sender: Type[Any], signal: Any, task_result: Any = None, logger: Any = None + ) -> None: + structlog.contextvars.bind_contextvars( + custom_field=task_result.custom_field + ) + + expected_custom_value = "custom_value" + task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + + self.cache.set(task_id, {}) + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + mock_task_result.custom_field = expected_custom_value + + structlog.contextvars.bind_contextvars(foo="bar") + context = structlog.contextvars.get_merged_contextvars(self.logger) + self.assertDictEqual({"foo": "bar"}, context) + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + receiver.receiver_task_started(sender=mock_sender, task_result=mock_task_result) + context = structlog.contextvars.get_merged_contextvars(self.logger) + + self.assertEqual(context["custom_field"], expected_custom_value) + self.assertEqual(context["task_id"], task_id) + + def test_receiver_task_finished_success(self) -> None: + task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + mock_task_result.status = TaskResultStatus.SUCCESSFUL + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.INFO + ) as log_results: + receiver.receiver_task_finished( + sender=mock_sender, task_result=mock_task_result + ) + + self.assertEqual(1, len(log_results.records)) + record: Any = log_results.records[0] + self.assertEqual("task_succeeded", record.msg["event"]) + self.assertEqual("INFO", record.levelname) + + def test_signal_pre_task_succeeded(self) -> None: + expected_result_value = "result_value" + + @django_receiver(signals.pre_task_succeeded) + def receiver_pre_task_succeeded( + sender: Type[Any], + signal: Any, + task_result: Any = None, + logger: Any = None, + ) -> None: + structlog.contextvars.bind_contextvars(result=task_result.return_value) + + task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + mock_task_result.status = TaskResultStatus.SUCCESSFUL + mock_task_result.return_value = expected_result_value + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.INFO + ) as log_results: + receiver.receiver_task_finished( + sender=mock_sender, task_result=mock_task_result + ) + + self.assertEqual(1, len(log_results.records)) + record: Any = log_results.records[0] + self.assertEqual("task_succeeded", record.msg["event"]) + self.assertEqual("INFO", record.levelname) + self.assertIn("result", record.msg) + self.assertEqual(expected_result_value, record.msg["result"]) + + def test_receiver_task_finished_failed(self) -> None: + task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + expected_exception_class = "builtins.ValueError" + expected_traceback = ( + "Traceback (most recent call last):\n File...\nValueError: test error" + ) + + mock_error = Mock() + mock_error.exception_class_path = expected_exception_class + mock_error.traceback = expected_traceback + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + mock_task_result.status = TaskResultStatus.FAILED + mock_task_result.errors = [mock_error] + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.ERROR + ) as log_results: + receiver.receiver_task_finished( + sender=mock_sender, task_result=mock_task_result + ) + + self.assertEqual(1, len(log_results.records)) + record: Any = log_results.records[0] + self.assertEqual("task_failed", record.msg["event"]) + self.assertEqual("ERROR", record.levelname) + self.assertIn("exception_class", record.msg) + self.assertEqual(expected_exception_class, record.msg["exception_class"]) + self.assertIn("traceback", record.msg) + self.assertEqual(expected_traceback, record.msg["traceback"]) + + def test_receiver_task_started_no_cached_context(self) -> None: + task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + + structlog.contextvars.bind_contextvars(foo="bar") + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.INFO + ) as log_results: + receiver.receiver_task_started( + sender=mock_sender, task_result=mock_task_result + ) + + context = structlog.contextvars.get_merged_contextvars(self.logger) + self.assertDictEqual({"task_id": task_id}, context) + + self.assertEqual(1, len(log_results.records)) + record: Any = log_results.records[0] + self.assertEqual("task_started", record.msg["event"]) + + def test_receiver_task_finished_other_status(self) -> None: + """Test that no logging occurs for task status other than SUCCESSFUL or FAILED.""" + task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + mock_task_result.status = TaskResultStatus.RUNNING + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + + # No logs should be produced for RUNNING status + with self.assertRaises(AssertionError): + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.INFO + ): + receiver.receiver_task_finished( + sender=mock_sender, task_result=mock_task_result + ) + + def test_receiver_task_finished_failed_empty_errors(self) -> None: + """Test task failure with empty errors list.""" + task_id = "11111111-1111-1111-1111-111111111111" + expected_task_name = "test_app.tasks.test_task" + + mock_task_result = Mock(spec=TaskResult) + mock_task_result.id = task_id + mock_task_result.task = Mock() + mock_task_result.task.module_path = expected_task_name + mock_task_result.status = TaskResultStatus.FAILED + mock_task_result.errors = [] + + mock_sender = Mock() + receiver = receivers.DjangoTaskReceiver() + with self.assertLogs( + logging.getLogger("django_structlog.tasks.receivers"), logging.ERROR + ) as log_results: + receiver.receiver_task_finished( + sender=mock_sender, task_result=mock_task_result + ) + + self.assertEqual(1, len(log_results.records)) + record: Any = log_results.records[0] + self.assertEqual("task_failed", record.msg["event"]) + self.assertEqual("ERROR", record.levelname) + # Should not have exception_class or traceback when errors list is empty + self.assertNotIn("exception_class", record.msg) + self.assertNotIn("traceback", record.msg) + + +@unittest.skipIf(django.VERSION < (6, 0), "Django 6.0+ required for native tasks") +class TestConnectDjangoTaskSignals(TestCase): + def test_call(self) -> None: + from django.tasks.signals import ( # type: ignore[import-untyped] + task_enqueued, + task_finished, + task_started, + ) + + from django_structlog.tasks.receivers import DjangoTaskReceiver + + receiver = DjangoTaskReceiver() + with patch( + "django.dispatch.dispatcher.Signal.connect", autospec=True + ) as mock_connect: + receiver.connect_signals() + + mock_connect.assert_has_calls( + [ + call(task_started, receiver.receiver_task_started), + call(task_finished, receiver.receiver_task_finished), + call(task_enqueued, receiver.receiver_task_enqueued), + ] + ) diff --git a/test_app/tests/test_app_settings.py b/test_app/tests/test_app_settings.py index 6fbbb038..ab39bf74 100644 --- a/test_app/tests/test_app_settings.py +++ b/test_app/tests/test_app_settings.py @@ -37,3 +37,59 @@ def test_status_5xx_log_level_custom(self) -> None: with self.settings(DJANGO_STRUCTLOG_STATUS_5XX_LOG_LEVEL=logging.CRITICAL): self.assertEqual(settings.STATUS_5XX_LOG_LEVEL, logging.CRITICAL) + + def test_status_4xx_log_level_default(self) -> None: + settings = app_settings.AppSettings() + self.assertEqual(settings.STATUS_4XX_LOG_LEVEL, logging.WARNING) + + def test_status_4xx_log_level_custom(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL=logging.ERROR): + self.assertEqual(settings.STATUS_4XX_LOG_LEVEL, logging.ERROR) + + def test_command_logging_enabled(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED=True): + self.assertTrue(settings.COMMAND_LOGGING_ENABLED) + + def test_command_logging_disabled(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED=False): + self.assertFalse(settings.COMMAND_LOGGING_ENABLED) + + def test_user_id_field_default(self) -> None: + settings = app_settings.AppSettings() + self.assertEqual(settings.USER_ID_FIELD, "pk") + + def test_user_id_field_custom(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_USER_ID_FIELD="id"): + self.assertEqual(settings.USER_ID_FIELD, "id") + + def test_ip_logging_enabled(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_IP_LOGGING_ENABLED=True): + self.assertTrue(settings.IP_LOGGING_ENABLED) + + def test_ip_logging_disabled(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_IP_LOGGING_ENABLED=False): + self.assertFalse(settings.IP_LOGGING_ENABLED) + + def test_django_tasks_enabled(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_DJANGO_TASKS_ENABLED=True): + self.assertTrue(settings.DJANGO_TASKS_ENABLED) + + def test_django_tasks_disabled(self) -> None: + settings = app_settings.AppSettings() + + with self.settings(DJANGO_STRUCTLOG_DJANGO_TASKS_ENABLED=False): + self.assertFalse(settings.DJANGO_TASKS_ENABLED) diff --git a/test_app/tests/test_apps.py b/test_app/tests/test_apps.py index bc985b80..af35c139 100644 --- a/test_app/tests/test_apps.py +++ b/test_app/tests/test_apps.py @@ -1,9 +1,12 @@ +import unittest from unittest.mock import create_autospec, patch +import django from django.test import TestCase from django_structlog import apps, commands from django_structlog.celery import receivers +from django_structlog.tasks import receivers as task_receivers class TestAppConfig(TestCase): @@ -70,3 +73,37 @@ def test_command_disabled(self) -> None: mock_receiver.connect_signals.assert_not_called() self.assertFalse(hasattr(app, "_django_command_receiver")) + + @unittest.skipIf(django.VERSION < (6, 0), "Django 6.0+ required for native tasks") + def test_django_tasks_enabled(self) -> None: + app = apps.DjangoStructLogConfig( + "django_structlog", __import__("django_structlog") + ) + mock_receiver = create_autospec(spec=task_receivers.DjangoTaskReceiver) + with patch( + "django_structlog.tasks.receivers.DjangoTaskReceiver", + return_value=mock_receiver, + ): + with self.settings(DJANGO_STRUCTLOG_DJANGO_TASKS_ENABLED=True): + app.ready() + mock_receiver.connect_signals.assert_called_once() + + self.assertTrue(hasattr(app, "_django_task_receiver")) + self.assertIsNotNone(app._django_task_receiver) + + @unittest.skipIf(django.VERSION < (6, 0), "Django 6.0+ required for native tasks") + def test_django_tasks_disabled(self) -> None: + app = apps.DjangoStructLogConfig( + "django_structlog", __import__("django_structlog") + ) + + mock_receiver = create_autospec(spec=task_receivers.DjangoTaskReceiver) + with patch( + "django_structlog.tasks.receivers.DjangoTaskReceiver", + return_value=mock_receiver, + ): + with self.settings(DJANGO_STRUCTLOG_DJANGO_TASKS_ENABLED=False): + app.ready() + mock_receiver.connect_signals.assert_not_called() + + self.assertFalse(hasattr(app, "_django_task_receiver"))