search

getsentry / raven-python

Raven is the legacy Python client for Sentry (getsentry.com) — replaced by sentry-python
https://sentry.io
BSD 3-Clause "New" or "Revised" License
1.68k stars 657 forks source link

zope handler not recursion-protected (enough) #562

Closed ctheune closed 9 years ago

ctheune commented 9 years ago

The internal warning when the Zope handler isn't able to extract request information will cause an infinite recursion.

I've had this a couple of times where I had to get up at night that some simple errors cause raven to go into an infinite loop like this (live traceback snapshot):

  File ".../eggs/tpv.http-0.11-py2.6.egg/tpv/http/plone.py", line 135, in __call__
    log.error("%s\n%s" % (str(e), traceback.format_exc()))
  File "/usr/lib/python2.6/logging/__init__.py", line 1082, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/lib/python2.6/logging/__init__.py", line 1173, in _log
    self.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1183, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1220, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 679, in handle
    self.emit(record)
  File "/srv/webwork/deployment/work/zope/eggs/raven-5.0.0-py2.6.egg/raven/contrib/zope/__init__.py", line 100, in emit
    logger.warning('Could not extract data from request', exc_info=True)
  File "/usr/lib/python2.6/logging/__init__.py", line 1068, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/usr/lib/python2.6/logging/__init__.py", line 1173, in _log
    self.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1183, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 1220, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.6/logging/__init__.py", line 679, in handle
    self.emit(record)
  File "/srv/webwork/deployment/work/zope/eggs/raven-5.0.0-py2.6.egg/raven/contrib/zope/__init__.py", line 52, in emit
    for frame_info in getouterframes(currentframe()):
  File "/usr/lib/python2.6/inspect.py", line 931, in getouterframes
    framelist.append((frame,) + getframeinfo(frame, context))
  File "/usr/lib/python2.6/inspect.py", line 906, in getframeinfo
    lines, lnum = findsource(frame)
  File "/usr/lib/python2.6/inspect.py", line 519, in findsource
    file = getsourcefile(object) or getfile(object)
  File "/usr/lib/python2.6/inspect.py", line 451, in getsourcefile
    if hasattr(getmodule(object, filename), '__loader__'):
  File "/usr/lib/python2.6/inspect.py", line 494, in getmodule
    os.path.realpath(f)] = module.__name__

This obviously errors out with a maximum recursion depth:

  Module raven.contrib.zope, line 100, in emit
  Module logging, line 1068, in warning
  Module logging, line 1173, in _log
  Module logging, line 1183, in handle
RuntimeError: maximum recursion depth exceeded while getting the str of an object

However, it takes ages (read: 3 minutes or so) for sentry to get there and it blocks our threads when users accidentally trigger this multiple times in a row ...

I think this specific plugin needs to filter for its self-generated log-messages. (Seen at line 100 in https://github.com/getsentry/raven-python/blob/master/raven/contrib/zope/__init__.py )

xordoquy commented 9 years ago

In order to avoid this, you need to configure your logging so that the raven logger messages aren't directed to raven handler. Unless someone with a good understanding of Zope steps and opens a PR this will likely remain as it is.

ctheune commented 9 years ago

I'm pretty good with Zope. I also know the guy who contributed the plugin. Having to rely on configuration is a bit of a no go as I see people mis-configure this easily (I'm seeing the ops' people side of applications). I'm in contact with @pilz who's currently working on a solution for this. We'll get back to you with a pull request or so when we have something working.

I think the raven internals could be made to avoid recursion generally, though, by doing some stack introspection and bailing out if you're in the stack too often.

xordoquy commented 9 years ago

Sounds fair though I'd rather avoid semi magic auto reconfiguration. This usually leads to complex and hardly maintainable system. I really need to think about this. Not sure whether it wouldn't be better solved through the documentation.

xordoquy commented 9 years ago

By the way, looking forward to the next step :)

ctheune commented 9 years ago

Right. Wasn't thinking about automatic reconfiguration. However, somewhere in the stack this passes through your more generic code, right? In that case you can make semi magic detection of states that are very likely to be infinite recursions. Not much overhead and should be reliable enough. I'll get back to you when we have somethign to show. :)

xordoquy commented 9 years ago

Answering the #564 I notice that the raven logging handler shouldn't recurse like this. See: https://github.com/getsentry/raven-python/blob/master/raven/handlers/logging.py#L53-L57

xordoquy commented 9 years ago

Forget the previous comment I think I get the issue

xordoquy commented 9 years ago

@ctheune Mind testing the current master ? It shouldn't recurse as it did and should still log as usual.

pilz commented 9 years ago

We are trying that out now, I'll report back here when we have a few days of experience.