openwisp/openwisp-notifications

[bug] IntegrityError in notifications celery task when staff user is created

nemesifier opened this issue · 6 comments

nemesifier commented

I can replicate this in an instance installed via ansible-openwisp2.
I suspect it can be replicated also in the development environment with the celery worker running.

How to replicate:

  • create a staff user, of the group administrator, add a relation to an org and flag (is_admin=True)

Expected outcome:

  • notification settings are created

Actual outcome:

This error is logged:

IntegrityError: insert or update on table "openwisp_notifications_notificationsetting" violates foreign key constraint "openwisp_notificatio_user_id_3cc7bf95_fk_openwisp_"
DETAIL:  Key (user_id)=(13201df6-2bb2-4017-a95b-30a4e88a21a7) is not present in table "openwisp_users_user".

This error is really typical. It happens when the background task is passed to the worker before the object it must operate on is committed to the DB.

The solution is to use transaction.on_commit to call the celery task, like we do in other modules, eg:

R9295 commented

@nemesisdesign cannot seem to reproduce this.

nemesifier commented

@R9295 are you running the celery worker?
PS: the bug shows up in the celery worker, not in the web app.

R9295 commented

@nemesisdesign yup.

[2021-01-19 12:06:50,558: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fa819f488c8> (args:('openwisp_notifications.tasks.ns_user_created', 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', {'lang': 'py', 'task': 'openwisp_notifications.tasks.ns_user_created', 'id': 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'group_index': None, 'retries': 0, 'timelimit': [None, None], 'root_id': 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', 'parent_id': None, 'argsrepr': "(UUID('488170ca-9039-4cbc-b066-9822dc840ba0'), True, True)", 'kwargsrepr': '{}', 'origin': 'gen28160@r9pc', 'reply_to': '86efbac7-e386-3084-b6d7-d8bc4396b9df', 'correlation_id': 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', 'hostname': 'celery@r9pc', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': None}, 'args': ['488170ca-9039-4cbc-b066-9822dc840ba0', True, True], 'kwargs': {}}, b'[["488170ca-9039-4cbc-b066-9822dc840ba0", true, true], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
[2021-01-19 12:06:50,559: DEBUG/MainProcess] Task accepted: openwisp_notifications.tasks.ns_user_created[b61bd3fb-8f95-442f-80fc-f5490d7b1889] pid:28117

ns_user_created waits for the post_save message too

@receiver(post_save, sender=User, dispatch_uid='user_notification_setting')
def notification_setting_user_created(instance, created, **kwargs):
    tasks.ns_user_created.delay(instance.pk, instance.is_superuser, created)
nemesifier commented

@nemesisdesign yup.

[2021-01-19 12:06:50,558: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fa819f488c8> (args:('openwisp_notifications.tasks.ns_user_created', 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', {'lang': 'py', 'task': 'openwisp_notifications.tasks.ns_user_created', 'id': 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'group_index': None, 'retries': 0, 'timelimit': [None, None], 'root_id': 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', 'parent_id': None, 'argsrepr': "(UUID('488170ca-9039-4cbc-b066-9822dc840ba0'), True, True)", 'kwargsrepr': '{}', 'origin': 'gen28160@r9pc', 'reply_to': '86efbac7-e386-3084-b6d7-d8bc4396b9df', 'correlation_id': 'b61bd3fb-8f95-442f-80fc-f5490d7b1889', 'hostname': 'celery@r9pc', 'delivery_info': {'exchange': '', 'routing_key': 'celery', 'priority': 0, 'redelivered': None}, 'args': ['488170ca-9039-4cbc-b066-9822dc840ba0', True, True], 'kwargs': {}}, b'[["488170ca-9039-4cbc-b066-9822dc840ba0", true, true], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
[2021-01-19 12:06:50,559: DEBUG/MainProcess] Task accepted: openwisp_notifications.tasks.ns_user_created[b61bd3fb-8f95-442f-80fc-f5490d7b1889] pid:28117

ns_user_created waits for the post_save message too

@receiver(post_save, sender=User, dispatch_uid='user_notification_setting')
def notification_setting_user_created(instance, created, **kwargs):
    tasks.ns_user_created.delay(instance.pk, instance.is_superuser, created)

I confirm that in the test environment the bug doesn't show up, but does show up in every system deployed with ansible-openwisp2 and postgresql. It probably shows up with a DB different than SQlite, although I'm not exactly sure.

I would try the suggested fix, I can test it for you.

  • 👍1
nemesifier commented

Related PR: #167
Not ready yet.

codesankalp commented

While replicating I am getting this error:

[2021-10-05 16:40:16,621: ERROR/ForkPoolWorker-6] Task openwisp_notifications.tasks.update_superuser_notification_settings[bf8ed8e2-2f55-4ba1-a5fd-cc16737d7b1f] raised unexpected: DoesNotExist('User matching query does not exist.')
Traceback (most recent call last):
  File "/home/sankalp/Desktop/openwisp/not-env/lib/python3.7/site-packages/celery/app/trace.py", line 412, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/home/sankalp/Desktop/openwisp/not-env/lib/python3.7/site-packages/celery/app/trace.py", line 704, in __protected_call__
    return self.run(*args, **kwargs)
  File "/home/sankalp/Desktop/openwisp/openwisp-notifications/openwisp_notifications/tasks.py", line 90, in update_superuser_notification_settings
    user = User.objects.get(pk=instance_id)
  File "/home/sankalp/Desktop/openwisp/not-env/lib/python3.7/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/home/sankalp/Desktop/openwisp/not-env/lib/python3.7/site-packages/django/db/models/query.py", line 431, in get
    self.model._meta.object_name
openwisp_users.models.User.DoesNotExist: User matching query does not exist.