Sentry-python: celery integration RecursionError

[chemiron]

Hi there,
I upgraded sentry_sdk to 0.7.0 and started getting RecursionError if there's an issue with celery task. Sentry record doesn't contain any stack trace for that but found that error in my apm system (can attach screenshot only, text data is a real mess there). I'm running celery 4.2.1 on Ubuntu 18.

[untitaker]

Thanks for reporting! This looks like it is omitting frames happening in celery sourcecode. Are you sure this is the full stacktrace?

[chemiron]

That's a stacktrace for recursion part. After 1448 frames I can see the stack trace for that celery task. Looks like the code was executed but I'm spammed by RecursionError entries.

[untitaker]

I mean, are you sure there are no frames between the frames you showed me. For example Sentry itself has the capability to filter out irrelevant frames, I wonder if something similar is happening here

[chemiron]

no, that's all what I have.

[untitaker]

hmm, ok. I'll mark this as needs information because I don't know how to reproduce this :/

[thomasw]

I'm encountering this same issue in 0.7.3 after upgrading from 0.6.9. Oddly enough, it's happening while running my test suite. It seems to only occur in my particular environment when CELERY_ALWAYS_EAGER = True, but this might be entirely circumstantial. The test suite might just be failing for other reasons before it gets to the RecursionError because they are written to assume synchronous operation.

@chemiron, I'd be interested to hear if you are encountering the problem with always eager set to False.

In my case, the problem is happening in a django+celery app configured as follows:

# settings.py

import sentry_sdk
from sentry_sdk.integrations.celery import CeleryIntegration
from sentry_sdk.integrations.django import DjangoIntegration

sentry_sdk.init(
    dsn=secrets.sentry.dsn,
    environment=secrets.sentry.environment,
    integrations=[DjangoIntegration(), CeleryIntegration()]
)

....

CELERY_TASK_ALWAYS_EAGER = True
CELERY_TAKS_IGNORE_RESULT = True
CELERY_TASK_STORE_ERRORS_EVEN_IF_IGNORED = True
CELERY_BROKER_URL = 'redis://{host}:{port}/{db}'.format(**secrets)
CELERY_RESULT_BACKEND = 'redis://{host}:{port}/{db}'.format(**secrets)

Here's a _nearly_ complete stack trace with some app-specific stuff stripped out: https://gist.github.com/thomasw/4e0f2b1aed63fdb9509ed19d0542b434

Some possibly relevant requirements:

amqp==2.3.2
billiard==3.5.0.5
celery==4.2.1
Django==2.1.7
kombu==4.2.2.post1
redis==3.0.1
sentry-sdk==0.7.3

Python version: 3.6.1

I can provide additional environment information if needed.

[untitaker]

Could you try changing celery versions?

Unrelated to that I have a theory that you're initializing the SDK for each task, which leads to a high nesting of monkeypatched functions (so for each fork() done by celery as part of task prep, you add a frame, creating close-to-but-not-quite infinite recursion. I'm not sure when celery forks though)

If you have some kind of testsuite where this happens it would be quite interesting how you test there. The integration does have tests of its own after all.

[thomasw]

I tested this again in the following environment and I'm still seeing the same behavior:

amqp==2.4.2
billiard==3.6.0.0
celery==4.3.0
Django==2.2.1
kombu==4.5.0
redis==3.2.1
sentry-sdk==0.7.14

Both downgrading back to 0.6.9 and removing CeleryIntegration() from the integrations list resolves the issue.

The tests themselves aren't particularly interesting. An API call is made which kicks off a celery task. Since CELERY_ALWAYS_EAGER is enabled, the task is supposed to execute synchronously but instead it results in the exception I shared earlier.

class SomeResourceAPIWithValidData(SomeResourceAPITestCase):
    """PUT requests to /api/resource/<pk>/"""
    def setUp(self):
        super().setUp()

        put_data = {
            'foo': 'bar',
        }
        self.response = self.client.put(
            f'/api/resource/{self.some_resource.pk}/', put_data)
        self.status_code = self.response.status_code
        self.response = self.response.json()

    def test_are_accepted(self):
        self.assertEqual(self.status_code, 200)

This is true for any of the tests that trigger any always eager task. EDIT: This is not true. See my update below.

The API is django rest framework based, so self.client in the example above is coming from rest_framework.test.APITestCase

[untitaker]

@thomasw if you could drill this down to a self-contained but complete repro case it would be highly apprechiated. I am basically testing the sdk the same way, and just now tried with the same dependencies. So there is some mundane detail that makes our tests different.

[untitaker]

Here's a shot in the dark, does it help to patch the SDK like this?

diff --git a/sentry_sdk/integrations/celery.py b/sentry_sdk/integrations/celery.py
index 7759e61..915179f 100644
--- a/sentry_sdk/integrations/celery.py
+++ b/sentry_sdk/integrations/celery.py
@@ -35,7 +35,6 @@ class CeleryIntegration(Integration):
         def sentry_build_tracer(name, task, *args, **kwargs):
             # Need to patch both methods because older celery sometimes
             # short-circuits to task.run if it thinks it's safe.
-            task.__call__ = _wrap_task_call(task, task.__call__)
             task.run = _wrap_task_call(task, task.run)
             task.apply_async = _wrap_apply_async(task, task.apply_async)
             return _wrap_tracer(task, old_build_tracer(name, task, *args, **kwargs))

[thomasw]

@untitaker I wanted to drop in real quick to update you, but more importantly just to say that I really appreciate your help. I know it can be exceptionally difficult to investigate these types of things without a minimal reproduction. Unfortunately, I'm bouncing back and forth between a bunch of implementations and I'm having to be very opportunistic about when I poke at this. If I drop in with incomplete details from time to time, please feel free to ignore me until I say something interesting.

When I last looked at this:

Your shot in the dark did not address the issue. I made several attempts at boiling things down to a minimal reproduction. It's really nowhere near as straightforward as I let on and I apologize for misleading you. Simple tasks triggered by tests are executing fine in my environment. When I isolate and execute the tests that fail when the entire test suite runs, they pass just fine. When I increase the recursion limit (sys.setrecursionlimit(10000)), the tests also pass.

The implementations under test which are failing use locks in production to delay async processing of a bunch of database entries until the first task finishes messing with them. With CELERY_ALWAYS_EAGER enabled, the implementation unnecessarily fires and executes tasks for every modified child. It's really messy. To make it even more complicated, Django signals are firing and then being consumed elsewhere in the app which trigger even more tasks.

When I come back around to this, I'm going to write a simple test that triggers a task that then triggers a few hundred more tasks to see if I can reproduce it that way.

[untitaker]

We're on the same page, and I really apprechiate that you are investigating this!

[mentholi]

We seem to be hitting this same problem with sentry-sdk==0.8.0 and Celery==4.1.0.

Here is our trace which seems very similar: https://gist.github.com/mentholi/68ec473293258b3a135a547102a79383

In Sentry there are "maximum recursion depth exceeded" errors but no useful info on them. That stacktrace is from Celery logs.

@thomasw Are you seeing this error without CELERY_ALWAYS_EAGER = True? We also run our tests with CELERY_ALWAYS_EAGER = True but no problem there. In production (always eager disabled of course) we are hitting this.

I try to dig more later but now my priority is to just revert back to using raven.

[untitaker]

@mentholi That's interesting, right now the consensus was that always_eager is a recurring theme. Could you try downgrading the SDK to pre-0.7.0?

[mentholi]

@untitaker Ok, that's interesting. I can try downgrading but as we are hitting this problem only on our production environment it will take some time to test it. :)

[zhangheng1442]

@untitaker Hi, I got the same problem in my environment. before I use sentry==9.0.0, everything is good .
But when i upgrade to sentry==9.1.1, sentry-sdk==0.8.0 ,celery==3.1.18 , the log keep showing in the sentry worker logfile.

here are part of my logs:

sentry-worker-stdout.txt

[thomasw]

@mentholi No, I wasn't seeing this behavior with CELERY_ALWAYS_EAGER = False. At least not that I can recall.

At this point, I don't believe the problem is related to directly CELELRY_ALWAYS_EAGER. In my case, with eager execution, the task triggering depth (tasks triggering tasks triggering tasks) is much higher. Without eager execution, it's significantly reduced. My guess would be that the opposite is incidentally true in your implementation.

[mentholi]

@thomasw Our case is also that we launch multiple tasks from one task. We have this only happening in production but that is probably due to amount of objects in database and how many tasks are triggered.

I think this has something to do with "nested tasks".

[islamgulov]

Basically in Celery 3 with CELERY_ALWAYS_EAGER apply_async method calls apply, and the same task object is passed to sentry_build_tracer, so CeleryIntegration keeps wrapping already wrapped task method.

File "/lib/python3.6/site-packages/celery/app/task.py", line 551, in apply_async
  link=link, link_error=link_error, **options)
File "/lib/python3.6/site-packages/celery/app/task.py", line 743, in apply
  request=request, propagate=throw)
File "/lib/python3.6/site-packages/celery/app/trace.py", line 354, in eager_trace_task
  return build_tracer(task.name, task, **opts)(
File "/lib/python3.6/site-packages/sentry_sdk/integrations/celery.py", line 38, in sentry_build_tracer
  task.__call__ = _wrap_task_call(task, task.__call__)

The error can be reproduced by running the same task object in loop:

--- a/tests/integrations/celery/test_celery.py
+++ b/tests/integrations/celery/test_celery.py
@@ -67,7 +67,8 @@ def test_simple(capture_events, celery, invocation, expected_context):
     with configure_scope() as scope:
         scope.set_span_context(span_context)

-    invocation(dummy_task, 1, 2)
+    for _ in range(100000):
+        invocation(dummy_task, 1, 2)
     invocation(dummy_task, 1, 0)

     event, = events
(END)

for example, the test passes if if task.__call__.func_name != '_inner': check is added to sentry_build_tracer before wrapping

[untitaker]

Wow, in hindsight that seems like a very silly mistake. Thanks, I will fix
this tomorrow!

On Tue, May 28, 2019, 21:37 Ilgiz Islamgulov [e-mail]
wrote:

Basically in Celery 3 with CELERY_ALWAYS_EAGER apply_async method calls
apply, and the same task object is passed to sentry_build_tracer, so
CeleryIntegration keeps wrapping already wrapped task method.

File "/lib/python3.6/site-packages/celery/app/task.py", line 551, in apply_async
link=link, link_error=link_error, *options)
File "/lib/python3.6/site-packages/celery/app/task.py", line 743, in apply
request=request, propagate=throw)
File "/lib/python3.6/site-packages/celery/app/trace.py", line 354, in eager_trace_task
return build_tracer(task.name, task, *opts)(
File "/lib/python3.6/site-packages/sentry_sdk/integrations/celery.py", line 38, in sentry_build_tracer
task.__call__ = _wrap_task_call(task, task.__call__)

The error can be reproduced by running the same task object in loop:

--- a/tests/integrations/celery/test_celery.py+++ b/tests/integrations/celery/test_celery.py@@ -67,7 +67,8 @@ def test_simple(capture_events, celery, invocation, expected_context):
with configure_scope() as scope:
scope.set_span_context(span_context)

• invocation(dummy_task, 1, 2)+ for _ in range(100000):+ invocation(dummy_task, 1, 2)
  invocation(dummy_task, 1, 0)

 event, = events

(END)

for example, the test passes if if task.__call__.func_name != '_inner':
check is added to sentry_build_tracer before wrapping

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/getsentry/sentry-python/issues/265?email_source=notifications&email_token=AAGMPROKW7ADZVBHWFH5HRTPXWCXNA5CNFSM4GXN3GXKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODWNGQSQ#issuecomment-496658506,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAGMPRKMNM6A3ZFT4UP47SLPXWCXNANCNFSM4GXN3GXA
.

[untitaker]

See https://github.com/getsentry/sentry-python/pull/381

[untitaker]

0.8.1 is out with this bugfix. Thanks for your patience!