2015-11-18 21:15:37 +00:00
|
|
|
import logging
|
|
|
|
|
2015-11-19 13:02:47 +00:00
|
|
|
from tornado import httputil, testing, web
|
2015-11-18 21:15:37 +00:00
|
|
|
|
2015-11-19 13:02:47 +00:00
|
|
|
from sprockets.http import mixins
|
2015-11-18 21:15:37 +00:00
|
|
|
import examples
|
|
|
|
|
|
|
|
|
|
|
|
class RecordingHandler(logging.Handler):
|
|
|
|
|
|
|
|
def __init__(self):
|
|
|
|
super(RecordingHandler, self).__init__()
|
|
|
|
self.emitted = []
|
|
|
|
|
|
|
|
def emit(self, record):
|
|
|
|
self.emitted.append((record, self.format(record)))
|
|
|
|
|
|
|
|
|
2015-11-19 13:02:47 +00:00
|
|
|
class RaisingHandler(mixins.ErrorLogger, web.RequestHandler):
|
|
|
|
|
|
|
|
def get(self, status_code):
|
|
|
|
raise web.HTTPError(int(status_code),
|
|
|
|
reason=self.get_query_argument('reason', None))
|
|
|
|
|
|
|
|
|
2015-11-19 16:54:23 +00:00
|
|
|
class ErrorLoggerTests(testing.AsyncHTTPTestCase):
|
2015-11-18 21:15:37 +00:00
|
|
|
|
|
|
|
def setUp(self):
|
2015-11-19 16:54:23 +00:00
|
|
|
super(ErrorLoggerTests, self).setUp()
|
2015-11-18 21:15:37 +00:00
|
|
|
self.recorder = RecordingHandler()
|
|
|
|
root_logger = logging.getLogger()
|
|
|
|
root_logger.addHandler(self.recorder)
|
|
|
|
|
|
|
|
def tearDown(self):
|
2015-11-19 16:54:23 +00:00
|
|
|
super(ErrorLoggerTests, self).tearDown()
|
2015-11-18 21:15:37 +00:00
|
|
|
logging.getLogger().removeHandler(self.recorder)
|
|
|
|
|
|
|
|
def get_app(self):
|
2015-11-19 13:02:47 +00:00
|
|
|
return web.Application([
|
|
|
|
web.url(r'/status/(?P<status_code>\d+)', examples.StatusHandler),
|
|
|
|
web.url(r'/fail/(?P<status_code>\d+)', RaisingHandler),
|
|
|
|
])
|
2015-11-18 21:15:37 +00:00
|
|
|
|
|
|
|
def assert_message_logged(self, level, msg_fmt, *msg_args):
|
|
|
|
suffix = msg_fmt.format(*msg_args)
|
|
|
|
for record, message in self.recorder.emitted:
|
2015-11-19 13:02:47 +00:00
|
|
|
if record.levelno == level and message.endswith(suffix):
|
|
|
|
return
|
|
|
|
self.fail('Expected message ending in "%s" to be logged in %r'
|
|
|
|
% (suffix, self.recorder.emitted))
|
2015-11-18 21:15:37 +00:00
|
|
|
|
|
|
|
def test_that_client_error_logged_as_warning(self):
|
|
|
|
self.fetch('/status/400')
|
|
|
|
self.assert_message_logged(
|
|
|
|
logging.WARNING, 'failed with 400: {}', httputil.responses[400])
|
|
|
|
|
|
|
|
def test_that_server_error_logged_as_error(self):
|
|
|
|
self.fetch('/status/500')
|
|
|
|
self.assert_message_logged(
|
|
|
|
logging.ERROR, 'failed with 500: {}', httputil.responses[500])
|
|
|
|
|
|
|
|
def test_that_custom_status_codes_logged_as_unknown(self):
|
|
|
|
self.fetch('/status/623')
|
|
|
|
self.assert_message_logged(logging.ERROR, 'failed with 623: Unknown')
|
|
|
|
|
|
|
|
def test_that_custom_reasons_are_supported(self):
|
|
|
|
self.fetch('/status/456?reason=oops')
|
|
|
|
self.assert_message_logged(logging.WARNING, 'failed with 456: oops')
|
2015-11-19 13:02:47 +00:00
|
|
|
|
|
|
|
def test_that_status_code_extracted_from_http_errors(self):
|
|
|
|
self.fetch('/fail/400')
|
|
|
|
self.assert_message_logged(
|
|
|
|
logging.WARNING, 'failed with 400: {}', httputil.responses[400])
|
|
|
|
|
|
|
|
def test_that_reason_extracted_from_http_errors(self):
|
|
|
|
self.fetch('/fail/400?reason=oopsie')
|
|
|
|
self.assert_message_logged(logging.WARNING, 'failed with 400: oopsie')
|
2015-11-19 16:51:34 +00:00
|
|
|
|
|
|
|
def test_that_log_message_is_honored(self):
|
|
|
|
self.fetch('/status/400?log_message=injected%20message')
|
|
|
|
self.assert_message_logged(logging.WARNING,
|
|
|
|
'failed with 400: injected message')
|