From dee70b6e43a93dd832a7c64ee82231da1af61240 Mon Sep 17 00:00:00 2001 From: Amber Heilman Date: Fri, 28 Aug 2015 11:43:33 -0400 Subject: [PATCH 1/4] add traceback and environment to logging --- sprockets/logging.py | 35 +++++++++++++++++++++++++++++++++-- tests.py | 7 +++++-- 2 files changed, 38 insertions(+), 4 deletions(-) diff --git a/sprockets/logging.py b/sprockets/logging.py index 28b4590..a09be5e 100644 --- a/sprockets/logging.py +++ b/sprockets/logging.py @@ -13,6 +13,7 @@ from __future__ import absolute_import from logging import config import json import logging +import os import sys try: @@ -65,6 +66,28 @@ class JSONRequestFormatter(logging.Formatter): the log data as JSON. """ + + def extract_exc_record(self, typ, val, tb): + """Create a JSON representation of the traceback given the records + exc_info + + :param `Exception` typ: Exception type of the exception being handled + :param `Exception` instance val: instance of the Exception class + :param `traceback` tb: traceback object with the call stack + + :rtype: dict + + """ + exc_record = {'type': typ.__name__, + 'message': str(val), + 'stack': []} + for file_name, line_no, func_name, txt in traceback.extract_tb(tb): + exc_record['stack'].append({'file': file_name, + 'line': str(line_no), + 'func': func_name, + 'text': txt}) + return exc_record + def format(self, record): """Return the log data as JSON @@ -72,6 +95,12 @@ class JSONRequestFormatter(logging.Formatter): :rtype: str """ + if hasattr(record, 'exc_info'): + try: + traceback = self.extract_exc_record(*record.exc_info) + except: + traceback = None + output = {'name': record.name, 'module': record.module, 'message': record.msg % record.args, @@ -81,7 +110,8 @@ class JSONRequestFormatter(logging.Formatter): 'timestamp': self.formatTime(record), 'thread': record.threadName, 'file': record.filename, - 'request': record.args} + 'request': record.args, + 'traceback': traceback} for key, value in list(output.items()): if not value: del output[key] @@ -119,7 +149,8 @@ def tornado_log_function(handler): 'protocol': handler.request.protocol, 'query_args': handler.request.query_arguments, 'remote_ip': handler.request.remote_ip, - 'status_code': status_code}) + 'status_code': status_code, + 'environment': os.environ.get('ENVIRONMENT')}) def currentframe(): diff --git a/tests.py b/tests.py index 4e2bf9e..cdc8d58 100644 --- a/tests.py +++ b/tests.py @@ -1,5 +1,6 @@ import json import logging +import os import random import unittest import uuid @@ -7,9 +8,10 @@ import uuid import mock import sprockets.logging +from tornado import web, testing LOGGER = logging.getLogger(__name__) - +os.environ['ENVIRONMENT'] = 'testing' class Prototype(object): pass @@ -91,7 +93,8 @@ class TornadoLogFunctionTestCase(unittest.TestCase): 'protocol': handler.request.protocol, 'query_args': handler.request.query_arguments, 'remote_ip': handler.request.remote_ip, - 'status_code': handler.status_code}) + 'status_code': handler.status_code, + 'environment': os.environ['ENVIRONMENT']}) sprockets.logging.tornado_log_function(handler) access_log.assertCalledOnceWith(expectation) From a249534dea4ea1fd1d904c98936b24b4520cf666 Mon Sep 17 00:00:00 2001 From: Amber Heilman Date: Fri, 28 Aug 2015 15:34:57 -0400 Subject: [PATCH 2/4] bump to 1.3.0 --- docs/history.rst | 4 ++++ sprockets/logging.py | 2 +- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/docs/history.rst b/docs/history.rst index df11097..5fd23c8 100644 --- a/docs/history.rst +++ b/docs/history.rst @@ -1,6 +1,10 @@ Version History =============== +`1.3.0`_ Aug 28, 2015 +--------------------- +- Add the traceback and environment if set + `1.2.1`_ Jun 24, 2015 --------------------- - Fix a potential ``KeyError`` when a HTTP request object is not present. diff --git a/sprockets/logging.py b/sprockets/logging.py index a09be5e..c7027fc 100644 --- a/sprockets/logging.py +++ b/sprockets/logging.py @@ -21,7 +21,7 @@ try: except ImportError: log = None -version_info = (1, 2, 1) +version_info = (1, 3, 0) __version__ = '.'.join(str(v) for v in version_info) # Shortcut methods and constants to avoid needing to import logging directly From da7b39e67bd2f3b1b31e4b40ac195421e4e5b022 Mon Sep 17 00:00:00 2001 From: Amber Heilman Date: Fri, 28 Aug 2015 17:11:54 -0400 Subject: [PATCH 3/4] add tests and test fix --- tests.py | 34 +++++++++++++++++++++++++++++++++- tox.ini | 5 ++++- 2 files changed, 37 insertions(+), 2 deletions(-) diff --git a/tests.py b/tests.py index cdc8d58..d2aba0e 100644 --- a/tests.py +++ b/tests.py @@ -96,7 +96,8 @@ class TornadoLogFunctionTestCase(unittest.TestCase): 'status_code': handler.status_code, 'environment': os.environ['ENVIRONMENT']}) sprockets.logging.tornado_log_function(handler) - access_log.assertCalledOnceWith(expectation) + access_log.info.assert_called_once_with(*expectation) + class JSONRequestHandlerTestCase(unittest.TestCase): @@ -138,3 +139,34 @@ class JSONRequestHandlerTestCase(unittest.TestCase): value = json.loads(result) for key in keys: self.assertIn(key, value) + + +class JSONRequestFormatterTestCase(testing.AsyncHTTPTestCase): + + def setUp(self): + super(JSONRequestFormatterTestCase, self).setUp() + self.recorder = RecordingHandler() + self.formatter = sprockets.logging.JSONRequestFormatter() + self.recorder.setFormatter(self.formatter) + web.app_log.addHandler(self.recorder) + + def tearDown(self): + super(JSONRequestFormatterTestCase, self).tearDown() + web.app_log.removeHandler(self.recorder) + + def get_app(self): + class JustFail(web.RequestHandler): + def get(self): + raise RuntimeError('something busted') + + return web.Application([web.url('/', JustFail)]) + + def test_that_things_happen(self): + self.fetch('/') + self.assertEqual(len(self.recorder.log_lines), 1) + + failure_info = json.loads(self.recorder.log_lines[0]) + self.assertEqual(failure_info['traceback']['type'], 'RuntimeError') + self.assertEqual(failure_info['traceback']['message'], + 'something busted') + self.assertEqual(len(failure_info['traceback']['stack']), 2) diff --git a/tox.ini b/tox.ini index 5b9e34b..7159afe 100644 --- a/tox.ini +++ b/tox.ini @@ -7,4 +7,7 @@ skip_missing_interpreters = true [testenv] commands = nosetests [] -deps = nose +deps = + nose + mock + tornado From e9440f07440b98028a61b550305037b7deb5d131 Mon Sep 17 00:00:00 2001 From: Amber Heilman Date: Fri, 28 Aug 2015 17:15:56 -0400 Subject: [PATCH 4/4] add traceback import --- sprockets/logging.py | 1 + 1 file changed, 1 insertion(+) diff --git a/sprockets/logging.py b/sprockets/logging.py index c7027fc..d6a85f8 100644 --- a/sprockets/logging.py +++ b/sprockets/logging.py @@ -15,6 +15,7 @@ import json import logging import os import sys +import traceback try: from tornado import log