Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

Error when logging request data in unexpected encoding #12

Closed
wants to merge 6 commits into from

2 participants

@jinty

the logger fails if PATH_INFO is in an unexpected encoding. If the error is then caught by an generic error view, that means nothing gets logged.

Attached is a patch with tests which resolves. The patch is pretty ugly, but should do the job. Improvements appreciated.

jinty added some commits
@jinty jinty Don't error on unexpected encodings
Do not error if the URL, query string or post data contains unexpected
encodings.
067cd18
@jinty jinty oops
cf0fb37
@jinty jinty the real logger.exception does not take an exc_info argument
aa62ae6
@jinty jinty Try log an exception when logging fails.
Also move logic to get the message from the
request into a private method. There was starting
to be too much logic in the tween.

The rational for logging an exception when logging
 fails is that often this component is used just
before one which converts all errors into
ServerErrors (500) thus hiding any exceptions
while logging.
675d8ff
pyramid_exclog/__init__.py
@@ -47,9 +47,25 @@ def exclog_tween(request, getLogger=getLogger):
raise
except:
logger = getLogger('exc_logger')
+ # save the traceback as it may get lost when we try decode
+ exc_info = sys.exc_info()
@tseaver Owner
tseaver added a note

Saving the traceback as a local variable creates a GC circular problem. Can you rework this to avoid that?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@jinty jinty Move error handling to a separate function
This removes a circular reference caused by saving
the traceback as a local variable. The function which
gets the traceback is not being called when the
error is raised, so it's local variables are not
referenced by the traceback.

Thanks to Tres for pointing this out:
Pylons#12 (comment)
ca39b79
@jinty

Tres: I think the circular reference is avoided now. Let me know if that is not the case.

pyramid_exclog/__init__.py
((29 lines not shown))
+
+
+ PARAMETERS
+
+ %(params)s
+
+
+ """ % dict(url=url,
+ env=pformat(request.environ),
+ params=pformat(params)))
+
+def _handle_error(request, getLogger, extra_info):
+ try:
+ # save the traceback as it may get lost when we get the message.
+ # _handle_error is not in the traceback, so no circular reference
+ exc_info = sys.exc_info()
@tseaver Owner
tseaver added a note

I'm worried that this local variable assigment (and the ones below) will create refleaks, because the traceback holds a reference to the framestack[1]. I think we need to two two things:

  • Avoid unpacking the 'exc_info' into three extra variables.

  • Capture 'exc_info' outside the current 'try:' block, but inside another one which has a 'finally:' which does 'del exc_info'

[1] http://docs.python.org/2/library/sys.html#sys.exc_info

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@tseaver
Owner

Ugh, I'm sorry I missed that we had already gone around once on the circular ref. issue. I still think we need the 'try:...finally: del exc_info' bit (and avoid assigning the 'tb' variable).

Also, can you please "sign" the CONTRIBUTORS.txt by adding your name and the date at the bottom? Thanks!

@tseaver
Owner

I just tried to merge your branch: turns out the conflicts are non-trivial. Any chance you could figure out how to replay your changes against the current master branch, preserving the new features?

Sorry that delays on our side messed up your pull. :(

@jinty

I've managed to replay the patches in a new branch no_error_on_decode_url_2 (https://github.com/jinty/pyramid_exclog/commits/no_error_on_decode_url_2). Not sure how to bring those patches into this pull request. It would be great if you merged that branch before any other pulls. Reformatting those patches was not fun.

I avoided assigning the tb variable but didn't add 'try:...finally: del exc_info' as I believe there is no circular reference. We would just make the code more complex for no gain.

The exc_info does not contain a reference to the _handle_error's locals as _handle_error is not in the traceback. I used the following code on python 2.7 to convince myself of that:

import sys
import gc

def circ():
    try:
        raise Exception()
    except:
        # Here we get a circular reference as the traceback contains a reference to this function
        exc_info = sys.exc_info()

def _handle_error():
    # NO circular reference here as _handle_error is not in the traceback
    exc_info = sys.exc_info()
    tp, value, tb = exc_info

def nocirc():
    try:
        raise Exception()
    except:
        _handle_error()

gc.disable()

gc.collect()
circ()
print gc.collect() # you see 4 here as the gc collects the circular reference
print gc.garbage

gc.collect()
nocirc()
print gc.collect() # 0 here as there were no circular references and objects were cleaned up by refcounting
print gc.garbage
@tseaver
Owner

Merged with ca0e189.

Thanks for going the extra mile -- I tried, but got snarled trying to detangle your original intent vs. the new features.

@tseaver tseaver closed this
@jinty jinty referenced this pull request from a commit in jinty/pyramid_exclog
@jinty jinty fix bug introduced by me in #12
get_message was being set to None, causing, well,
most everythng to break
0c96702
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on Nov 27, 2012
  1. @jinty

    Don't error on unexpected encodings

    jinty authored
    Do not error if the URL, query string or post data contains unexpected
    encodings.
  2. @jinty

    oops

    jinty authored
  3. @jinty
Commits on Nov 28, 2012
  1. @jinty

    Try log an exception when logging fails.

    jinty authored
    Also move logic to get the message from the
    request into a private method. There was starting
    to be too much logic in the tween.
    
    The rational for logging an exception when logging
     fails is that often this component is used just
    before one which converts all errors into
    ServerErrors (500) thus hiding any exceptions
    while logging.
Commits on Jan 29, 2013
  1. @jinty

    Move error handling to a separate function

    jinty authored
    This removes a circular reference caused by saving
    the traceback as a local variable. The function which
    gets the traceback is not being called when the
    error is raised, so it's local variables are not
    referenced by the traceback.
    
    Thanks to Tres for pointing this out:
    Pylons#12 (comment)
Commits on Jun 18, 2013
  1. @jinty
This page is out of date. Refresh to see the latest.
Showing with 104 additions and 26 deletions.
  1. +8 −0 CHANGES.txt
  2. +52 −25 pyramid_exclog/__init__.py
  3. +44 −1 pyramid_exclog/tests.py
View
8 CHANGES.txt
@@ -1,6 +1,14 @@
Next release
------------
+- Try log an exception when logging fails. The rational for logging an
+ exception when logging fails is that often this component is used just
+ before one which converts all errors into ServerErrors (500) thus
+ hiding any exceptions while logging.
+
+- Do not error if the URL, query string or post data contains unexpected
+ encodings.
+
- Changed testing regime to allow ``setup.py dev``.
- We no longer test under Python 2.5 (although it's not explicitly broken
View
77 pyramid_exclog/__init__.py
@@ -30,6 +30,56 @@ def as_globals_list(value):
L.append(obj)
return L
+def _make_log_message(request, extra_info=True):
+ try:
+ url = request.url
+ except UnicodeDecodeError:
+ # do the best we can
+ url = request.host_url + request.environ.get('SCRIPT_NAME') + request.environ.get('PATH_INFO')
+ qs = request.environ.get('QUERY_STRING')
+ if qs:
+ url += '?' + qs
+ url = 'could not decode: %r' % url
+
+ if not extra_info:
+ return url
+
+ try:
+ params = request.params
+ except UnicodeDecodeError:
+ params = 'could not decode params'
+
+ return dedent("""\n
+ %(url)s
+
+ ENVIRONMENT
+
+ %(env)s
+
+
+ PARAMETERS
+
+ %(params)s
+
+
+ """ % dict(url=url,
+ env=pformat(request.environ),
+ params=pformat(params)))
+
+def _handle_error(request, getLogger, extra_info):
+ # save the traceback as it may get lost when we get the message.
+ # _handle_error is not in the traceback, so calling sys.exc_info
+ # does NOT create a circular reference
+ exc_info = sys.exc_info()
+ try:
+ logger = getLogger('exc_logger')
+ message = _make_log_message(request, extra_info=extra_info)
+ logger.error(message, exc_info=exc_info)
+ except:
+ logger.exception("Exception while logging")
+ raise
+ raise exc_info
+
def exclog_tween_factory(handler, registry):
get = registry.settings.get
@@ -46,31 +96,8 @@ def exclog_tween(request, getLogger=getLogger):
except ignored:
raise
except:
- logger = getLogger('exc_logger')
-
-
- if extra_info:
- message = dedent("""\n
- %(url)s
-
- ENVIRONMENT
-
- %(env)s
-
-
- PARAMETERS
-
- %(params)s
-
-
- """ % dict(url=request.url,
- env=pformat(request.environ),
- params=pformat(request.params)))
- else:
- message = request.url
- logger.exception(message)
- raise
-
+ _handle_error(request, getLogger, extra_info)
+ raise AssertionError('Should never get here') # _handle_error always raises
return exclog_tween
def includeme(config):
View
45 pyramid_exclog/tests.py
@@ -1,3 +1,4 @@
+import sys
import unittest
from pyramid import testing
@@ -64,7 +65,43 @@ def test_extra_info(self):
self.assertEqual(len(self.logger.exceptions), 1)
msg = self.logger.exceptions[0]
self.assertTrue('ENVIRONMENT' in msg)
-
+
+ def test_evil_encodings(self):
+ from pyramid.request import Request
+ request = Request.blank('/\xfa') # not utf-8
+ self.assertRaises(NotImplementedError, self._callFUT, request=request)
+ self.assertEqual(len(self.logger.exceptions), 1)
+
+ def test_evil_encodings_extra_info(self):
+ from pyramid.request import Request
+ request = Request.blank('/\xfa?\xfa=\xfa') # not utf-8
+ self.registry.settings['exclog.extra_info'] = True
+ self.assertRaises(NotImplementedError, self._callFUT, request=request)
+ msg = self.logger.exceptions[0]
+ self.assertTrue('ENVIRONMENT' in msg)
+
+ def test_evil_encodings_extra_info_POST(self):
+ from pyramid.request import Request
+ request = Request.blank('/\xfa', content_type='application/x-www-form-urlencoded; charset=utf-8', POST='\xfa=\xfa') # not utf-8
+ self.registry.settings['exclog.extra_info'] = True
+ self.assertRaises(NotImplementedError, self._callFUT, request=request)
+ msg = self.logger.exceptions[0]
+ self.assertTrue('ENVIRONMENT' in msg)
+
+ def test_exception_while_logging(self):
+ from pyramid.request import Request
+ bang = AssertionError('bang')
+ class BadRequest(Request):
+ @property
+ def url(self):
+ raise bang
+ request = BadRequest.blank('/')
+ self.assertRaises(AssertionError, self._callFUT, request=request)
+ msg = self.logger.exceptions[0]
+ self.assertEqual('Exception while logging', msg)
+ raised = self.logger.exc_info[0][1]
+ self.assertEqual(raised, bang)
+
class Test_includeme(unittest.TestCase):
def _callFUT(self, config):
from pyramid_exclog import includeme
@@ -115,9 +152,15 @@ class DummyException(object):
class DummyLogger(object):
def __init__(self):
self.exceptions = []
+ self.exc_info = []
+
+ def error(self, msg, exc_info=None):
+ self.exceptions.append(msg)
+ self.exc_info.append(exc_info)
def exception(self, msg):
self.exceptions.append(msg)
+ self.exc_info.append(sys.exc_info())
class DummyConfig(object):
def __init__(self):
Something went wrong with that request. Please try again.