Exception in message logging kills application thread until reboot. #134

MazMachine · 2016-09-20T00:49:37Z

Summary

We encountered a UnicodeDecodeError when the logger was interpolating a message. The corrupted message was stored in thread-local memory. Therefore every subsequent request to that thread that triggered a logging call would attempt to read that corrupted message and raise the same exception, effectivly taking down the application until manually rebooted.

Details

Steps

A logger call tries to log a message that has unicode in the arguments.
log message is put in threadlocal history by rollbar
logger raises UnicodeDecodeError
Another request hits the same thread, triggers a logger call
logger attempts to read history
logger triggers same exception from the bad message

Versions:

Django 1.8.13
Python 2.7.11
pyrollbar 0.13.3

Environment

Heroku w/ gunicorn

Logging config

Using the django rollbarmiddleware
Using the rollbar log handler

Culprit:

Line that triggers the exception:

pyrollbar/rollbar/logger.py

Line 164 in 047ddab

'message': record.getMessage()}

Line that pulls in corrupted message:

pyrollbar/rollbar/logger.py

Line 30 in 047ddab

_history = threading.local()

Example Stacktrace (with some ommited data)

» 13 Sep 2016 14:39:32.861 262 <190>1 2016-09-13T21:39:32.498184+00:00 host app web.3 - DjangoLogger :: 2016-09-13 21:39:32 [ERROR] :: name=django.request func=handle_uncaught_exception lineno=256  :: Internal Server Error: /XXX/XXX/XXX ERROR /
» 13 Sep 2016 14:39:32.861 92 <190>1 2016-09-13T21:39:32.498186+00:00 host app web.3 - Traceback (most recent call last): /
» 13 Sep 2016 14:39:32.861 170 <190>1 2016-09-13T21:39:32.498187+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/site-packages/django/core/handlers/base.py", line 223, in get_response /
» 13 Sep 2016 14:39:32.861 109 <190>1 2016-09-13T21:39:32.498188+00:00 host app web.3 - response = middleware_method(request, response) /
» 13 Sep 2016 14:39:32.861 190 <190>1 2016-09-13T21:39:32.498189+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/site-packages/newrelic-2.66.0.49/newrelic/hooks/framework_django.py", line 335, in wrapper /
» 13 Sep 2016 14:39:32.861 93 <190>1 2016-09-13T21:39:32.498189+00:00 host app web.3 - return wrapped(*args, **kwargs) /
» 13 Sep 2016 14:39:32.861 173 <190>1 2016-09-13T21:39:32.498189+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/site-packages/request_logger/middleware.py", line 53, in process_response /
» 13 Sep 2016 14:39:32.861 97 <190>1 2016-09-13T21:39:32.498190+00:00 host app web.3 - self.log_request(request, response) /
» 13 Sep 2016 14:39:32.861 168 <190>1 2016-09-13T21:39:32.498191+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/site-packages/request_logger/middleware.py", line 49, in log_request /
» 13 Sep 2016 14:39:32.861 94 <190>1 2016-09-13T21:39:32.498192+00:00 host app web.3 - request.META.get('HTTP_REFERER') /
» 13 Sep 2016 14:39:32.861 140 <190>1 2016-09-13T21:39:32.498193+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/logging/__init__.py", line 1159, in info /
» 13 Sep 2016 14:39:32.861 98 <190>1 2016-09-13T21:39:32.498193+00:00 host app web.3 - self._log(INFO, msg, args, **kwargs) /
» 13 Sep 2016 14:39:32.861 140 <190>1 2016-09-13T21:39:32.498194+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/logging/__init__.py", line 1278, in _log /
» 13 Sep 2016 14:39:32.861 81 <190>1 2016-09-13T21:39:32.498194+00:00 host app web.3 - self.handle(record) /
» 13 Sep 2016 14:39:32.861 142 <190>1 2016-09-13T21:39:32.498195+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/logging/__init__.py", line 1288, in handle /
» 13 Sep 2016 14:39:32.861 87 <190>1 2016-09-13T21:39:32.498195+00:00 host app web.3 - self.callHandlers(record) /
» 13 Sep 2016 14:39:32.861 148 <190>1 2016-09-13T21:39:32.498196+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/logging/__init__.py", line 1328, in callHandlers /
» 13 Sep 2016 14:39:32.861 81 <190>1 2016-09-13T21:39:32.498196+00:00 host app web.3 - hdlr.handle(record) /
» 13 Sep 2016 14:39:32.861 141 <190>1 2016-09-13T21:39:32.498196+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/logging/__init__.py", line 751, in handle /
» 13 Sep 2016 14:39:32.861 79 <190>1 2016-09-13T21:39:32.498197+00:00 host app web.3 - self.emit(record) /
» 13 Sep 2016 14:39:32.861 151 <190>1 2016-09-13T21:39:32.498197+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/site-packages/rollbar/logger.py", line 104, in emit /
» 13 Sep 2016 14:39:32.861 101 <190>1 2016-09-13T21:39:32.498198+00:00 host app web.3 - self._add_history(record, payload_data) /
» 13 Sep 2016 14:39:32.861 159 <190>1 2016-09-13T21:39:32.498198+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/site-packages/rollbar/logger.py", line 154, in _add_history /
» 13 Sep 2016 14:39:32.861 123 <190>1 2016-09-13T21:39:32.498199+00:00 host app web.3 - history_data = [self._build_history_data(r) for r in history] /
» 13 Sep 2016 14:39:32.861 166 <190>1 2016-09-13T21:39:32.498199+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/site-packages/rollbar/logger.py", line 164, in _build_history_data /
» 13 Sep 2016 14:39:32.861 93 <190>1 2016-09-13T21:39:32.498200+00:00 host app web.3 - 'message': record.getMessage()} /
» 13 Sep 2016 14:39:32.861 145 <190>1 2016-09-13T21:39:32.498200+00:00 host app web.3 - File "/app/.heroku/python/lib/python2.7/logging/__init__.py", line 329, in getMessage /
» 13 Sep 2016 14:39:32.861 83 <190>1 2016-09-13T21:39:32.498200+00:00 host app web.3 - msg = msg % self.args /
» 13 Sep 2016 14:39:32.861 157 <190>1 2016-09-13T21:39:32.498201+00:00 host app web.3 - UnicodeDecodeError: 'ascii' codec can't decode byte 0xd9 in position 649: ordinal not in range(128) prod/XXX

The text was updated successfully, but these errors were encountered:

ezarowny · 2016-09-20T18:48:16Z

Good find! We'll take a look at this.

ezarowny · 2016-09-20T20:46:05Z

I might need a little more information or a sample function.

Using the following function, with string_to_log coming right from the Django URL dispatcher, doesn't seem to cut it when I provide a Unicode string:

def log_error(request, string_to_log):
    logger.error('not such a standard string: %s', string_to_log)

    return render(request, 'homepage/log_error.html')

For reference, the entered url was something like http://127.0.0.1:8000/log_error/héreoråre堆栈溢出/.

MazMachine · 2016-09-20T22:51:52Z

I actually have not yet been able to track the source of the UnicodeDecodeError itself yet. My current theory is that we are logging the user_agent from a request and that has unicode characters that go through our log formatter. I have yet to find out why logging the unicode character raises the exception though, as it should be handled fine.

The UnicodeDecodeError is not necessarily the problem with rollbar though. The problem I believe is that rollbar saves records to the _history regardless of if there is an exception in rendering the message. The record is added, and then there is the try/except block wrapping the getMessage call. This would prevent the error from being propogated to other subsequent requests.

It seems that either:
A: in the except block the record should be popped from _history
or
B: The record should be added to _history in the else of the try/except block

refs:
https://github.com/rollbar/pyrollbar/blob/master/rollbar/logger.py#L144
https://github.com/rollbar/pyrollbar/blob/master/rollbar/logger.py#L104

EDIT: I am re-thinking my response, noticed the exception is raised before getting to the try/except block.

ezarowny · 2016-09-21T22:41:47Z

I'm not quite sure how to get some_string % (unicode_str, unicode_str) to throw a decode error as an implicit conversion is done for you.

Edit: oh wait, if you use u prefix in front of the string you can get a decode error. Hmm!

In [15]: u'yet another string %s %s' % ('îˆ¨¥†®í', 'é®†¥üîøoπ¬¬˚∆')
---------------------------------------------------------------------------
UnicodeDecodeError                        Traceback (most recent call last)
<ipython-input-15-aaee5696c0e2> in <module>()
----> 1 u'yet another string %s %s' % ('îˆ¨¥†®í', 'é®†¥üîøoπ¬¬˚∆')

UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 0: ordinal not in range(128)

ezarowny · 2016-09-21T22:54:04Z

A better example:

In [1]: import logging

In [2]: logger = logging.getLogger(__name__)

In [3]: logger.addHandler(logging.StreamHandler())

In [4]: logger.error(u'yet another string %s %s', 'îˆ¨¥†®í', 'é®†¥üîøoπ¬¬˚∆')
Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 861, in emit
    msg = self.format(record)
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 734, in format
    return fmt.format(record)
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 465, in format
    record.message = record.getMessage()
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 329, in getMessage
    msg = msg % self.args
UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 0: ordinal not in range(128)
Logged from file <ipython-input-4-f9afb254acb2>, line 1

ezarowny · 2016-09-21T22:59:18Z

Replicated! Here we go:

In [1]: import rollbar

In [2]: import logging

In [3]: logger = logging.getLogger(__name__)

In [4]: from rollbar.logger import RollbarHandler

In [5]: rollbar.init('TOKEN', 'dev-eric')

In [6]: rollbar_handler = RollbarHandler()

In [7]: logger.addHandler(rollbar_handler)

In [8]: logger.error(u'yet another string %s %s', 'îˆ¨¥†®í', 'é®†¥üîøoπ¬¬˚∆')
Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 861, in emit
    msg = self.format(record)
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 734, in format
    return fmt.format(record)
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 465, in format
    record.message = record.getMessage()
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 329, in getMessage
    msg = msg % self.args
UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 0: ordinal not in range(128)
Logged from file <ipython-input-8-f9afb254acb2>, line 1

In [10]: logger.error(u'yet another string %s %s', 'asd', 'asd')
---------------------------------------------------------------------------
UnicodeDecodeError                        Traceback (most recent call last)
<ipython-input-10-8102186e0ffe> in <module>()
----> 1 logger.error(u'yet another string %s %s', 'asd', 'asd')

/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.pyc in error(self, msg, *args, **kwargs)
   1191         """
   1192         if self.isEnabledFor(ERROR):
-> 1193             self._log(ERROR, msg, args, **kwargs)
   1194
   1195     def exception(self, msg, *args, **kwargs):

/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.pyc in _log(self, level, msg, args, exc_info, extra)
   1284                 exc_info = sys.exc_info()
   1285         record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
-> 1286         self.handle(record)
   1287
   1288     def handle(self, record):

/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.pyc in handle(self, record)
   1294         """
   1295         if (not self.disabled) and self.filter(record):
-> 1296             self.callHandlers(record)
   1297
   1298     def addHandler(self, hdlr):

/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.pyc in callHandlers(self, record)
   1334                 found = found + 1
   1335                 if record.levelno >= hdlr.level:
-> 1336                     hdlr.handle(record)
   1337             if not c.propagate:
   1338                 c = None    #break out

/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.pyc in handle(self, record)
    757             self.acquire()
    758             try:
--> 759                 self.emit(record)
    760             finally:
    761                 self.release()

/Users/ezarowny/.virtualenvs/ipython/lib/python2.7/site-packages/rollbar/logger.pyc in emit(self, record)
    102         payload_data = getattr(record, 'payload_data', {})
    103
--> 104         self._add_history(record, payload_data)
    105
    106         # after we've added the history data, check to see if the

/Users/ezarowny/.virtualenvs/ipython/lib/python2.7/site-packages/rollbar/logger.pyc in _add_history(self, record, payload_data)
    152
    153             if history:
--> 154                 history_data = [self._build_history_data(r) for r in history]
    155                 payload_data.setdefault('server', {})['history'] = history_data
    156

/Users/ezarowny/.virtualenvs/ipython/lib/python2.7/site-packages/rollbar/logger.pyc in _build_history_data(self, record)
    162     def _build_history_data(self, record):
    163         data = {'timestamp': record.created,
--> 164                 'message': record.getMessage()}
    165
    166         if hasattr(record, 'rollbar_uuid'):

/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.pyc in getMessage(self)
    327                     msg = self.msg      #Defer encoding till later
    328         if self.args:
--> 329             msg = msg % self.args
    330         return msg
    331

UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 0: ordinal not in range(128)

Every log attempt after this keeps making the same error regardless of what you log. I'll start working on a fix. Thanks for the report!

MazMachine · 2016-09-21T23:26:20Z

Nice!
In the meantime, I have disabled the history in the handler so we do not have the same error propagation problems.

coryvirok · 2016-09-22T01:04:21Z

I think we should probably also store the formatted value in the history list instead of the record itself. That will likely result in cleaner code.

ezarowny · 2016-09-22T21:41:17Z

@MazMachine PR up at #135

ezarowny · 2016-09-22T22:48:55Z

Should be solved with #135. I'll release 0.13.5 shortly.

MazMachine · 2016-09-22T23:25:58Z

Awesome! Thanks @ezarowny

ezarowny mentioned this issue Sep 22, 2016

put record msg and args in history, remove message #135

Merged

ezarowny closed this as completed Sep 22, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Exception in message logging kills application thread until reboot. #134

Exception in message logging kills application thread until reboot. #134

MazMachine commented Sep 20, 2016 •

edited

Loading

ezarowny commented Sep 20, 2016

ezarowny commented Sep 20, 2016 •

edited

Loading

MazMachine commented Sep 20, 2016 •

edited

Loading

ezarowny commented Sep 21, 2016 •

edited

Loading

ezarowny commented Sep 21, 2016 •

edited

Loading

ezarowny commented Sep 21, 2016 •

edited

Loading

MazMachine commented Sep 21, 2016

coryvirok commented Sep 22, 2016

ezarowny commented Sep 22, 2016

ezarowny commented Sep 22, 2016 •

edited

Loading

MazMachine commented Sep 22, 2016

Exception in message logging kills application thread until reboot. #134

Exception in message logging kills application thread until reboot. #134

Comments

MazMachine commented Sep 20, 2016 • edited Loading

Summary

Details

Steps

Versions:

Environment

Logging config

Culprit:

Example Stacktrace (with some ommited data)

ezarowny commented Sep 20, 2016

ezarowny commented Sep 20, 2016 • edited Loading

MazMachine commented Sep 20, 2016 • edited Loading

ezarowny commented Sep 21, 2016 • edited Loading

ezarowny commented Sep 21, 2016 • edited Loading

ezarowny commented Sep 21, 2016 • edited Loading

MazMachine commented Sep 21, 2016

coryvirok commented Sep 22, 2016

ezarowny commented Sep 22, 2016

ezarowny commented Sep 22, 2016 • edited Loading

MazMachine commented Sep 22, 2016

MazMachine commented Sep 20, 2016 •

edited

Loading

ezarowny commented Sep 20, 2016 •

edited

Loading

MazMachine commented Sep 20, 2016 •

edited

Loading

ezarowny commented Sep 21, 2016 •

edited

Loading

ezarowny commented Sep 21, 2016 •

edited

Loading

ezarowny commented Sep 21, 2016 •

edited

Loading

ezarowny commented Sep 22, 2016 •

edited

Loading