Org Web Adapter

Editing pages/shortcut_218720_deadlock_issue_with_surepreme_and_webhooks.org

:PROPERTIES:
:ID:       5969d9f9-9d71-4996-864b-9f207448da6a
:LINK:     https://app.shortcut.com/sure/story/218720
:END:
#+title: Shortcut 218720 - Deadlock issue with Surepreme and Webhooks

Sentry: https://sentry.io/organizations/sure-inc/issues/3806906100/events/latest/?project=1362650&referrer=latest-event

* Overview
:PROPERTIES:
:ID:       0765b99d-9181-43c0-b21b-1334d4557ad2
:END:
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.

[[id:c86da29b-fa63-4208-8e71-16e62116c6e1][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 [2023-02-08 Wed 11:24]

[[id:c86da29b-fa63-4208-8e71-16e62116c6e1][Emmanuel Gasquez]] made some interesting observations yesterday about this issue
  that came from a chat with [[id:468c4d64-382e-46f6-8101-a430838677ac][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 [2023-02-06 Mon 11:09]

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 [2023-02-06 Mon 10:10]

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 [2023-02-03 Fri 13:41]

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 [2023-02-02 Thu 16:33]

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:

https://sentry.io/organizations/sure-inc/issues/?project=1362650&query=datadog_trace_id%3A1823456933791662634

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, [[id:dab0e5e9-390c-421c-8c93-bf768afcbecb][Jackson]] is the one who, during a coffee call of the old
  [[id:b6001958-09c7-45db-9415-15d8711579f6][PorchPals Pod]] mentioned the [[id:5646fee0-684f-4c65-bc72-d615f3b4c12d][Deadlock]] issues had been happening for
  "years, well, at least a year" which I didn't realize.

- Note taken on [2023-02-02 Thu 13:48]

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 [2023-02-02 Thu 10:52]

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 [2023-02-01 Wed 15:55]

- Note taken on [2023-02-01 Wed 12:18]

+ 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 [[id:72ef1cce-85b2-428a-a66f-2095c07d3cb3][Surepreme]] project:

https://github.com/sureapp/surepreme/commit/7b7c42b69f29fb15c0e24996524cb33c0a74c8c5