- ID
- 5969d9f9-9d71-4996-864b-9f207448da6a
- LINK
- https://app.shortcut.com/sure/story/218720
Shortcut 218720 - Deadlock issue with Surepreme and Webhooks
Overview
- ID
- 0765b99d-9181-43c0-b21b-1334d4557ad2
Best bet on this issue is that the billing cyclist task runs every night at
midnight UTC and involves cache-locking a policy while billing is updated.
While the policy is updated, a webhook is hit to try to make an update to the
policy, and that causes our webhook dispatcher to lock up becuase it can't
update the policy while the policy is locked by the billing cycle.
Emmanuel Gasquez pointed out that the perhaps the best thing we could do we
could maybe make an on-demand queue. policy change event is fired off, blocked
due to lock (need a specific exception maybe), add policy change event to queue.
queue, waits for locks.
Here we have the [[file:~/src/github.com/sureapp/platform-core/platform_core/apps/core_protections/cyclist/async_tasks.py::if not lock_acquired:][policy cache lock]]
Post PR
- Note taken on
Emmanuel Gasquez made some interesting observations yesterday about this issue
that came from a chat with Jack Bailey:
#+begin_src slack
billing cyclist running at midnight UTC
[3:11 PM] locking up eerrrrything
[3:11 PM] so you have policies locked to do the billing (edited)
[3:11 PM] and so any mutation probably fails
[3:11 PM] also changing this
APIConsumerWebhook.objects.filter(retries__gte=self.RETRY_LIMIT)
to
APIConsumerWebhook.objects.filter(retries__gte=self.RETRY_LIMIT, disabled_at__isnull=True)
it's overzealously trying to disable the same webhook over and over and over...
[3:12 PM] but yeah billing cyclist is likely your common root or at least looking into
[3:13 PM] https://github.com/sureapp/platform-core/blob/ebfed5d377bb09928fd331277d272135bec0[…]d023/platform_core/apps/core_protections/cyclist/async_tasks.py
[3:13 PM] locky mclockerson
#+end_src
I'm working on opening a PR up for the pretty simple skip of already
disabled webhooks. I'm not sure if that will make it better, but it's worth a
shot.
Open a PR
- Note taken on
Well, I opened the PR anyhow. I don't think it's good to have a celery task
failing for a known exception over and over again. And it correlates with the
deadlock, so there's a fair chance the failing task is causing the webhook to
be disabled, which causes the deadlock due to the thundering herd. But I'm
still not super satisfied with this solution, so I'm gonna keep looking a little
bit this morning.
- Note taken on
My concern on Friday continues. I am nervous now that bailing on the billing
attempt may have unintended consequences. The task is set to back off on
retry, which means that it eventually succeeds. But I'm not sure how to not
flood the system with attempts during these backoffs.
- Note taken on
Damn. I have a test for this, and it's all ready to be submitted. But I'm not
100% sure that skipping the tasks is the best thing we can do. I'm also not
convinced that this is really the problem either.
The problem is that I saw a correlation in this error happening while the
webhooks were being marked as disabled. But I don't have solid evidence
connecting them both, just the correlation.
Tests
- Note taken on
Holy crap. While trying to figure this out, I hit the button on Sentry to show
other activities during the same datadog trace and loe and behold:
Looks like all this is caused by an exception being raised while trying to do
billing processing that causes the webhook to fail.
I actually am starting to wonder if this is actually two different issues. The
webhook dispatcher should definitely not cause a deadlock on failures, but the
scope of these failures when processing billing is likely flooding the
dispatcher.
Interestingly, Jackson is the one who, during a coffee call of the old
PorchPals Pod mentioned the Deadlock issues had been happening for
"years, well, at least a year" which I didn't realize.
- Note taken on
I've found a handful of useful tests that check webhook endpoints and am
working to build a more elaborate version that simulates the multiple attempts
to disable webhooks at the same time and hopefully recreate the bug.
Investigation
- Note taken on
This [[file:~/src/github.com/sureapp/platform-core/platform_core/services/webhooks_dispatcher.py::if self.failed_webhook_ids:][update() call to webhooks]] is the problem. Looks like it's trying to
disable failing webhooks in bulk and stopping over another call.
- Note taken on
- Note taken on
+ Initial investigation started with this [[https://iamsure.slack.com/archives/C045HKNRXHA/p1675123608140169][slack thread]]
On the face, it's just a deadlock. The Sentry errors that occurs very
consistently at midnight UTC every day.
Working this through this this afternoon and it looks more and more like the
code that dispatches webhooks in platform-core maybe the culprit.
This call may be where it originates: [[file:~/src/github.com/sureapp/surepreme/surepreme/task_list.py::PremeJob("platform_core.services.webhooks_dispatcher.send_pending_webhook_event", every="15 minutes"),][send_pending_webhook_event]] It get's
called every 15 minutes and there's some other task that must kick off at
midnight UTC that clobbers the event.
Sentry
This ops error occurs with consistency every day at 00:00 UTC:
#+begin_quote
OperationalError
deadlock detected
DETAIL: Process 103925 waits for ShareLock on transaction 213703674; blocked by process 103929.
Process 103929 waits for ShareLock on transaction 213703677; blocked by process 103948.
Process 103948 waits for ExclusiveLock on tuple (14,1) of relation 19307 of database 16403; blocked by process 103925.
HINT: See server log for query details.
CONTEXT: while locking tuple (14,1) in relation "actors_apiconsumerwebhook"
#+end_quote
It's also correlated with this git commit from the Surepreme project:
https://github.com/sureapp/surepreme/commit/7b7c42b69f29fb15c0e24996524cb33c0a74c8c5