Repository: jrobichaud/django-structlog

Issue:
Bind a "command_id" when using django commands

could be used along with [django-extensions's command signals](https://django-extensions.readthedocs.io/en/latest/command_signals.html#basic-example)

Something like this:

```python
import uuid

from django_extensions.management.signals import pre_command, post_command
import structlog

def pre_receiver(sender, *args, **kwargs):
    structlog.contextvars.bind_contextvars(command_id=str(uuid.uuid4()))

def post_receiver(sender, outcome, *args, **kwargs):
    # log result
    pass

pre_command.connect(pre_receiver)
post_command.connect(post_receiver)
```

Discussion:

Patch:
diff --git a/config/settings/base.py b/config/settings/base.py
index 2706de9..a49821d 100644
--- a/config/settings/base.py
+++ b/config/settings/base.py
@@ -62,7 +62,9 @@ THIRD_PARTY_APPS = [
     "rest_framework",
 ]
 LOCAL_APPS = [
-    "django_structlog_demo_project.users.apps.UsersAppConfig",
+    "django_structlog_demo_project.command_examples",
+    "django_structlog_demo_project.users",
+    "django_structlog_demo_project.home",
     # Your stuff: custom apps go here
 ]
 # https://docs.djangoproject.com/en/dev/ref/settings/#installed-apps
diff --git a/config/settings/local.py b/config/settings/local.py
index eeb7441..fd6f801 100644
--- a/config/settings/local.py
+++ b/config/settings/local.py
@@ -164,3 +164,4 @@ MIDDLEWARE += [
 ]
 
 DJANGO_STRUCTLOG_CELERY_ENABLED = True
+DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED = True
diff --git a/django_structlog/app_settings.py b/django_structlog/app_settings.py
index 6f5e914..c9642ed 100644
--- a/django_structlog/app_settings.py
+++ b/django_structlog/app_settings.py
@@ -15,5 +15,9 @@ class AppSettings:
     def STATUS_4XX_LOG_LEVEL(self):
         return getattr(settings, self.PREFIX + "STATUS_4XX_LOG_LEVEL", logging.WARNING)
 
+    @property
+    def COMMAND_LOGGING_ENABLED(self):
+        return getattr(settings, self.PREFIX + "COMMAND_LOGGING_ENABLED", False)
+
 
 app_settings = AppSettings()
diff --git a/django_structlog/apps.py b/django_structlog/apps.py
index 17104b5..50f2958 100644
--- a/django_structlog/apps.py
+++ b/django_structlog/apps.py
@@ -11,3 +11,8 @@ class DjangoStructLogConfig(AppConfig):
             from .celery.receivers import connect_celery_signals
 
             connect_celery_signals()
+
+        if app_settings.COMMAND_LOGGING_ENABLED:
+            from .commands import init_command_signals
+
+            init_command_signals()
diff --git a/django_structlog/commands.py b/django_structlog/commands.py
new file mode 100644
index 0000000..4a3096e
--- /dev/null
+++ b/django_structlog/commands.py
@@ -0,0 +1,40 @@
+import structlog
+import uuid
+
+logger = structlog.getLogger(__name__)
+stack = []
+
+
+def pre_receiver(sender, *args, **kwargs):
+    command_id = str(uuid.uuid4())
+    if len(stack):
+        parent_command_id, _ = stack[-1]
+        tokens = structlog.contextvars.bind_contextvars(
+            parent_command_id=parent_command_id, command_id=command_id
+        )
+    else:
+        tokens = structlog.contextvars.bind_contextvars(command_id=command_id)
+    stack.append((command_id, tokens))
+
+    logger.info(
+        "command_started",
+        command_name=sender.__module__.replace(".management.commands", ""),
+    )
+
+
+def post_receiver(sender, outcome, *args, **kwargs):
+    logger.info("command_finished")
+
+    if len(stack):
+        command_id, tokens = stack.pop()
+        structlog.contextvars.reset_contextvars(**tokens)
+
+
+def init_command_signals():
+    try:
+        from django_extensions.management.signals import pre_command, post_command
+    except ModuleNotFoundError:  # pragma: no cover
+        return
+
+    pre_command.connect(pre_receiver)
+    post_command.connect(post_receiver)
diff --git a/django_structlog_demo_project/command_examples/__init__.py b/django_structlog_demo_project/command_examples/__init__.py
new file mode 100644
index 0000000..e69de29
diff --git a/django_structlog_demo_project/command_examples/apps.py b/django_structlog_demo_project/command_examples/apps.py
new file mode 100644
index 0000000..17571a7
--- /dev/null
+++ b/django_structlog_demo_project/command_examples/apps.py
@@ -0,0 +1,6 @@
+from django.apps import AppConfig
+
+
+class CommandExamplesAppConfig(AppConfig):
+    name = "django_structlog_demo_project.command_examples"
+    default_auto_field = "django.db.models.AutoField"
diff --git a/django_structlog_demo_project/command_examples/management/__init__.py b/django_structlog_demo_project/command_examples/management/__init__.py
new file mode 100644
index 0000000..e69de29
diff --git a/django_structlog_demo_project/command_examples/management/commands/__init__.py b/django_structlog_demo_project/command_examples/management/commands/__init__.py
new file mode 100644
index 0000000..e69de29
diff --git a/django_structlog_demo_project/command_examples/management/commands/example_command.py b/django_structlog_demo_project/command_examples/management/commands/example_command.py
new file mode 100644
index 0000000..7258655
--- /dev/null
+++ b/django_structlog_demo_project/command_examples/management/commands/example_command.py
@@ -0,0 +1,17 @@
+import structlog
+from django.core import management
+from django.core.management import BaseCommand
+from django_extensions.management.utils import signalcommand
+
+logger = structlog.getLogger(__name__)
+
+
+class Command(BaseCommand):
+    def add_arguments(self, parser):
+        parser.add_argument("foo", type=str)
+
+    @signalcommand
+    def handle(self, foo, *args, **options):
+        logger.info("my log", foo=foo)
+        management.call_command("example_nested_command", "buz", verbosity=0)
+        logger.info("my log 2")
diff --git a/django_structlog_demo_project/command_examples/management/commands/example_nested_command.py b/django_structlog_demo_project/command_examples/management/commands/example_nested_command.py
new file mode 100644
index 0000000..64f8454
--- /dev/null
+++ b/django_structlog_demo_project/command_examples/management/commands/example_nested_command.py
@@ -0,0 +1,15 @@
+import structlog
+from django.core.management import BaseCommand
+from django_extensions.management.utils import signalcommand
+
+logger = structlog.getLogger(__name__)
+
+
+class Command(BaseCommand):
+    def add_arguments(self, parser):
+        parser.add_argument("baz", type=str)
+
+    @signalcommand
+    def handle(self, baz, *args, **options):
+        logger.info("my nested log", baz=baz)
+        return 0
diff --git a/django_structlog_demo_project/home/apps.py b/django_structlog_demo_project/home/apps.py
new file mode 100644
index 0000000..2bddf3c
--- /dev/null
+++ b/django_structlog_demo_project/home/apps.py
@@ -0,0 +1,6 @@
+from django.apps import AppConfig
+
+
+class HomeAppConfig(AppConfig):
+    name = "django_structlog_demo_project.home"
+    default_auto_field = "django.db.models.AutoField"
diff --git a/docs/changelog.rst b/docs/changelog.rst
index 1627e28..7240ad3 100644
--- a/docs/changelog.rst
+++ b/docs/changelog.rst
@@ -8,6 +8,7 @@ See: :ref:`upgrade_6.0`
 
 *New:*
     - Python 3.12 support
+    - Add support of logging :ref:`commands`
 
 *Changes:*
     - Drop support of python 3.7
diff --git a/docs/commands.rst b/docs/commands.rst
new file mode 100644
index 0000000..bd1fc54
--- /dev/null
+++ b/docs/commands.rst
@@ -0,0 +1,62 @@
+.. _commands:
+
+Commands
+========
+
+Prerequisites
+^^^^^^^^^^^^^
+
+Install ``django-structlog`` with command support (it will install `django-extensions <https://django-extensions.readthedocs.io/en/latest/>`_).
+
+.. code-block:: bash
+
+   pip install django-structlog[commands]
+
+Enable ``django-structlog`` command logging:
+
+.. code-block:: python
+
+   DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED = True
+
+Add `@signalcommand` to your commands
+
+.. code-block:: python
+
+    import structlog
+    from django.core.management import BaseCommand
+    from django_extensions.management.utils import signalcommand # <- add this
+
+    logger = structlog.getLogger(__name__)
+
+
+    class Command(BaseCommand):
+        def add_arguments(self, parser):
+            parser.add_argument("foo", type=str)
+
+        @signalcommand # <- add this
+        def handle(self, foo, *args, **options):
+            logger.info("my log", foo=foo)
+            return 0
+
+Log will add ``command_name`` and ``command_id`` to the logs:
+
+.. code-block:: bash
+
+    $ python manage.py example_command bar
+    2023-09-13T21:10:50.084368Z [info     ] command_started                [django_structlog.commands] command_name=django_structlog_demo_project.users.example_command command_id=be723d34-59f5-468e-9258-24232aa4cedd
+    2023-09-13T21:10:50.085325Z [info     ] my log                         [django_structlog_demo_project.users.management.commands.example_command] command_id=be723d34-59f5-468e-9258-24232aa4cedd foo=bar
+    2023-09-13T21:10:50.085877Z [info     ] command_finished               [django_structlog.commands] command_id=be723d34-59f5-468e-9258-24232aa4cedd
+
+
+It also supports nested commands which will keep track of parent commands through ``parent_id``:
+
+.. code-block:: bash
+
+    $ python manage.py example_command bar
+    2023-09-15T00:10:10.466616Z [info     ] command_started                [django_structlog.commands] command_id=f2a8c9a8-5aa3-4e22-b11c-f387449a34ed command_name=django_structlog_demo_project.users.example_command foo=bar
+    2023-09-15T00:10:10.467250Z [info     ] my log                         [django_structlog_demo_project.users.management.commands.example_command] command_id=f2a8c9a8-5aa3-4e22-b11c-f387449a34ed
+    2023-09-15T00:10:10.468176Z [info     ] command_started                [django_structlog.commands] baz=2 command_id=57524ccb-a8eb-4d30-a989-4e83ffdca9c0 command_name=django_structlog_demo_project.users.example_nested_command parent_command_id=f2a8c9a8-5aa3-4e22-b11c-f387449a34ed
+    2023-09-15T00:10:10.468871Z [info     ] my nested log                  [django_structlog_demo_project.users.management.commands.example_nested_command] command_id=57524ccb-a8eb-4d30-a989-4e83ffdca9c0 parent_command_id=f2a8c9a8-5aa3-4e22-b11c-f387449a34ed
+    2023-09-15T00:10:10.469418Z [info     ] command_finished               [django_structlog.commands] command_id=57524ccb-a8eb-4d30-a989-4e83ffdca9c0 parent_command_id=f2a8c9a8-5aa3-4e22-b11c-f387449a34ed
+    2023-09-15T00:10:10.469964Z [info     ] my log 2                       [django_structlog_demo_project.users.management.commands.example_command] command_id=f2a8c9a8-5aa3-4e22-b11c-f387449a34ed
+    2023-09-15T00:10:10.470585Z [info     ] command_finished               [django_structlog.commands] command_id=f2a8c9a8-5aa3-4e22-b11c-f387449a34ed
diff --git a/docs/configuration.rst b/docs/configuration.rst
index 7ff608f..e3f1638 100644
--- a/docs/configuration.rst
+++ b/docs/configuration.rst
@@ -16,10 +16,12 @@ Example:
 Settings
 --------
 
-+---------------------------------------+---------+-----------------+-------------------------------+
-| Key                                   | Type    | Default         | Description                   |
-+=======================================+=========+=================+===============================+
-| DJANGO_STRUCTLOG_CELERY_ENABLED       | boolean | False           | See :ref:`celery_integration` |
-+---------------------------------------+---------+-----------------+-------------------------------+
-| DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL | int     | logging.WARNING | Log level of 4XX status codes |
-+---------------------------------------+---------+-----------------+-------------------------------+
++------------------------------------------+---------+-----------------+-------------------------------+
+| Key                                      | Type    | Default         | Description                   |
++==========================================+=========+=================+===============================+
+| DJANGO_STRUCTLOG_CELERY_ENABLED          | boolean | False           | See :ref:`celery_integration` |
++------------------------------------------+---------+-----------------+-------------------------------+
+| DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL    | int     | logging.WARNING | Log level of 4XX status codes |
++------------------------------------------+---------+-----------------+-------------------------------+
+| DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED | boolean | False           | See :ref:`commands`           |
++------------------------------------------+---------+-----------------+-------------------------------+
diff --git a/docs/index.rst b/docs/index.rst
index 2c4c189..f4a0a83 100644
--- a/docs/index.rst
+++ b/docs/index.rst
@@ -10,8 +10,9 @@ Contents, indices and tables
   :maxdepth: 2
 
   getting_started
-  celery
   configuration
+  celery
+  commands
   api_documentation
   events
   example_outputs
diff --git a/pyproject.toml b/pyproject.toml
index 6b2822b..fd002f2 100644
--- a/pyproject.toml
+++ b/pyproject.toml
@@ -44,6 +44,9 @@ build-backend = "setuptools.build_meta"
   celery = [
     "celery>=5.1"
   ]
+  commands = [
+    "django-extensions>=1.4.9"
+  ]
 
 [tool.setuptools.dynamic]
   version = { attr = "django_structlog.__version__" }
diff --git a/requirements/ci.txt b/requirements/ci.txt
index 680520e..885af19 100644
--- a/requirements/ci.txt
+++ b/requirements/ci.txt
@@ -2,6 +2,7 @@
 # ------------------------------------------------------------------------------
 django-environ==0.11.2  # https://github.com/joke2k/django-environ
 django-redis==5.3.0  # https://github.com/niwinz/django-redis
+django-extensions==3.2.3
 
 structlog>=21.4.0
 colorama>=0.4.3


Test patch:
diff --git a/config/settings/test.py b/config/settings/test.py
index 38e6987..0f6dcf7 100644
--- a/config/settings/test.py
+++ b/config/settings/test.py
@@ -111,3 +111,5 @@ DATABASES = {
 }
 
 INSTALLED_APPS += ["django_structlog", "test_app"]
+
+DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED = True
diff --git a/config/settings/test_demo_app.py b/config/settings/test_demo_app.py
index 6c31939..1b2aee6 100644
--- a/config/settings/test_demo_app.py
+++ b/config/settings/test_demo_app.py
@@ -7,3 +7,5 @@ from .base import *  # noqa: F401,F403
 
 # noinspection PyUnresolvedReferences
 from .test import DATABASES, LOGGING  # noqa: F401
+
+DJANGO_STRUCTLOG_COMMAND_LOGGING_ENABLED = True
diff --git a/django_structlog_demo_project/command_examples/tests/__init__.py b/django_structlog_demo_project/command_examples/tests/__init__.py
new file mode 100644
index 0000000..e69de29
diff --git a/django_structlog_demo_project/command_examples/tests/test_commands.py b/django_structlog_demo_project/command_examples/tests/test_commands.py
new file mode 100644
index 0000000..26234b0
--- /dev/null
+++ b/django_structlog_demo_project/command_examples/tests/test_commands.py
@@ -0,0 +1,16 @@
+import pytest
+from django.core import management
+
+from django_structlog_demo_project.command_examples.management.commands import (
+    example_command,
+)
+
+pytestmark = pytest.mark.django_db
+
+
+class TestCommand:
+    def test_command(self):
+        assert (
+            management.call_command(example_command.Command(), "bar", verbosity=0)
+            is None
+        )
diff --git a/test_app/tests/test_commands.py b/test_app/tests/test_commands.py
new file mode 100644
index 0000000..c99ac96
--- /dev/null
+++ b/test_app/tests/test_commands.py
@@ -0,0 +1,99 @@
+import logging
+
+import structlog
+from django.test import TestCase
+from django.core.management import BaseCommand, call_command
+from django_extensions.management.utils import signalcommand
+
+
+class TestCommands(TestCase):
+    def test_command(self):
+        class Command(BaseCommand):
+            @signalcommand
+            def handle(self, *args, **options):
+                structlog.getLogger("command").info("command_event")
+
+        with self.assertLogs(
+            "command", logging.INFO
+        ) as command_log_results, self.assertLogs(
+            "django_structlog.commands", logging.INFO
+        ) as django_structlog_commands_log_results:
+            call_command(Command())
+
+        self.assertEqual(1, len(command_log_results.records))
+        record = command_log_results.records[0]
+        self.assertEqual("command_event", record.msg["event"])
+        self.assertIn("command_id", record.msg)
+
+        self.assertEqual(2, len(django_structlog_commands_log_results.records))
+        record = django_structlog_commands_log_results.records[0]
+        self.assertEqual("command_started", record.msg["event"])
+        self.assertIn("command_id", record.msg)
+        record = django_structlog_commands_log_results.records[1]
+        self.assertEqual("command_finished", record.msg["event"])
+        self.assertIn("command_id", record.msg)
+
+    def test_nested_command(self):
+        class Command(BaseCommand):
+            @signalcommand
+            def handle(self, *args, **options):
+                logger = structlog.getLogger("command")
+                logger.info("command_event_1")
+                call_command(NestedCommand())
+                logger.info("command_event_2")
+
+        class NestedCommand(BaseCommand):
+            @signalcommand
+            def handle(self, *args, **options):
+                structlog.getLogger("nested_command").info("nested_command_event")
+
+        with self.assertLogs(
+            "command", logging.INFO
+        ) as command_log_results, self.assertLogs(
+            "nested_command", logging.INFO
+        ), self.assertLogs(
+            "django_structlog.commands", logging.INFO
+        ) as django_structlog_commands_log_results:
+            call_command(Command())
+
+        self.assertEqual(2, len(command_log_results.records))
+        command_event_1 = command_log_results.records[0]
+        self.assertEqual("command_event_1", command_event_1.msg["event"])
+        self.assertIn("command_id", command_event_1.msg)
+        command_event_2 = command_log_results.records[1]
+        self.assertEqual("command_event_2", command_event_2.msg["event"])
+        self.assertIn("command_id", command_event_2.msg)
+        self.assertEqual(
+            command_event_1.msg["command_id"], command_event_2.msg["command_id"]
+        )
+
+        self.assertEqual(4, len(django_structlog_commands_log_results.records))
+        command_started_1 = django_structlog_commands_log_results.records[0]
+        self.assertEqual("command_started", command_started_1.msg["event"])
+        self.assertIn("command_id", command_started_1.msg)
+
+        command_started_2 = django_structlog_commands_log_results.records[1]
+        self.assertEqual("command_started", command_started_2.msg["event"])
+        self.assertIn("command_id", command_started_2.msg)
+        self.assertIn("parent_command_id", command_started_2.msg)
+        self.assertEqual(
+            command_started_1.msg["command_id"],
+            command_started_2.msg["parent_command_id"],
+        )
+
+        command_finished_1 = django_structlog_commands_log_results.records[2]
+        self.assertEqual("command_finished", command_finished_1.msg["event"])
+        self.assertIn("command_id", command_finished_1.msg)
+        self.assertIn("parent_command_id", command_finished_1.msg)
+        self.assertEqual(
+            command_started_1.msg["command_id"],
+            command_finished_1.msg["parent_command_id"],
+        )
+
+        command_finished_2 = django_structlog_commands_log_results.records[3]
+        self.assertEqual("command_finished", command_finished_2.msg["event"])
+        self.assertIn("command_id", command_finished_2.msg)
+        self.assertNotIn("parent_command_id", command_finished_2.msg)
+        self.assertEqual(
+            command_event_1.msg["command_id"], command_finished_2.msg["command_id"]
+        )