What version are you running?
ReviewBoard 2.5.8
What's the URL of the page containing the problem?
https://MYSERVER/reviews/r/1465/diff/1/fragment/24145/?index=0&1486735796&api_format=json
(this is loaded by the review request's diff page)
What steps will reproduce the problem?
- Load a diff page for a diff which doesn't cleanly apply.
What is the expected output? What do you see instead?
Expected: diff fragment should have a warning message like "The patch to '%(filename)s' didn't apply cleanly. The temporary files have been left in ..."
Actual: Django stack trace:
Traceback:
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/core/handlers/base.py" in get_response
118. response = middleware_method(request, e)
File "/usr/lib/python2.6/site-packages/Djblets-0.9.5-py2.6.egg/djblets/log/middleware.py" in process_exception
180. request=request)Exception Type: TypeError at /reviews/r/1465/diff/1/fragment/24145/
Exception Value: exception() got an unexpected keyword argument 'request'What operating system are you using? What browser?
ReviewBoard is hosted on RHEL 6, running Python 2.6.6
Please provide any additional information below.
ReviewBoard and Djblets use Python logging module, several methods of which don't take arbitrary keyword parameters, but only take one called 'extra'.
Having just tested, in Python 2.6.6, Python 2.7.12 and Python 3.5.2:
- logging.debug() and logging.log() accept any keyword parameters
- logging.warning(), logging.exception(), logging.error() don't accept arbitrary keyword parameters, they require extra parameters to be in a dictionary parameter called "extra"
Here, middleware.py fails because it calls logging.exception("blah", ..., request=request).
Instead, it should be logging.exception("blah", ..., extra={'request':request}) like many other parts of the Djblets/ReviewBoard codebase.
If middleware.py is fixed, the same problem happens again in reviewboard/diffviewer/views.py.
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/core/handlers/base.py" in get_response
112. response = wrapped_callback(request, callback_args, callback_kwargs)
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/views/generic/base.py" in view
69. return self.dispatch(request, *args, kwargs)
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/utils/decorators.py" in _wrapper
29. return bound_func(args, kwargs)
File "/usr/lib/python2.6/site-packages/ReviewBoard-2.5.8-py2.6.egg/reviewboard/accounts/decorators.py" in _check
23. return login_required(view_func)(*args, kwargs)
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/contrib/auth/decorators.py" in _wrapped_view
22. return view_func(request, args, kwargs)
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/utils/decorators.py" in bound_func
25. return func(self, *args2, kwargs2)
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/utils/decorators.py" in _wrapper
29. return bound_func(args, kwargs)
File "/usr/lib/python2.6/site-packages/ReviewBoard-2.5.8-py2.6.egg/reviewboard/site/decorators.py" in _check
35. return view_func(request, local_site=local_site, *args, kwargs)
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/utils/decorators.py" in bound_func
25. return func(self, args2, kwargs2)
File "/usr/lib/python2.6/site-packages/Djblets-0.9.5-py2.6.egg/djblets/util/decorators.py" in _call
75. f = augmented_func(*args, kwargs)
File "/usr/lib/python2.6/site-packages/Django-1.6.11-py2.6.egg/django/views/generic/base.py" in dispatch
87. return handler(request, args, **kwargs)
File "/usr/lib/python2.6/site-packages/ReviewBoard-2.5.8-py2.6.egg/reviewboard/diffviewer/views.py" in get
309. request=request)
Exception Type: TypeError at /reviews/r/1465/diff/1/fragment/24145/
Exception Value: exception() got an unexpected keyword argument 'request'
If that's fixed, finally ReviewBoard works correctly: it reports that the diff didn't apply cleanly.
I looked for all usages of logging.loggingmethod() (error, warning, exception, debug, critical, info, log) with keyword args in them, and came down to this:
In Djblets-0.9.5:
djblets/webapi/auth/backends/api_tokens.py: logging.warning('WebAPITokenAuthBackend: Missing token in ' 'HTTP_AUTHORIZATION header %s', http_auth, extra={'request': request})
djblets/webapi/auth/backends/basic.py: logging.warning("Failed to parse HTTP_AUTHORIZATION header %s" % request.META['HTTP_AUTHORIZATION'], exc_info=1, extra={'request': request})
djblets/webapi/auth/backends/base.py: logging.debug( 'Attempting authentication on API: %s', ', '.join([ '%s=%s' % pair for pair in six.iteritems(cleaned_credentials) ]), extra=log_extra)
djblets/webapi/auth/backends/base.py: logging.debug('API Login failed. No valid user found.', extra=log_extra)
djblets/datagrid/grids.py: logging.error("Unable to load template '%s' for datagrid " "cell. This may be an installation issue.", self.cell_template, extra={ 'request': self.request, })
djblets/datagrid/grids.py: logging.error("Unable to load template '%s' for datagrid " "column headers. This may be an installation " "issue.", self.column_header_template, extra={ 'request': self.request, })
djblets/log/__init__.py: logging.log(self.default_level, "Begin: %s" % self.message, request=self.request)
djblets/log/__init__.py: logging.log(self.default_level, "End: %s" % self.message, request=self.request)
djblets/log/__init__.py: logging.log(level, '%s took %d.%06d seconds' % (self.message, delta.seconds, delta.microseconds), request=self.request)
djblets/log/middleware.py: logging.exception('Exception thrown for user %s at %s\n\n%s', request.user, request.build_absolute_uri(), exception, request=request)
In ReviewBoard-2.5.8:
reviewboard/webapi/resources/base_file_attachment.py: logging.error( 'Failed to store thumbnail for attachment %d: %s', file.pk, e, request=request)
reviewboard/webapi/resources/repository.py: logging.error('Got unexpected SSHError when checking ' 'repository: %s' % e, exc_info=1, request=request)
reviewboard/webapi/resources/repository.py: logging.error('Got unexpected SCMError when checking ' 'repository: %s' % e, exc_info=1, request=request)
reviewboard/webapi/resources/repository.py: logging.error('Unknown error in checking repository %s: %s', path, e, exc_info=1, request=request)
reviewboard/webapi/resources/base_patched_file.py: logging.error('%s: Error retrieving original file for FileDiff ' '%s: %s', self.__class__.__name__, filediff.pk, e, exc_info=1, request=request)
reviewboard/webapi/resources/base_patched_file.py: logging.error('%s: Error retrieving patched file for FileDiff %' '%s: %s', self.__class__.__name__, filediff.pk, e, exc_info=1, request=request)
reviewboard/webapi/resources/base_original_file.py: logging.error('%s: Error retrieving original file for FileDiff ' '%s: %s', self.__class__.__name__, filediff.pk, e, exc_info=1, request=request)
reviewboard/webapi/resources/diff.py: logging.error("Error uploading new diff: %s", e, exc_info=1, request=request)
reviewboard/reviews/models/group.py: logging.warning('Group pk=%d (%s) is not accessible by user ' '%s because its local_site is not accessible ' 'by that user.', self.pk, self.name, user, request=request)
reviewboard/reviews/models/group.py: logging.warning('Group pk=%d (%s) is not accessible by user %s ' 'because it is invite only, and the user is not a ' 'member.', self.pk, self.name, user, request=request)
reviewboard/reviews/models/review_request.py: logging.warning('Review Request pk=%d (display_id=%d) is not ' 'accessible by user %s because it has not yet ' 'been published.', self.pk, self.display_id, user, request=request)
reviewboard/reviews/models/review_request.py: logging.warning('Review Request pk=%d (display_id=%d) is not ' 'accessible by user %s because its repository ' 'is not accessible by that user.', self.pk, self.display_id, user, request=request)
reviewboard/reviews/models/review_request.py: logging.warning('Review Request pk=%d (display_id=%d) is not ' 'accessible by user %s because its local_site ' 'is not accessible by that user.', self.pk, self.display_id, user, request=request)
reviewboard/reviews/models/review_request.py: logging.warning('Review Request pk=%d (display_id=%d) is not ' 'accessible by user %s because they are not ' 'directly listed as a reviewer, and none of ' 'the target groups are accessible by that user.', self.pk, self.display_id, user, request=request)
reviewboard/diffviewer/views.py: logging.debug('Generating diff viewer page for interdiffset ' 'ids %s-%s', diffset.id, interdiffset.id, request=request)
reviewboard/diffviewer/views.py: logging.debug('Generating diff viewer page for filediff id %s', diffset.id, request=request)
reviewboard/diffviewer/views.py: logging.debug('Done generating diff viewer page for ' 'interdiffset ids %s-%s', diffset.id, interdiffset.id, request=request)
reviewboard/diffviewer/views.py: logging.debug('Done generating diff viewer page for filediff ' 'id %s', diffset.id, request=request)
reviewboard/diffviewer/views.py: logging.exception('%s.get: Error rendering diff for diffset ' 'ID=%s, interdiffset ID=%s: %s', self.__class__.__name__, diffset.pk, interdiffset_id, e, request=request)
reviewboard/diffviewer/views.py: logging.exception('%s.get: Error when processing diffset info ' 'for filediff ID=%s, interfilediff ID=%s, ' 'chunkindex=%s: %s', self.__class__.__name__, kwargs.get('filediff_id'), kwargs.get('interfilediff_id'), kwargs.get('chunkindex'), e, request=request)
reviewboard/diffviewer/views.py: logging.exception('%s.get: Error when rendering diffset for ' 'filediff ID=%s, interfilediff ID=%s, ' 'chunkindex=%s: %s', self.__class__.__name__, kwargs.get('filediff_id'), kwargs.get('interfilediff_id'), kwargs.get('chunkindex'), e, request=request)
Which, when made entirely generic (replacing strings and multiple-arguments with test arguments), becomes this:
logging.debug('test %s', 'test', extra=None)
logging.debug('test', extra=None)
logging.debug('test %s', 'test', request=None)
logging.error('test %s', 'test', request=None)
logging.error('test %s', 'test', exc_info=1, request=None)
logging.error('test %s', 'test', extra={'request': None})
logging.exception('test %s', 'test', request=None)
logging.log(logging.INFO, 'test', request=None)
logging.warning('test', exc_info=1, extra={'request': None})
logging.warning('test %s', 'test', request=None)
logging.warning('test %s', 'test', extra={'request': None})
I then tested running these in Python 3.5.2:
These work:
logging.debug('test %s', 'test', extra=None)
logging.debug('test', extra=None)
logging.debug('test %s', 'test', request=None)
logging.error('test %s', 'test', extra={'request': None})
logging.log(logging.INFO, 'test', request=None)
logging.warning('test', exc_info=1, extra={'request': None})
* logging.warning('test %s', 'test', extra={'request': None})
These fail:
logging.error('test %s', 'test', request=None)
logging.error('test %s', 'test', exc_info=1, request=None)
logging.exception('test %s', 'test', request=None)
logging.warning('test %s', 'test', request=None)
So in the code base, I've changed all "request=request" in logging.error(), logging.exception(), logging.warning() to extra={'request':request}
So what's happening here is that we actually wrap all logging methods to add support for
request=. We used to support Python 2.4, back when this was added, and there was noextra=back then. However, what we have should continue to work just fine today, provided that the code doing the wrapping is initialized. This is happening indjblets/log/__init__.py(see_wrap_logger).My thinking is that somehow, the wrapping is either not occurring or is being undone. I wish I knew why, but I don't. However, moving to
extra=is better all around.We still haven't hit this on our end, and I want to figure out why that is. Can you tell me:
1) Do you have any extensions loaded?
2) Do you have any custom logging configuration anywhere insettings_local.py?
3) Is logging enabled on your system?
4) What's your web server configuration like? (Apache? mod_wsgi? What does that configuration look like?)
-
- New + NeedInfo -
+ reviewboard:Release-2.5.x -
- Priority:Medium + Priority:High -
+ chipx86
Okay, I've figured this out fully. Here's the situation.
All the logging methods (
logging.debug,logging.info,logging.warning,logging.error,logging.exception,logging.critical, andlogging.log) go through a common method on the root logger,logging.RootLogger._log(which is reallylogging.Logger._log). They are supposed to pass their arguments and keyword arguments to this method, which then interprets them. This is what understands things like theextra=keyword argument.We wrap
_logon the root logger in order to accept arequest=argument, as a convenience. That turns into aextra={'request': request}. This has been working for years, hence my surprise at the recent bug reports. However, now it makes sense.In some versions of Python (2.6.x, 2.7.0 through 2.7.5, 3.0.x, and 3.1.x),
logging.exception()had a bug where keyword arguments were not accepted. The rest of the logging methods supported them, but whenlogging.exception()was introduced, it was left off. This bug remained until Python 2.7.6 and 3.2.The reason this started cropping up now is that, as part of some cleanup code, we started changing functions like this:
logging.error('...', request=request, exc_info=True)to this:
logging.exception('...', request=request)The two calls are identical, basically. The latter is a wrapper for the former. However, since
logging.exception()was lacking support for keyword arguments, this was failing on older versions of Python. Most people these days, according to our stats, use newer versions of Python 2.7.x, which is why we haven't been completely bombarded with bug reports, and why this wasn't happening on any servers under our control. (Worth noting that Review Board 3.0 will require a newer version of Python than 2.7.5).The solution, it turns out, is not as simple as moving to
extra={'request': request}. That would be wonderful. However, once again, that requires keyword argument support inlogging.exception(), which doesn't exist in these versions.The good news is that we can intelligently monkey-patch
logging.Logger.exception()to support keyword arguments if we determine it's lacking. We can also patchlogging.exception(), which will work for anyone that doesn't dofrom logging import exception(which won't be us, and is a terrible idea -- this has to do with how imports work in Python).This is what I'm working on now, and we should be able to ship this Wednesday.
-
- NeedInfo + Confirmed
Fix pushed to release-0.8.x (6c2e1c1ae558d6fd041a64ef4ff85e45db37a707) and merged to newer branches. This will ship in new Review Board releases tomorrow.
-
- PendingReview + Fixed -
- reviewboard + djblets -
+ Release-0.8.x + Release-0.9.x + reviewboard:Release-2.0.x -
+ Logging