search

getsentry / sentry

Developer-first error tracking and performance monitoring
https://sentry.io
Other
38.93k stars 4.18k forks source link

Infinite recursion loop blows Sentry #176

Closed maraujop closed 11 years ago

maraujop commented 13 years ago

As I've commented to you on Twitter, I've tried django-debug-toolbar 0.8.5 and 0.8.6 (latest master at the moment). Both make django-sentry 1.8.5 blow.

I have been tracing the error, but haven't found anything. It gets too deep in django managers and very hard to follow. This is the best traceback I've got from it.

If I disable django-debug-toolbar, django-sentry works flawlessly and viceversa.

Traceback (most recent call last):
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/manager.py", line 92, in from_kwargs
    defaults=group_kwargs
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/manager.py", line 135, in get_or_create
    return self.get_query_set().get_or_create(**kwargs)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 378, in get_or_create
    return self.get(**lookup), False
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 344, in get
    num = len(clone)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 82, in __len__
    self._result_cache = list(self.iterator())
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 273, in iterator
    for row in compiler.results_iter():
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/sql/compiler.py", line 680, in results_iter
    for rows in self.execute_sql(MULTI):
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/sql/compiler.py", line 735, in execute_sql
    cursor.execute(sql, params)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django_debug_toolbar-0.8.6_dev-py2.6.egg/debug_toolbar/utils/tracking/db.py", line 35, in execute
    return self.cursor.execute(sql, params)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/backends/util.py", line 44, in execute
    extra={'duration':duration, 'sql':sql, 'params':params}
  File "/usr/lib/python2.6/logging/__init__.py", line 1036, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib/python2.6/logging/__init__.py", line 1165, in _log
    self.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1175, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1212, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 673, in handle
    self.emit(record)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/client/handlers.py", line 19, in emit
    get_client().create_from_record(record, request=request)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/client/base.py", line 248, in create_from_record
    **kwargs
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/client/base.py", line 165, in process
    kwargs['data'] = transform(kwargs['data'])
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 100, in transform
    ret = dict((k, transform_rec(v)) for k, v in value.iteritems())
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 100, in 
    ret = dict((k, transform_rec(v)) for k, v in value.iteritems())
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 94, in 
    transform_rec = lambda o: transform(o, stack + [value], context)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 100, in transform
    ret = dict((k, transform_rec(v)) for k, v in value.iteritems())
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 100, in 
    ret = dict((k, transform_rec(v)) for k, v in value.iteritems())
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 94, in 
    transform_rec = lambda o: transform(o, stack + [value], context)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 100, in transform
    ret = dict((k, transform_rec(v)) for k, v in value.iteritems())
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 100, in 
    ret = dict((k, transform_rec(v)) for k, v in value.iteritems())
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 94, in 
    transform_rec = lambda o: transform(o, stack + [value], context)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/sentry/utils/__init__.py", line 95, in transform
    if isinstance(value, (tuple, list, set, frozenset)):
RuntimeError: maximum recursion depth exceeded while calling a Python object
Unable to process log entry: maximum recursion depth exceeded while calling a Python object

I hope this helps, cheers, Miguel

dcramer commented 13 years ago

I just committed a change that may solve this issue. Could you try using latest master? (its not on PyPi yet)

maraujop commented 13 years ago

Hi David,

I just pulled your changes and updated django-sentry in my project. It still gets in an infinite recursion loop.

After seeing where you changed your code, I tried to find out why it's breaking, but hell this is hard. Your sentry/utils/__init.py__ is one of the hardest pieces of code to follow I've seen :D (some doc strings would help)

After playing around with the recursion error handler, I've found that it's a template rendering that detonates this. Well the template rendering, detonates something in DjDT that Sentry tries to log and when creating the GroupedMessage, DjDT captures that sql and everything starts again.

I'm getting exactly the same traceback. This time I've logged in a file the parameter value in transform function and this is what happens. As you can see it captures the template rendering and then you see APPs versions again and again till it collapses:


</head>
    <body>
        <div id="wrapper">
            <div id="topbar">
                <div id="topbarInner">

{'__sentry__': {'versions': {'uni_form': '0.8.0', 'debug_toolbar': '0.8.5', 'sentry': '1.8.5.1', 'fixture_generator': '0.2.0', 'social_auth': '0.3.1', 'indexer': '0.3.0', 'django': '1.3', 'captcha': '0.2.0', 'paging': '0.2.4', 'django_extensions': '0.6', 'taggit': '0.9.3', 'registration': '0.8 alpha 1'}}}
{'versions': {'uni_form': '0.8.0', 'debug_toolbar': '0.8.5', 'sentry': '1.8.5.1', 'fixture_generator': '0.2.0', 'social_auth': '0.3.1', 'indexer': '0.3.0', 'django': '1.3', 'captcha': '0.2.0', 'paging': '0.2.4', 'django_extensions': '0.6', 'taggit': '0.9.3', 'registration': '0.8 alpha 1'}}
{'uni_form': '0.8.0', 'debug_toolbar': '0.8.5', 'sentry': '1.8.5.1', 'fixture_generator': '0.2.0', 'social_auth': '0.3.1', 'indexer': '0.3.0', 'django': '1.3', 'captcha': '0.2.0', 'paging': '0.2.4', 'django_extensions': '0.6', 'taggit': '0.9.3', 'registration': '0.8 alpha 1'}
0.8.0
0.8.5
1.8.5.1
0.2.0
0.3.1
0.3.0
1.3
0.2.0
0.2.4
0.6
0.9.3
0.8 alpha 1

{'__sentry__': {'versions': {'uni_form': '0.8.0', 'debug_toolbar': '0.8.5', 'sentry': '1.8.5.1', 'fixture_generator': '0.2.0', 'social_auth': '0.3.1', 'indexer': '0.3.0', 'django': '1.3', 'captcha': '0.2.0', 'paging': '0.2.4', 'django_extensions': '0.6', 'taggit': '0.9.3', 'registration': '0.8 alpha 1'}}}
{'versions': {'uni_form': '0.8.0', 'debug_toolbar': '0.8.5', 'sentry': '1.8.5.1', 'fixture_generator': '0.2.0', 'social_auth': '0.3.1', 'indexer': '0.3.0', 'django': '1.3', 'captcha': '0.2.0', 'paging': '0.2.4', 'django_extensions': '0.6', 'taggit': '0.9.3', 'registration': '0.8 alpha 1'}}
{'uni_form': '0.8.0', 'debug_toolbar': '0.8.5', 'sentry': '1.8.5.1', 'fixture_generator': '0.2.0', 'social_auth': '0.3.1', 'indexer': '0.3.0', 'django': '1.3', 'captcha': '0.2.0', 'paging': '0.2.4', 'django_extensions': '0.6', 'taggit': '0.9.3', 'registration': '0.8 alpha 1'}
0.8.0
0.8.5
1.8.5.1
0.2.0
0.3.1
0.3.0
1.3
0.2.0
0.2.4
0.6
0.9.3
0.8 alpha 1

Thanks for being so fast in trying to fix this, cheers Miguel

dcramer commented 13 years ago

Do you happen to know the named logger used by the debug toolbar in this case?

Also, would you mind testing this under the latest DjDt master? (it uses an entirely new recording scheme that should circumvent problems like these)

maraujop commented 13 years ago

No I don't know the named logger, is there an easy way that I can find it out debugging the code?

I will try master later today, I will keep you posted.

Thanks

maraujop commented 13 years ago

Ok I just tried with DjDT pypi and DjDT 0.8.6-dev and both make sentry blow. This is the new traceback:


Traceback (most recent call last):
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django_sentry-1.8.5.1-py2.6.egg/sentry/utils/manager.py", line 91, in from_kwargs
    defaults=group_kwargs
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/manager.py", line 135, in get_or_create
    return self.get_query_set().get_or_create(**kwargs)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 378, in get_or_create
    return self.get(**lookup), False
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 343, in get
    clone = clone.order_by()
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 654, in order_by
    obj = self._clone()
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/query.py", line 754, in _clone
    query = self.query.clone()
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/db/models/sql/query.py", line 247, in clone
    obj.where = deepcopy(self.where, memo=memo)
  File "/usr/lib/python2.6/copy.py", line 173, in deepcopy
    y = copier(memo)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/utils/tree.py", line 61, in __deepcopy__
    obj.children = deepcopy(self.children, memodict)
  File "/usr/lib/python2.6/copy.py", line 162, in deepcopy
    y = copier(x, memo)
  File "/usr/lib/python2.6/copy.py", line 228, in _deepcopy_list
    y.append(deepcopy(a, memo))
  File "/usr/lib/python2.6/copy.py", line 173, in deepcopy
    y = copier(memo)
  File "/home/map/.virtualenvs/telollevo1.3/lib/python2.6/site-packages/django/utils/tree.py", line 61, in __deepcopy__
    obj.children = deepcopy(self.children, memodict)
  File "/usr/lib/python2.6/copy.py", line 162, in deepcopy
    y = copier(x, memo)
  File "/usr/lib/python2.6/copy.py", line 228, in _deepcopy_list
    y.append(deepcopy(a, memo))
  File "/usr/lib/python2.6/copy.py", line 162, in deepcopy
    y = copier(x, memo)
  File "/usr/lib/python2.6/copy.py", line 235, in _deepcopy_tuple
    y.append(deepcopy(a, memo))
  File "/usr/lib/python2.6/copy.py", line 189, in deepcopy
    y = _reconstruct(x, rv, 1, memo)
  File "/usr/lib/python2.6/copy.py", line 322, in _reconstruct
    args = deepcopy(args, memo)
  File "/usr/lib/python2.6/copy.py", line 162, in deepcopy
    y = copier(x, memo)
  File "/usr/lib/python2.6/copy.py", line 235, in _deepcopy_tuple
    y.append(deepcopy(a, memo))
RuntimeError: maximum recursion depth exceeded
Unable to process log entry: maximum recursion depth exceeded
coderholic commented 13 years ago

I'm seeing the same problem. Django ends up looping forever doing this query:

2011-07-25 18:43 django.db.backends DEBUG    (0.421) SELECT `django_site`.`id`, `django_site`.`domain`, `django_site`.`name` FROM `django_site` WHERE `django_site`.`id` = %s ; args=(1,)

The query seems to be triggered by "conf.SITE = Site.objects.get_current().name". I've uploaded a full backtrace to http://pastie.org/2269580 but here's the repeating section:

  /System/Library/Frameworks/Python.framework/Versions/2.6/logging/__init__.py(1009)debug()
-> self._log(DEBUG, msg, args, **kwargs)
  /System/Library/Frameworks/Python.framework/Versions/2.6/logging/__init__.py(1129)_log()
-> self.handle(record)
  /System/Library/Frameworks/Python.framework/Versions/2.6/logging/__init__.py(1139)handle()
-> self.callHandlers(record)
  /System/Library/Frameworks/Python.framework/Versions/2.6/logging/__init__.py(1176)callHandlers()
-> hdlr.handle(record)
  /System/Library/Frameworks/Python.framework/Versions/2.6/logging/__init__.py(662)handle()
-> self.emit(record)
  .../sentry/client/handlers.py(18)emit()
-> get_client().create_from_record(record, request=request)
  .../sentry/client/base.py(198)create_from_record()
-> **kwargs
  .../sentry/client/base.py(119)process()
-> kwargs = filter_(None).process(kwargs) or kwargs
  .../sentry/filters/__init__.py(138)process()
-> conf.SITE = Site.objects.get_current().name
  .../django/contrib/sites/models.py(25)get_current()
-> current_site = self.get(pk=sid)
  .../django/db/models/manager.py(132)get()
-> return self.get_query_set().get(*args, **kwargs)
  .../django/db/models/query.py(345)get()
-> num = len(clone)
  .../django/db/models/query.py(83)__len__()
-> self._result_cache = list(self.iterator())
  .../django/db/models/query.py(274)iterator()
-> for row in compiler.results_iter():
  .../django/db/models/sql/compiler.py(680)results_iter()
-> for rows in self.execute_sql(MULTI):
  .../django/db/models/sql/compiler.py(735)execute_sql()
-> cursor.execute(sql, params)
   .../debug_toolbar/panels/sql.py(146)execute()
-> extra={'duration':duration, 'sql':sql, 'params':params}
# Back to the top and around again...
dcramer commented 13 years ago

This is going to be fun to solve. We need some kind of protection within Sentry so that it can only recurse so far on the same message. I suppose we could store a (last_checksum, times_occurred) thread local and check that on each creation.

originalgremlin commented 12 years ago

Removing 'debug_toolbar.panels.logger.LoggingPanel' from the DEBUG_TOOLBAR_PANELS setting stops the infinite recursion. It's a cheap workaround that allows both tools to be (mostly) used until a real solution is found.

tadeck commented 12 years ago

I am getting similar error, but without DjDt installed. My apps include TastyPie and South, not much more. I do not even use logging yet. Any changes to fix that? I had the following error:

Top level Sentry exception caught - failed creating log record
(0.000) INSERT INTO "sentry_message" ("logger", "class_name", "level",
(...traceback...)
File "/usr/lib/python2.7/logging/__init__.py", line 464, in format
    record.message = record.getMessage()
File "/usr/lib/python2.7/logging/__init__.py", line 322, in getMessage
    if not isinstance(msg, basestring):
RuntimeError: maximum recursion depth exceeded while calling a Python object