In Django, is it possible to see which method is generating a SQL query?

Question

When creating a custom User (inherits from AbstractUser) we have a signal which creates a randomized password (from Django's get_random_string) and send it out in an email in a celery task to the user.

# accounts/models.py
class User(AbstractUser):
    # ...

    def save(self, *args, **kwargs):
        if self.avatar:
            self.avatar = resized_image(self.avatar, settings.SOCIAL_AVATAR_SIZE)
        super().save(*args, **kwargs)

resized_image returns from django.core.files.uploadedfile import InMemoryUploadedFile

# accounts/signals.py
@receiver(post_save, sender=User, dispatch_uid="c_employee")
def create_employee(sender, instance: User, created, **kwargs):
    if not instance.has_usable_password():
        password = get_random_string(length=12)

    email_args = {  # we're collecting information for the celery task
        "password": password,
    }
    email_send_as_task.delay(
        email_args, "Sending PASSWORD CREATE email to {{ instance.email }}"
    )
    
    if password:
        logger.debug(f"CREATE PASSWORD FOR INSTANCE: {instance}")
        sender.objects.filter(pk=instance.pk).update(password=make_password(password))  # .update so we don't trigger signal again

And looking through my (logging level DEBUG) logs, I can see the following:

D0121 18:55:35.434 accounts.signals:81 CREATE PASSWORD FOR INSTANCE: Employee @ Example
D0121 18:55:35.641 django.db.backends:123 (0.000) UPDATE "accounts_user" SET "password" = 'pbkdf2_sha256$260000$FKRktQOZAwQ4OjcvD3QHGn$dmg9T1Y3mEwN1nbI5W2EyOAHp2chU4MGvSlaOTORNxY=' WHERE "accounts_user"."id" = 394; args=('pbkdf2_sha256$260000$FKRktQOZAwQ4OjcvD3QHGn$dmg9T1Y3mEwN1nbI5W2EyOAHp2chU4MGvSlaOTORNxY=', 394)

So far so good.

But then, later in the logs, this query appears:

D0121 18:55:35.770 django.db.backends:123 (0.015) UPDATE "accounts_user" SET "password" = '', "last_login" = NULL, "is_superuser" = false, "username" = 'employee@example.com', "first_name" = 'First name', "last_name" = 'Employee', "email" = 'employee@example.com', "is_staff" = false, "is_active" = true, "date_joined" = '2023-01-21T17:55:35.044046+00:00'::timestamptz, "company_id" = 20, "venue_id" = 297, "avatar" = 'users/avatar.jpg', "is_admin" = false, "is_developer" = true, "role" = 'event', "allow_update" = true, "device_id" = NULL WHERE "accounts_user"."id" = 394; args=('', False, 'employee@example.com', 'First name', 'Employee', 'employee@example.com', False, True, datetime.datetime(2023, 1, 21, 17, 55, 35, 44046, tzinfo=<UTC>), 20, 297, 'users/avatar.jpg', False, True, 'event', True, 394)

My question is thus: why is the password re-set to empty string? And how do I go about debugging/understanding where this query originates from?

TYIA

I haven't used it myself but you might look at one of the packages mentioned in this answer: https://stackoverflow.com/a/50452057 Offhand I'd say the extra query looks like your `user` instance getting `save()` called on it again somewhere, with an instance that doesn't have the password set. That is, you make an in-memory user and save it, and your signal makes a randomized password and saves that - but the in-memory user doesn't know about it and if something later in the code re-saves it'll act like this. You could just set the password on `instance` in the signal to maybe fix it. — Peter DeGlopper, Jan 21 '23 at 19:25

kunambi · Accepted Answer · 2023-01-22T00:09:15.813

Apparently it seems that we're running into a race-condition when writing to the DB. It seems that calling a method outside of the signal doesn't trigger another call to the post_save signal when we're already inside it.

This is how the working solution looks like atm:

# accounts/signals.py
from accounts.utils import create_password


@receiver(post_save, sender=User, dispatch_uid="c_employee")
def create_employee(sender, instance: User, created, **kwargs):
    if not instance.has_usable_password():
        logger.debug(f"CREATE PASSWORD FOR INSTANCE: {instance}")
        password = create_password(obj=instance)

    email_args = {  # we're collecting information for the celery task
        "password": password,
    }
    email_send_as_task.delay(
        email_args, "Sending PASSWORD CREATE email to {{ instance.email }}"
    )

and in the utils.py file:

# accounts/utils.py
from django.utils.crypto import get_random_string


def create_password(obj=None, length=12):
    password = get_random_string(length=length)
    if obj is not None:
        obj.set_password(password)
        obj.save()
    return password

I have to surmise that there is some Django magic I yet haven't understood. Unfortunatelly this doesn't answer the question in the headline but using .save() instead of .update() solved my problem.

The comment from @peter-deglopper pointed me in the right direction. Thanks!

In Django, is it possible to see which method is generating a SQL query?

1 Answers1