Captured logging in tests with self.assertLogs().

This commit is contained in:
Claude Paroz 2018-04-29 11:02:51 +02:00 committed by Tim Graham
parent 607970f31c
commit 523e04dfeb
3 changed files with 66 additions and 84 deletions

View File

@ -1,4 +1,3 @@
import logging
from io import BytesIO
from django.core.handlers.wsgi import WSGIRequest
@ -18,36 +17,26 @@ class Stub:
class WSGIRequestHandlerTestCase(SimpleTestCase):
def test_log_message(self):
# Silence the django.server logger by replacing its StreamHandler with
# NullHandler.
logger = logging.getLogger('django.server')
original_handlers = logger.handlers
logger.handlers = [logging.NullHandler()]
try:
request = WSGIRequest(RequestFactory().get('/').environ)
request.makefile = lambda *args, **kwargs: BytesIO()
handler = WSGIRequestHandler(request, '192.168.0.2', None)
level_status_codes = {
'info': [200, 301, 304],
'warning': [400, 403, 404],
'error': [500, 503],
}
for level, status_codes in level_status_codes.items():
for status_code in status_codes:
# The correct level gets the message.
with self.assertLogs('django.server', level.upper()) as cm:
handler.log_message('GET %s %s', 'A', str(status_code))
self.assertIn('GET A %d' % status_code, cm.output[0])
# Incorrect levels shouldn't have any messages.
for wrong_level in level_status_codes:
if wrong_level != level:
with self.assertRaisesMessage(AssertionError, 'no logs'):
with self.assertLogs('django.template', level.upper()):
handler.log_message('GET %s %s', 'A', str(status_code))
finally:
logger.handlers = original_handlers
request = WSGIRequest(RequestFactory().get('/').environ)
request.makefile = lambda *args, **kwargs: BytesIO()
handler = WSGIRequestHandler(request, '192.168.0.2', None)
level_status_codes = {
'info': [200, 301, 304],
'warning': [400, 403, 404],
'error': [500, 503],
}
for level, status_codes in level_status_codes.items():
for status_code in status_codes:
# The correct level gets the message.
with self.assertLogs('django.server', level.upper()) as cm:
handler.log_message('GET %s %s', 'A', str(status_code))
self.assertIn('GET A %d' % status_code, cm.output[0])
# Incorrect levels don't have any messages.
for wrong_level in level_status_codes:
if wrong_level != level:
with self.assertLogs('django.server', 'INFO') as cm:
handler.log_message('GET %s %s', 'A', str(status_code))
self.assertNotEqual(cm.records[0].levelname, wrong_level.upper())
def test_https(self):
request = WSGIRequest(RequestFactory().get('/').environ)

View File

@ -4,29 +4,7 @@ from django.template import Engine, Variable, VariableDoesNotExist
from django.test import SimpleTestCase
class TestHandler(logging.Handler):
def __init__(self):
super().__init__()
self.log_record = None
def emit(self, record):
self.log_record = record
class BaseTemplateLoggingTestCase(SimpleTestCase):
def setUp(self):
self.test_handler = TestHandler()
self.logger = logging.getLogger('django.template')
self.original_level = self.logger.level
self.logger.addHandler(self.test_handler)
self.logger.setLevel(self.loglevel)
def tearDown(self):
self.logger.removeHandler(self.test_handler)
self.logger.level = self.original_level
class VariableResolveLoggingTests(BaseTemplateLoggingTestCase):
class VariableResolveLoggingTests(SimpleTestCase):
loglevel = logging.DEBUG
def test_log_on_variable_does_not_exist_silent(self):
@ -52,31 +30,38 @@ class VariableResolveLoggingTests(BaseTemplateLoggingTestCase):
def __getitem__(self, item):
return self.__dict__[item]
Variable('article').resolve(TestObject())
with self.assertLogs('django.template', self.loglevel) as cm:
Variable('article').resolve(TestObject())
self.assertEqual(len(cm.records), 1)
log_record = cm.records[0]
self.assertEqual(
self.test_handler.log_record.getMessage(),
log_record.getMessage(),
"Exception while resolving variable 'article' in template 'template_name'."
)
self.assertIsNotNone(self.test_handler.log_record.exc_info)
raised_exception = self.test_handler.log_record.exc_info[1]
self.assertIsNotNone(log_record.exc_info)
raised_exception = log_record.exc_info[1]
self.assertEqual(str(raised_exception), 'Attribute does not exist.')
def test_log_on_variable_does_not_exist_not_silent(self):
with self.assertRaises(VariableDoesNotExist):
Variable('article.author').resolve({'article': {'section': 'News'}})
with self.assertLogs('django.template', self.loglevel) as cm:
with self.assertRaises(VariableDoesNotExist):
Variable('article.author').resolve({'article': {'section': 'News'}})
self.assertEqual(len(cm.records), 1)
log_record = cm.records[0]
self.assertEqual(
self.test_handler.log_record.getMessage(),
log_record.getMessage(),
"Exception while resolving variable 'author' in template 'unknown'."
)
self.assertIsNotNone(self.test_handler.log_record.exc_info)
raised_exception = self.test_handler.log_record.exc_info[1]
self.assertIsNotNone(log_record.exc_info)
raised_exception = log_record.exc_info[1]
self.assertEqual(
str(raised_exception),
"Failed lookup for key [author] in {'section': 'News'}"
)
def test_no_log_when_variable_exists(self):
Variable('article.section').resolve({'article': {'section': 'News'}})
self.assertIsNone(self.test_handler.log_record)
with self.assertRaisesMessage(AssertionError, 'no logs'):
with self.assertLogs('django.template', self.loglevel):
Variable('article.section').resolve({'article': {'section': 'News'}})

View File

@ -57,22 +57,25 @@ class CallableSettingWrapperTests(SimpleTestCase):
@override_settings(DEBUG=True, ROOT_URLCONF='view_tests.urls')
class DebugViewTests(LoggingCaptureMixin, SimpleTestCase):
class DebugViewTests(SimpleTestCase):
def test_files(self):
response = self.client.get('/raises/')
with self.assertLogs('django.request', 'ERROR'):
response = self.client.get('/raises/')
self.assertEqual(response.status_code, 500)
data = {
'file_data.txt': SimpleUploadedFile('file_data.txt', b'haha'),
}
response = self.client.post('/raises/', data)
with self.assertLogs('django.request', 'ERROR'):
response = self.client.post('/raises/', data)
self.assertContains(response, 'file_data.txt', status_code=500)
self.assertNotContains(response, 'haha', status_code=500)
def test_400(self):
# When DEBUG=True, technical_500_template() is called.
response = self.client.get('/raises400/')
with self.assertLogs('django.security', 'WARNING'):
response = self.client.get('/raises400/')
self.assertContains(response, '<div class="context" id="', status_code=400)
# Ensure no 403.html template exists to test the default case.
@ -139,7 +142,8 @@ class DebugViewTests(LoggingCaptureMixin, SimpleTestCase):
Numeric IDs and fancy traceback context blocks line numbers shouldn't be localized.
"""
with self.settings(DEBUG=True, USE_L10N=True):
response = self.client.get('/raises500/')
with self.assertLogs('django.request', 'ERROR'):
response = self.client.get('/raises500/')
# We look for a HTML fragment of the form
# '<div class="context" id="c38123208">', not '<div class="context" id="c38,123,208"'
self.assertContains(response, '<div class="context" id="', status_code=500)
@ -152,15 +156,16 @@ class DebugViewTests(LoggingCaptureMixin, SimpleTestCase):
)
def test_template_exceptions(self):
try:
self.client.get(reverse('template_exception'))
except Exception:
raising_loc = inspect.trace()[-1][-2][0].strip()
self.assertNotEqual(
raising_loc.find("raise Exception('boom')"), -1,
"Failed to find 'raise Exception' in last frame of "
"traceback, instead found: %s" % raising_loc
)
with self.assertLogs('django.request', 'ERROR'):
try:
self.client.get(reverse('template_exception'))
except Exception:
raising_loc = inspect.trace()[-1][-2][0].strip()
self.assertNotEqual(
raising_loc.find("raise Exception('boom')"), -1,
"Failed to find 'raise Exception' in last frame of "
"traceback, instead found: %s" % raising_loc
)
def test_template_loader_postmortem(self):
"""Tests for not existing file"""
@ -171,7 +176,7 @@ class DebugViewTests(LoggingCaptureMixin, SimpleTestCase):
with override_settings(TEMPLATES=[{
'BACKEND': 'django.template.backends.django.DjangoTemplates',
'DIRS': [tempdir],
}]):
}]), self.assertLogs('django.request', 'ERROR'):
response = self.client.get(reverse('raises_template_does_not_exist', kwargs={"path": template_name}))
self.assertContains(response, "%s (Source does not exist)" % template_path, status_code=500, count=2)
# Assert as HTML.
@ -187,8 +192,9 @@ class DebugViewTests(LoggingCaptureMixin, SimpleTestCase):
"""
Make sure if you don't specify a template, the debug view doesn't blow up.
"""
with self.assertRaises(TemplateDoesNotExist):
self.client.get('/render_no_template/')
with self.assertLogs('django.request', 'ERROR'):
with self.assertRaises(TemplateDoesNotExist):
self.client.get('/render_no_template/')
@override_settings(ROOT_URLCONF='view_tests.default_urls')
def test_default_urlconf_template(self):
@ -253,7 +259,8 @@ class NonDjangoTemplatesDebugViewTests(SimpleTestCase):
def test_400(self):
# When DEBUG=True, technical_500_template() is called.
response = self.client.get('/raises400/')
with self.assertLogs('django.security', 'WARNING'):
response = self.client.get('/raises400/')
self.assertContains(response, '<div class="context" id="', status_code=400)
def test_403(self):
@ -267,7 +274,8 @@ class NonDjangoTemplatesDebugViewTests(SimpleTestCase):
def test_template_not_found_error(self):
# Raises a TemplateDoesNotExist exception and shows the debug view.
url = reverse('raises_template_does_not_exist', kwargs={"path": "notfound.html"})
response = self.client.get(url)
with self.assertLogs('django.request', 'ERROR'):
response = self.client.get(url)
self.assertContains(response, '<div class="context" id="', status_code=500)