Bind a "command_id" when using django commands

[jrobichaud]

could be used along with django-extensions's command signals

Something like this:

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)

[bcdickinson]

We've done exactly this on some of our projects and it works like a charm!

[jrobichaud]

Thanks @bcdickinson, this is reassuring.

I was currently working on implementing it.

The only thing I am not sure about it when there is an unhandled exception.

The decorator will not catch the exception.

[bcdickinson]

Hmm, good point, although the same concern (i.e. "Will this get cleaned up properly?") applies to pretty much any code using structlog.contextvars. I'm not sure there's a watertight solution for every case. Structlog's own docs aren't prescriptive, but they do suggest running clear_contextvars() at the start of whatever is using them to defend against leaks from previous code.

We get away with it because, 99.9%, of the time, management commands are run in their own process via ./manage.py my_fancy_command so nothing runs after them that would be affected by any leaked context. The only time I can see this potentially being a problem is when using call_command() in something longer lived like a gunicorn or celery worker.

[jrobichaud]

I'll spend some time to test nested commands (ex: a command calling another command) and see if there are any problems.

[jrobichaud]

especially this one:

from django.core import management
from django.core.management.commands import loaddata

management.call_command("flush", verbosity=0, interactive=False)
management.call_command("loaddata", "test_data", verbosity=0)
management.call_command(loaddata.Command(), "test_data", verbosity=0)  # <-- here

https://docs.djangoproject.com/en/4.2/ref/django-admin/#running-management-commands-from-your-code

[bcdickinson]

You could maybe do a similar trick to the way you've handled Celery task IDs:

• Assume that a command_id in the context when pre_command gets fired means this a command being run by another command and push that in as parent_command_id
• The unbind "command_id" and "parent_command_id" in the post_command handler

[jrobichaud]

The test i'll have to do is to see if the command_id is preserved.

the expected behaviour would be like this:

log 1: command_id = A
push another command
log 2: command_id = B
command finishes
log 3: command_id = A

[jrobichaud]

and handling of parent_command_id like celery task will be complex if even feasible.

[jrobichaud]

I managed to do it:

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

I decided not to log the outcome since it can be anything.

[jrobichaud]

I made a PR to django-extensions in order to be sure post_command is called.

django-extensions/django-extensions#1837

[jrobichaud]

@bcdickinson, in case you want to test it, I released 6.0.0.dev2 which includes command support. Take note this is a pre-release version, it has to be installed explicitly.

Ex:

pip install django-structlog[commands]==6.0.0.dev2

You can also take a look at django-structlog's command documentation