class LogTestCase(BaseLogTestCase):
def setUp(self):
self.factory = RequestFactory()
self.middleware = LoggingMiddleware()
def test_request_body_logged(self, mock_log):
body = "some body"
datafile = io.StringIO(body)
request = self.factory.post("/somewhere", data={"file": datafile})
self.middleware.process_request(request)
self._assert_logged(mock_log, "some body")
def test_request_headers_logged(self, mock_log):
request = self.factory.post("/somewhere",
**{'HTTP_USER_AGENT': 'silly-human'})
self.middleware.process_request(request)
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_response_headers_logged(self, mock_log):
request = self.factory.post("/somewhere")
response = mock.MagicMock()
response.get.return_value = 'application/json'
response._headers = {'test_headers': 'test_headers'}
self.middleware.process_response(request, response)
self._assert_logged(mock_log, "test_headers")
def test_logging_http_4xx_level(self, mock_log):
for level in (logging.INFO, logging.WARNING, logging.ERROR):
mock_log.reset_mock()
with override_settings(REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL=level):
middleware = LoggingMiddleware()
middleware.process_response(self.request, self.response_404)
self._assert_logged_with_level(mock_log, level)
class DRFTestCase(BaseLogTestCase):
def setUp(self):
from django.urls import set_urlconf
set_urlconf('test_urls')
self.factory = RequestFactory()
self.middleware = LoggingMiddleware()
def test_no_request_logging_is_honored(self, mock_log):
uri = "/widgets"
request = self.factory.get(uri)
self.middleware.process_request(request)
self._assert_logged(mock_log, "DRF explicit annotation")
def test_no_response_logging_is_honored(self, mock_log):
uri = "/widgets"
request = self.factory.get(uri)
mock_response = HttpResponse('{"example":"response"}',
content_type='application/json',
status=422)
self.middleware.process_response(request, response=mock_response)
self._assert_not_logged(mock_log, '"example":"response"')
self._assert_logged(mock_log, '/widgets')
def test_non_existent_drf_route_logs(self, mock_log):
uri = "/widgets/1234"
request = self.factory.patch(uri, data={"almost": "had you"})
self.middleware.process_request(request)
self._assert_not_logged(mock_log, "almost")
self._assert_not_logged(mock_log, "had you")
class LoggingContextTestCase(BaseLogTestCase):
def setUp(self):
self.factory = RequestFactory()
self.middleware = LoggingMiddleware()
def test_request_logging_context(self, mock_log):
request = self.factory.post("/somewhere")
self.middleware.process_request(request, None, request.body)
self._asset_logged_with_additional_args_and_kwargs(
mock_log, (), {"extra": {
"request": request,
"response": None
}})
def test_response_logging_context(self, mock_log):
request = self.factory.post("/somewhere")
response = mock.MagicMock()
response.get.return_value = "application/json"
headers = {"test_headers": "test_headers"}
if IS_DJANGO_VERSION_GTE_3_2_0:
response.headers = headers
else:
response._headers = headers
self.middleware.process_response(request, response)
self._asset_logged_with_additional_args_and_kwargs(
mock_log, (),
{"extra": {
"request": request,
"response": response
}})
def test_get_logging_context_extensibility(self, mock_log):
request = self.factory.post("/somewhere")
self.middleware._get_logging_context = lambda request, response: {
"args": (1, True, "Test"),
"kwargs": {
"extra": {
"REQUEST": request,
"middleware": self.middleware
},
"exc_info": True
},
}
self.middleware.process_request(request, None, request.body)
self._asset_logged_with_additional_args_and_kwargs(
mock_log,
(1, True, "Test"),
{
"extra": {
"REQUEST": request,
"middleware": self.middleware
},
"exc_info": True
},
)
class LoggingContextTestCase(BaseLogTestCase):
def setUp(self):
self.factory = RequestFactory()
self.middleware = LoggingMiddleware()
def test_request_logging_context(self, mock_log):
request = self.factory.post("/somewhere")
self.middleware.process_request(request)
self._asset_logged_with_additional_args_and_kwargs(
mock_log, (), {
'extra': {
'request': request,
'response': None,
},
})
def test_response_logging_context(self, mock_log):
request = self.factory.post("/somewhere")
response = mock.MagicMock()
response.get.return_value = 'application/json'
response._headers = {'test_headers': 'test_headers'}
self.middleware.process_response(request, response)
self._asset_logged_with_additional_args_and_kwargs(
mock_log, (), {
'extra': {
'request': request,
'response': response,
},
})
def test_get_logging_context_extensibility(self, mock_log):
request = self.factory.post("/somewhere")
self.middleware._get_logging_context = lambda request, response: {
'args': (1, True, 'Test'),
'kwargs': {
'extra': {
'REQUEST': request,
'middleware': self.middleware,
},
'exc_info': True,
},
}
self.middleware.process_request(request)
self._asset_logged_with_additional_args_and_kwargs(
mock_log, (1, True, 'Test'), {
'extra': {
'REQUEST': request,
'middleware': self.middleware,
},
'exc_info': True,
})
class UnicodeLogTestCase(BaseLogTestCase):
def setUp(self):
def get_response(request):
response = mock.MagicMock()
response.status_code = 200
response.get.return_value = 'application/json'
response._headers = {'test_headers': 'test_headers'}
return response
self.uri = "/test_class"
self.factory = RequestFactory()
self.middleware = LoggingMiddleware(get_response)
def test_logs_unicode_http_response(self, mock_log):
request = self.factory.get(self.uri)
response = mock.MagicMock()
response.get.return_value = "application/json"
response.content = str({"test_unicode_body": "El Niño"})
response.streaming = False
self.middleware.process_response(request, response)
self._assert_logged(mock_log, response.content)
def test_logs_url_with_unicode(self, mock_log):
url = "{}/El Niño".format(self.uri)
request = self.factory.get(url)
self.middleware.process_request(request)
self._assert_logged(mock_log, url)
def test_logs_unicode_http_request_with_json_type_body(self, mock_log):
body = "El Niño"
request = self.factory.post("/somewhere", data={"body": body})
self.middleware.process_request(request)
self._assert_logged(mock_log, body)
def test_logs_unicode_http_request_with_url_encoded_body(self, mock_log):
try:
# Python 3.x
from urllib.parse import quote, unquote
except ImportError:
# Python 2.7
from urllib import quote, unquote
body = "El Niño"
request = self.factory.post(
"/somewhere",
data=quote(body, encoding='utf-8'),
content_type="application/x-www-form-urlencoded")
self.middleware.process_request(request)
self._assert_logged(mock_log, unquote(body))
class LogTestCase(unittest.TestCase):
def setUp(self):
self.factory = RequestFactory()
self.middleware = LoggingMiddleware()
def test_does_not_error_with_binary_content_larger_than_chunk_size(self, mock_log):
body = MAX_BODY_LENGTH * "0" + "1"
datafile = io.StringIO(body)
request = self.factory.post("/somewhere", data={"file": datafile})
self.middleware.process_request(request)
self._assert_logged(mock_log, str(request.body[:MAX_BODY_LENGTH]))
self._assert_not_logged(mock_log, body)
def test_request_body_logged(self, mock_log):
body = "some body"
datafile = io.StringIO(body)
request = self.factory.post("/somewhere", data={"file": datafile})
self.middleware.process_request(request)
self._assert_logged(mock_log, "some body")
def test_request_headers_logged(self, mock_log):
request = self.factory.post("/somewhere",
**{'HTTP_USER_AGENT': 'silly-human'})
self.middleware.process_request(request)
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_response_headers_logged(self, mock_log):
request = self.factory.post("/somewhere")
response = mock.MagicMock()
response.get.return_value = 'application/json'
response._headers = {'test_headers': 'test_headers'}
self.middleware.process_response(request, response)
self._assert_logged(mock_log, "test_headers")
def _assert_logged(self, mock_log, expected_entry):
calls = mock_log.log.call_args_list
text = " ".join([call[0][1] for call in calls])
self.assertTrue(expected_entry in text)
def _assert_not_logged(self, mock_log, unexpected_entry):
calls = mock_log.log.call_args_list
text = " ".join([call[0][1] for call in calls])
self.assertTrue(unexpected_entry not in text)
class LogTestCase(BaseLogTestCase):
def setUp(self):
self.factory = RequestFactory()
def get_response(request):
response = mock.MagicMock()
response.status_code = 200
response.get.return_value = 'application/json'
response._headers = {'test_headers': 'test_headers'}
return response
self.middleware = LoggingMiddleware(get_response)
def test_request_body_logged(self, mock_log):
body = u"some body"
request = self.factory.post("/somewhere", data={"file": body})
self.middleware.process_request(request)
self._assert_logged(mock_log, body)
def test_request_binary_logged(self, mock_log):
body = u"some body"
datafile = io.StringIO(body)
request = self.factory.post("/somewhere", data={"file": datafile})
self.middleware.process_request(request)
self._assert_logged(mock_log, "(binary data)")
@unittest.skipIf(sys.version_info < (3, 0), "This issue won't happen on python 2")
def test_request_jpeg_logged(self, mock_log):
body = b'--BoUnDaRyStRiNg\r\nContent-Disposition: form-data; name="file"; filename="campaign_carousel_img.jp' \
b'g"\r\nContent-Type: image/jpeg\r\n\r\n\xff\xd8\xff\xe1\x00\x18Exif\x00\x00II*\x00\x08\x00\x00\x00' \
b'\x00\x00\x00\x00\x00\x00\x00\x00\xff\xec\x00\x11Ducky\x00\x01\x00\x04\x00\x00\x00d\x00\x00\xff\xe1' \
b'\x03{http://ns.adobe.com/'
datafile = io.BytesIO(body)
request = self.factory.post("/somewhere", data={"file": datafile})
self.middleware.process_request(request)
self._assert_logged(mock_log, "(multipart/form)")
def test_request_headers_logged(self, mock_log):
request = self.factory.post("/somewhere",
**{'HTTP_USER_AGENT': 'silly-human'})
self.middleware.process_request(request)
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_response_headers_logged(self, mock_log):
request = self.factory.post("/somewhere")
response = mock.MagicMock()
response.get.return_value = 'application/json'
response._headers = {'test_headers': 'test_headers'}
self.middleware.process_response(request, response)
self._assert_logged(mock_log, "test_headers")
def test_call_logged(self, mock_log):
body = u"some body"
request = self.factory.post("/somewhere", data={"file": body},
**{'HTTP_USER_AGENT': 'silly-human'})
self.middleware.__call__(request)
self._assert_logged(mock_log, body)
self._assert_logged(mock_log, "test_headers")
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_call_binary_logged(self, mock_log):
body = u"some body"
datafile = io.StringIO(body)
request = self.factory.post("/somewhere", data={"file": datafile},
**{'HTTP_USER_AGENT': 'silly-human'})
self.middleware.__call__(request)
self._assert_logged(mock_log, "(binary data)")
self._assert_logged(mock_log, "test_headers")
self._assert_logged(mock_log, "HTTP_USER_AGENT")
@unittest.skipIf(sys.version_info < (3, 0), "This issue won't happen on python 2")
def test_call_jpeg_logged(self, mock_log):
body = b'--BoUnDaRyStRiNg\r\nContent-Disposition: form-data; name="file"; filename="campaign_carousel_img.jp' \
b'g"\r\nContent-Type: image/jpeg\r\n\r\n\xff\xd8\xff\xe1\x00\x18Exif\x00\x00II*\x00\x08\x00\x00\x00' \
b'\x00\x00\x00\x00\x00\x00\x00\x00\xff\xec\x00\x11Ducky\x00\x01\x00\x04\x00\x00\x00d\x00\x00\xff\xe1' \
b'\x03{http://ns.adobe.com/'
datafile = io.BytesIO(body)
request = self.factory.post("/somewhere", data={"file": datafile},
**{'HTTP_USER_AGENT': 'silly-human'})
self.middleware.__call__(request)
self._assert_logged(mock_log, "(multipart/form)")
self._assert_logged(mock_log, "test_headers")
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_logging_default_http_4xx_error(self, mock_log):
middleware = LoggingMiddleware()
middleware.process_response(self.request, self.response_404)
self.assertEqual(DEFAULT_HTTP_4XX_LOG_LEVEL, logging.ERROR)
self._assert_logged_with_level(mock_log, DEFAULT_HTTP_4XX_LOG_LEVEL)
class LogTestCase(BaseLogTestCase):
def setUp(self):
self.factory = RequestFactory()
def get_response(request):
response = mock.MagicMock()
response.status_code = 200
response.get.return_value = "application/json"
response._headers = {"test_headers": "test_headers"}
return response
self.middleware = LoggingMiddleware(get_response)
def test_request_body_logged(self, mock_log):
body = u"some body"
request = self.factory.post("/somewhere", data={"file": body})
self.middleware.process_request(request)
self._assert_logged(mock_log, body)
def test_request_binary_logged(self, mock_log):
body = u"some body"
datafile = io.StringIO(body)
request = self.factory.post("/somewhere", data={"file": datafile})
self.middleware.process_request(request)
self._assert_logged(mock_log, "(binary data)")
def test_request_jpeg_logged(self, mock_log):
body = (
b'--BoUnDaRyStRiNg\r\nContent-Disposition: form-data; name="file"; filename="campaign_carousel_img.jp'
b'g"\r\nContent-Type: image/jpeg\r\n\r\n\xff\xd8\xff\xe1\x00\x18Exif\x00\x00II*\x00\x08\x00\x00\x00'
b"\x00\x00\x00\x00\x00\x00\x00\x00\xff\xec\x00\x11Ducky\x00\x01\x00\x04\x00\x00\x00d\x00\x00\xff\xe1"
b"\x03{http://ns.adobe.com/")
datafile = io.BytesIO(body)
request = self.factory.post("/somewhere", data={"file": datafile})
self.middleware.process_request(request)
self._assert_logged(mock_log, "(multipart/form)")
def test_request_headers_logged(self, mock_log):
request = self.factory.post("/somewhere",
**{"HTTP_USER_AGENT": "silly-human"})
self.middleware.process_request(request)
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_request_headers_sensitive_logged_default(self, mock_log):
request = self.factory.post(
"/somewhere", **{
"HTTP_AUTHORIZATION": "sensitive-token",
"HTTP_PROXY_AUTHORIZATION": "proxy-token"
})
middleware = LoggingMiddleware()
middleware.process_request(request)
self._assert_logged(mock_log, "HTTP_AUTHORIZATION")
self._assert_logged(mock_log, "HTTP_PROXY_AUTHORIZATION")
self._assert_logged_with_key_value(mock_log, "HTTP_AUTHORIZATION",
"*****")
self._assert_logged_with_key_value(mock_log,
"HTTP_PROXY_AUTHORIZATION", "*****")
@override_settings(
REQUEST_LOGGING_SENSITIVE_HEADERS=["HTTP_AUTHORIZATION"])
def test_request_headers_sensitive_logged(self, mock_log):
request = self.factory.post(
"/somewhere", **{
"HTTP_AUTHORIZATION": "sensitive-token",
"HTTP_USER_AGENT": "silly-human",
"HTTP_PROXY_AUTHORIZATION": "proxy-token",
})
middleware = LoggingMiddleware()
middleware.process_request(request)
self._assert_logged(mock_log, "HTTP_AUTHORIZATION")
self._assert_logged(mock_log, "HTTP_USER_AGENT")
self._assert_logged(mock_log, "HTTP_PROXY_AUTHORIZATION")
self._assert_logged_with_key_value(mock_log, "HTTP_AUTHORIZATION",
"*****")
self._assert_logged_with_key_value(mock_log, "HTTP_USER_AGENT",
"silly-human")
self._assert_logged_with_key_value(mock_log,
"HTTP_PROXY_AUTHORIZATION",
"proxy-token")
def test_response_headers_logged(self, mock_log):
request = self.factory.post("/somewhere")
response = mock.MagicMock()
response.get.return_value = "application/json"
response._headers = {"test_headers": "test_headers"}
self.middleware.process_response(request, response)
self._assert_logged(mock_log, "test_headers")
def test_call_logged(self, mock_log):
body = u"some body"
request = self.factory.post("/somewhere",
data={"file": body},
**{"HTTP_USER_AGENT": "silly-human"})
self.middleware.__call__(request)
self._assert_logged(mock_log, body)
self._assert_logged(mock_log, "test_headers")
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_call_binary_logged(self, mock_log):
body = u"some body"
datafile = io.StringIO(body)
request = self.factory.post("/somewhere",
data={"file": datafile},
**{"HTTP_USER_AGENT": "silly-human"})
self.middleware.__call__(request)
self._assert_logged(mock_log, "(binary data)")
self._assert_logged(mock_log, "test_headers")
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_call_jpeg_logged(self, mock_log):
body = (
b'--BoUnDaRyStRiNg\r\nContent-Disposition: form-data; name="file"; filename="campaign_carousel_img.jp'
b'g"\r\nContent-Type: image/jpeg\r\n\r\n\xff\xd8\xff\xe1\x00\x18Exif\x00\x00II*\x00\x08\x00\x00\x00'
b"\x00\x00\x00\x00\x00\x00\x00\x00\xff\xec\x00\x11Ducky\x00\x01\x00\x04\x00\x00\x00d\x00\x00\xff\xe1"
b"\x03{http://ns.adobe.com/")
datafile = io.BytesIO(body)
request = self.factory.post("/somewhere",
data={"file": datafile},
**{"HTTP_USER_AGENT": "silly-human"})
self.middleware.__call__(request)
self._assert_logged(mock_log, "(multipart/form)")
self._assert_logged(mock_log, "test_headers")
self._assert_logged(mock_log, "HTTP_USER_AGENT")
def test_minimal_logging_when_streaming(self, mock_log):
uri = "/somewhere"
request = self.factory.get(uri)
response = StreamingHttpResponse(status=200,
streaming_content=b"OK",
content_type="application/json")
self.middleware.process_response(request, response=response)
self._assert_logged(mock_log, "(data_stream)")
