djangodjango-ormdjango-loggingdjango-dev-server

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


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


Solution

  • 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!