Repository: jrobichaud/django-structlog

Issue:
Improve metadata of exceptional celery signals
When fixing #317 I noted these improvement that should be made.

[task_revoked](https://docs.celeryq.dev/en/stable/userguide/signals.html#id15)
- [x] signum is an object and should be logged as a primitive

[task_unknown](https://docs.celeryq.dev/en/stable/userguide/signals.html#id16)
- [x] add `task_id` and `task`
- [x] add example in demo project
- [x] validate how `message` is logged

[task_rejected](https://docs.celeryq.dev/en/stable/userguide/signals.html#task-rejected)
- [x] add example in demo project
- [x] validate how `message` is logged

Discussion:

Patch:
diff --git a/.idea/inspectionProfiles/Project_Default.xml b/.idea/inspectionProfiles/Project_Default.xml
index 47da128..285d274 100644
--- a/.idea/inspectionProfiles/Project_Default.xml
+++ b/.idea/inspectionProfiles/Project_Default.xml
@@ -4,10 +4,12 @@
     <inspection_tool class="PyCompatibilityInspection" enabled="true" level="WARNING" enabled_by_default="true">
       <option name="ourVersions">
         <value>
-          <list size="3">
-            <item index="0" class="java.lang.String" itemvalue="3.5" />
-            <item index="1" class="java.lang.String" itemvalue="3.6" />
-            <item index="2" class="java.lang.String" itemvalue="3.7" />
+          <list size="5">
+            <item index="0" class="java.lang.String" itemvalue="3.8" />
+            <item index="1" class="java.lang.String" itemvalue="3.9" />
+            <item index="2" class="java.lang.String" itemvalue="3.10" />
+            <item index="3" class="java.lang.String" itemvalue="3.11" />
+            <item index="4" class="java.lang.String" itemvalue="3.12" />
           </list>
         </value>
       </option>
diff --git a/compose/local/django/celery/worker/start b/compose/local/django/celery/worker/start
index 1279329..7a082b7 100644
--- a/compose/local/django/celery/worker/start
+++ b/compose/local/django/celery/worker/start
@@ -4,4 +4,4 @@ set -o errexit
 set -o nounset
 
 
-celery -A django_structlog_demo_project.taskapp worker -l INFO
+IS_WORKER=1 celery -A django_structlog_demo_project.taskapp worker -l INFO
diff --git a/compose/local/docs/Dockerfile b/compose/local/docs/Dockerfile
index 6969d81..10faaf7 100644
--- a/compose/local/docs/Dockerfile
+++ b/compose/local/docs/Dockerfile
@@ -24,13 +24,14 @@ COPY --from=python-build-stage /usr/src/app/wheels  /wheels/
 RUN pip install --no-cache-dir --no-index --find-links=/wheels/ /wheels/* \
 	&& rm -rf /wheels/
 
+COPY ./compose/local/docs/start /start
+RUN sed -i 's/\r//' /start
+RUN chmod +x /start
+
 RUN addgroup --system django \
     && adduser --system --ingroup django django
-
+RUN mkdir /docs
 RUN chown django:django /app
+RUN chown django:django /docs
 
 USER django
-
-COPY ./compose/local/docs/start /start
-RUN sed -i 's/\r//' /start
-RUN chmod +x /start
diff --git a/config/settings/local.py b/config/settings/local.py
index fd6f801..fd3fd8c 100644
--- a/config/settings/local.py
+++ b/config/settings/local.py
@@ -15,6 +15,8 @@ SECRET_KEY = env(
 # https://docs.djangoproject.com/en/dev/ref/settings/#allowed-hosts
 ALLOWED_HOSTS = ["localhost", "0.0.0.0", "127.0.0.1"]
 
+IS_WORKER = env.bool("IS_WORKER", default=False)
+
 # CACHES
 # ------------------------------------------------------------------------------
 # https://docs.djangoproject.com/en/dev/ref/settings/#caches
diff --git a/config/urls.py b/config/urls.py
index 4e37443..64445fd 100644
--- a/config/urls.py
+++ b/config/urls.py
@@ -20,6 +20,10 @@ urlpatterns = [
     ),
     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"^unknown_task$", views.enqueue_unknown_task, name="enqueue_unknown_task"),
+    re_path(
+        r"^rejected_task$", views.enqueue_rejected_task, name="enqueue_rejected_task"
+    ),
     re_path(r"^raise_exception", views.raise_exception, name="raise_exception"),
     re_path(
         r"^standard_logger", views.log_with_standard_logger, name="standard_logger"
diff --git a/django_structlog/celery/receivers.py b/django_structlog/celery/receivers.py
index b976582..b9dfe71 100644
--- a/django_structlog/celery/receivers.py
+++ b/django_structlog/celery/receivers.py
@@ -86,18 +86,23 @@ def receiver_task_revoked(
     logger.warning(
         "task_revoked",
         terminated=terminated,
-        signum=signum,
+        signum=signum.value if signum is not None else None,
+        signame=signum.name if signum is not None else None,
         expired=expired,
         **metadata,
     )
 
 
 def receiver_task_unknown(message=None, exc=None, name=None, id=None, **kwargs):
-    logger.error("task_not_found", message=message)
+    logger.error(
+        "task_not_found",
+        task=name,
+        task_id=id,
+    )
 
 
 def receiver_task_rejected(message=None, exc=None, **kwargs):
-    logger.error("task_rejected", message=message)
+    logger.exception("task_rejected", task_id=message.properties.get("correlation_id"))
 
 
 def connect_celery_signals():
diff --git a/django_structlog_demo_project/home/views.py b/django_structlog_demo_project/home/views.py
index 00f5a27..448aabd 100644
--- a/django_structlog_demo_project/home/views.py
+++ b/django_structlog_demo_project/home/views.py
@@ -7,6 +7,7 @@ from django_structlog_demo_project.taskapp.celery import (
     successful_task,
     failing_task,
     nesting_task,
+    rejected_task,
 )
 
 logger = structlog.get_logger(__name__)
@@ -41,6 +42,21 @@ def revoke_task(request):
     return HttpResponse(status=201)
 
 
+def enqueue_unknown_task(request):
+    from django_structlog_demo_project.taskapp.celery import (
+        unknown_task,
+    )
+
+    logger.info("Enqueuing unknown task")
+    unknown_task.delay()
+    return HttpResponse(status=201)
+
+
+def enqueue_rejected_task(request):
+    rejected_task.delay()
+    return HttpResponse(status=201)
+
+
 async def async_view(request):
     for num in range(1, 2):
         await asyncio.sleep(1)
diff --git a/django_structlog_demo_project/taskapp/celery.py b/django_structlog_demo_project/taskapp/celery.py
index 9cd4bef..629d5d9 100644
--- a/django_structlog_demo_project/taskapp/celery.py
+++ b/django_structlog_demo_project/taskapp/celery.py
@@ -85,7 +85,31 @@ def nested_task():
     logger.info("This is a nested task")
 
 
-@shared_task()
+@shared_task
 def scheduled_task():
     logger = structlog.getLogger(__name__)
     logger.info("This is a scheduled task")
+
+
+@shared_task
+def rejected_task():
+    pass
+
+
+if not settings.IS_WORKER:
+
+    @shared_task
+    def unknown_task():
+        """Simulate a task unavailable in the worker for demonstration purpose"""
+
+
+@signals.before_task_publish.connect
+def corrupt_rejected_task(sender=None, headers=None, body=None, **kwargs):
+    """Simulate celery's task rejection mechanism by breaking up the message"""
+    logger = structlog.getLogger(__name__)
+    if headers.get("task") == f"{rejected_task.__module__}.{rejected_task.__name__}":
+        logger.warn(
+            f"corrupting {rejected_task.__name__}",
+            task_id=headers.get("id"),
+        )
+        del headers["task"]
diff --git a/django_structlog_demo_project/templates/pages/home.html b/django_structlog_demo_project/templates/pages/home.html
index 8bba5da..0915ceb 100644
--- a/django_structlog_demo_project/templates/pages/home.html
+++ b/django_structlog_demo_project/templates/pages/home.html
@@ -3,53 +3,69 @@
 
 {% block content %}
     <div>
-        <form action="{% url 'enqueue_successful_task' %}" method="post" id="form1" target="dummyframe">
+        <form action="{% url 'raise_exception' %}" method="post" id="form_raise_exception">
             {% csrf_token %}
         </form>
-        <button type="submit" form="form1">Enqueue successful task</button>
+        <button type="submit" form="form_raise_exception">Raise exception</button>
     </div>
+
     <div>
-        <form action="{% url 'enqueue_failing_task' %}" method="post" id="form2" target="dummyframe">
-        {% csrf_token %}
+        <form action="{% url 'standard_logger' %}" method="post" id="form_standard_logger" target="dummyframe">
+            {% csrf_token %}
         </form>
-        <button type="submit" form="form2">Enqueue failing task</button>
+        <button type="submit" form="form_standard_logger">Standard logger</button>
     </div>
+
     <div>
-        <form action="{% url 'enqueue_nesting_task' %}" method="post" id="form3" target="dummyframe">
+        <form action="{% url 'async_view' %}" method="post" id="form_async_view" target="dummyframe">
             {% csrf_token %}
         </form>
-        <button type="submit" form="form3">Enqueue nesting task</button>
+        <button type="submit" form="form_async_view">Async View</button>
+    </div>
+
+    <div>
+        <a href="{% url 'api_view' %}">rest-framework API View</a>
     </div>
+
     <div>
-        <form action="{% url 'raise_exception' %}" method="post" id="form4">
+        <form action="{% url 'enqueue_successful_task' %}" method="post" id="form_enqueue_successful_task" target="dummyframe">
             {% csrf_token %}
         </form>
-        <button type="submit" form="form4">Raise exception</button>
+        <button type="submit" form="form_enqueue_successful_task">Celery: Enqueue successful task</button>
+    </div>
+    <div>
+        <form action="{% url 'enqueue_failing_task' %}" method="post" id="form_enqueue_failing_task" target="dummyframe">
+            {% csrf_token %}
+        </form>
+        <button type="submit" form="form_enqueue_failing_task">Celery: Enqueue failing task</button>
     </div>
 
     <div>
-        <form action="{% url 'standard_logger' %}" method="post" id="form5" target="dummyframe">
+        <form action="{% url 'enqueue_nesting_task' %}" method="post" id="form_enqueue_nesting_task" target="dummyframe">
             {% csrf_token %}
         </form>
-        <button type="submit" form="form5">Standard logger</button>
+        <button type="submit" form="form_enqueue_nesting_task">Celery: Enqueue nesting task</button>
     </div>
 
     <div>
-        <form action="{% url 'revoke_task' %}" method="post" id="form6" target="dummyframe">
+        <form action="{% url 'enqueue_unknown_task' %}" method="post" id="form_enqueue_unknown_task" target="dummyframe">
             {% csrf_token %}
         </form>
-        <button type="submit" form="form6">Revoke task</button>
+        <button type="submit" form="form_enqueue_unknown_task">Celery: Enqueue unknown task</button>
     </div>
 
     <div>
-        <form action="{% url 'async_view' %}" method="post" id="form6" target="dummyframe">
+        <form action="{% url 'enqueue_rejected_task' %}" method="post" id="form_enqueue_rejected_task" target="dummyframe">
             {% csrf_token %}
         </form>
-        <button type="submit" form="form6">Async View</button>
+        <button type="submit" form="form_enqueue_rejected_task">Celery: Enqueue rejected task</button>
     </div>
 
     <div>
-        <a href="{% url 'api_view' %}">rest-framework API View</a>
+        <form action="{% url 'revoke_task' %}" method="post" id="form_revoke_task" target="dummyframe">
+            {% csrf_token %}
+        </form>
+        <button type="submit" form="form_revoke_task">Celery: Revoke task</button>
     </div>
 
     <span><iframe width="0" height="0" border="0" name="dummyframe" id="dummyframe" style="visibility: hidden;"></iframe></span>
diff --git a/docs/changelog.rst b/docs/changelog.rst
index 95d9a02..8ceecc2 100644
--- a/docs/changelog.rst
+++ b/docs/changelog.rst
@@ -9,6 +9,8 @@ See: :ref:`upgrade_6.0`
 *New:*
     - Python 3.12 support
     - Add support of logging :ref:`commands`
+    - ``task_revoked`` has now a ``signame`` metadata. See `#323 <https://github.com/jrobichaud/django-structlog/issues/323>`_.
+    - ``task_not_found`` has now a ``task_id`` and a ``task`` metadata. See `#323 <https://github.com/jrobichaud/django-structlog/issues/323>`_.
 
 *Fixes:*
     - Add missing metadata when a task is revoked. See `#317 <https://github.com/jrobichaud/django-structlog/issues/317>`_. Special thanks to `@badziyoussef <https://github.com/badziyoussef>`_.
@@ -22,6 +24,9 @@ See: :ref:`upgrade_6.0`
         - :class:`django_structlog.middlewares.AsyncRequestMiddleware`
         - :class:`django_structlog.middlewares.request_middleware_router`
     - ``4XX`` status codes now log by default as ``WARNING`` and ``5XX`` as ``ERROR``. The behaviour of ``4XX`` can be customized with :ref:`configuration`. See `#308 <https://github.com/jrobichaud/django-structlog/issues/308>`_. Special thanks to `@adinhodovic <https://github.com/adinhodovic>`_.
+    - ``task_revoked``'s ``signum`` is now an integer instead of an object. See `#323 <https://github.com/jrobichaud/django-structlog/issues/323>`_.
+    - ``task_not_found``'s ``message`` was removed and replaced by ``task_id`` and ``task``. See `#323 <https://github.com/jrobichaud/django-structlog/issues/323>`_.
+    - ``task_rejected``'s ``message`` was removed and replaced by ``task_id``. See `#323 <https://github.com/jrobichaud/django-structlog/issues/323>`_.
 
 
 5.3.0 (June 30, 2023)
diff --git a/docs/events.rst b/docs/events.rst
index 5f2551f..2909349 100644
--- a/docs/events.rst
+++ b/docs/events.rst
@@ -132,7 +132,9 @@ These metadata appear once along with their associated event
 +------------------+------------------+----------------------------------------+
 | task_revoked     | terminated       | Set to True if the task was terminated |
 +------------------+------------------+----------------------------------------+
-| task_revoked     | signum           | see Celery's documentation             |
+| task_revoked     | signum           | python termination signal's number     |
++------------------+------------------+----------------------------------------+
+| task_revoked     | signame          | python termination signal's name       |
 +------------------+------------------+----------------------------------------+
 | task_revoked     | expired          | see Celery's documentation             |
 +------------------+------------------+----------------------------------------+
@@ -140,5 +142,11 @@ These metadata appear once along with their associated event
 +------------------+------------------+----------------------------------------+
 | task_revoked     | task             | name of the task being revoked         |
 +------------------+------------------+----------------------------------------+
+| task_not_found   | task_id          | id of the task not found               |
++------------------+------------------+----------------------------------------+
+| task_not_found   | task             | name of the task not found             |
++------------------+------------------+----------------------------------------+
+| task_rejected    | task_id          | id of the task being rejected          |
++------------------+------------------+----------------------------------------+
 
 \* if task threw an expected exception, ``exception`` will be omitted. See `Celery's Task.throws <https://docs.celeryproject.org/en/latest/userguide/tasks.html#Task.throws>`_


Test patch:
diff --git a/config/settings/test_demo_app.py b/config/settings/test_demo_app.py
index 1b2aee6..3d15c75 100644
--- a/config/settings/test_demo_app.py
+++ b/config/settings/test_demo_app.py
@@ -9,3 +9,5 @@ from .base import *  # noqa: F401,F403
 from .test import DATABASES, LOGGING  # noqa: F401
 
 DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED = True
+
+IS_WORKER = False
diff --git a/django_structlog_demo_project/home/tests/test_views.py b/django_structlog_demo_project/home/tests/test_views.py
index 0f40625..d68e646 100644
--- a/django_structlog_demo_project/home/tests/test_views.py
+++ b/django_structlog_demo_project/home/tests/test_views.py
@@ -48,3 +48,15 @@ class TestRevokeTask:
     def test(self):
         response = views.revoke_task(None)
         assert response.status_code == 201
+
+
+class TestEnqueueUnknownTask:
+    def test(self):
+        response = views.enqueue_unknown_task(None)
+        assert response.status_code == 201
+
+
+class TestEnqueueRejectedTask:
+    def test(self):
+        response = views.enqueue_rejected_task(None)
+        assert response.status_code == 201
diff --git a/django_structlog_demo_project/taskapp/tests/test_celery.py b/django_structlog_demo_project/taskapp/tests/test_celery.py
index ac9a2a0..faec66f 100644
--- a/django_structlog_demo_project/taskapp/tests/test_celery.py
+++ b/django_structlog_demo_project/taskapp/tests/test_celery.py
@@ -42,3 +42,36 @@ class TestScheduledTask:
         assert len(caplog.records) == 1
         record = caplog.records[0]
         assert record.msg["event"] == "This is a scheduled task"
+
+
+class TestRejectedTask:
+    def test(self):
+        assert celery.rejected_task() is None
+
+
+class TestCorruptRejectedTask:
+    def test(self, caplog):
+        task_id = "11111111-1111-1111-1111-111111111111"
+        headers = dict(
+            id=task_id,
+            task="django_structlog_demo_project.taskapp.celery.rejected_task",
+        )
+        celery.corrupt_rejected_task(sender=None, headers=headers)
+        assert len(caplog.records) == 1
+        record = caplog.records[0]
+        assert record.msg["event"] == "corrupting rejected_task"
+        assert record.msg["task_id"] == task_id
+        assert "task" not in headers
+
+    def test_other_tasks_not_corrupted(self, caplog):
+        task_id = "11111111-1111-1111-1111-111111111111"
+        headers = dict(
+            id=task_id,
+            task="django_structlog_demo_project.taskapp.celery.successful_task",
+        )
+        celery.corrupt_rejected_task(sender=None, headers=headers)
+        assert len(caplog.records) == 0
+        assert (
+            headers["task"]
+            == "django_structlog_demo_project.taskapp.celery.successful_task"
+        )
diff --git a/test_app/tests/celery/test_receivers.py b/test_app/tests/celery/test_receivers.py
index ee394a5..eeffdeb 100644
--- a/test_app/tests/celery/test_receivers.py
+++ b/test_app/tests/celery/test_receivers.py
@@ -1,4 +1,5 @@
 import logging
+from signal import SIGTERM
 from unittest import mock
 from unittest.mock import Mock, patch, call
 
@@ -362,7 +363,47 @@ class TestReceivers(TestCase):
             logging.getLogger("django_structlog.celery.receivers"), logging.WARNING
         ) as log_results:
             receivers.receiver_task_revoked(
-                request=request, terminated=True, signum=1, expired=False
+                request=request, terminated=False, signum=None, expired=False
+            )
+
+        self.assertEqual(1, len(log_results.records))
+        record = log_results.records[0]
+        self.assertEqual("task_revoked", record.msg["event"])
+        self.assertEqual("WARNING", record.levelname)
+        self.assertIn("terminated", record.msg)
+        self.assertFalse(record.msg["terminated"])
+        self.assertIn("signum", record.msg)
+        self.assertIsNone(record.msg["signum"])
+        self.assertIn("signame", record.msg)
+        self.assertIsNone(record.msg["signame"])
+        self.assertIn("expired", record.msg)
+        self.assertFalse(record.msg["expired"])
+        self.assertIn("task_id", record.msg)
+        self.assertEqual(task_id, record.msg["task_id"])
+        self.assertIn("task", record.msg)
+        self.assertEqual(expected_task_name, record.msg["task"])
+        self.assertIn("request_id", record.msg)
+        self.assertEqual(expected_request_uuid, record.msg["request_id"])
+        self.assertIn("user_id", record.msg)
+        self.assertEqual(expected_user_id, record.msg["user_id"])
+
+    def test_receiver_task_revoked_terminated(self):
+        expected_request_uuid = "00000000-0000-0000-0000-000000000000"
+        task_id = "11111111-1111-1111-1111-111111111111"
+        expected_user_id = "1234"
+        expected_task_name = "task_name"
+        request = Mock()
+        request.__django_structlog__ = {
+            "request_id": expected_request_uuid,
+            "user_id": expected_user_id,
+        }
+        request.task = expected_task_name
+        request.id = task_id
+        with self.assertLogs(
+            logging.getLogger("django_structlog.celery.receivers"), logging.WARNING
+        ) as log_results:
+            receivers.receiver_task_revoked(
+                request=request, terminated=True, signum=SIGTERM, expired=False
             )
 
         self.assertEqual(1, len(log_results.records))
@@ -372,7 +413,9 @@ class TestReceivers(TestCase):
         self.assertIn("terminated", record.msg)
         self.assertTrue(record.msg["terminated"])
         self.assertIn("signum", record.msg)
-        self.assertEqual(1, record.msg["signum"])
+        self.assertEqual(15, record.msg["signum"])
+        self.assertIn("signame", record.msg)
+        self.assertEqual("SIGTERM", record.msg["signame"])
         self.assertIn("expired", record.msg)
         self.assertFalse(record.msg["expired"])
         self.assertIn("task_id", record.msg)
@@ -385,34 +428,39 @@ class TestReceivers(TestCase):
         self.assertEqual(expected_user_id, record.msg["user_id"])
 
     def test_receiver_task_unknown(self):
-        expected_message = "foo"
+        task_id = "11111111-1111-1111-1111-111111111111"
+        expected_task_name = "task_name"
 
         with self.assertLogs(
             logging.getLogger("django_structlog.celery.receivers"), logging.ERROR
         ) as log_results:
-            receivers.receiver_task_unknown(message=expected_message)
+            receivers.receiver_task_unknown(id=task_id, name=expected_task_name)
 
         self.assertEqual(1, len(log_results.records))
         record = log_results.records[0]
         self.assertEqual("task_not_found", record.msg["event"])
         self.assertEqual("ERROR", record.levelname)
-        self.assertIn("message", record.msg)
-        self.assertEqual(expected_message, record.msg["message"])
+        self.assertIn("task_id", record.msg)
+        self.assertEqual(task_id, record.msg["task_id"])
+        self.assertIn("task", record.msg)
+        self.assertEqual(expected_task_name, record.msg["task"])
 
     def test_receiver_task_rejected(self):
-        expected_message = "foo"
+        task_id = "11111111-1111-1111-1111-111111111111"
+        message = Mock(name="message")
+        message.properties = dict(correlation_id=task_id)
 
         with self.assertLogs(
             logging.getLogger("django_structlog.celery.receivers"), logging.ERROR
         ) as log_results:
-            receivers.receiver_task_rejected(message=expected_message)
+            receivers.receiver_task_rejected(message=message)
 
         self.assertEqual(1, len(log_results.records))
         record = log_results.records[0]
         self.assertEqual("task_rejected", record.msg["event"])
         self.assertEqual("ERROR", record.levelname)
-        self.assertIn("message", record.msg)
-        self.assertEqual(expected_message, record.msg["message"])
+        self.assertIn("task_id", record.msg)
+        self.assertEqual(task_id, record.msg["task_id"])
 
 
 class TestConnectCelerySignals(TestCase):