def test_output_request_should_be_logged_with_input_request(self):
with capture_security_logs() as logged_data:
responses.add(responses.GET, 'http://localhost', body='test')
assert_equal(self.get('/proxy/?url=http://localhost').content, b'test')
assert_length_equal(logged_data.output_request_started, 1)
assert_length_equal(logged_data.output_request_finished, 1)
assert_equal(
logged_data.output_request[0]._get_parent_with_id(),
logged_data.input_request[0]
)
def test_excluded_command_should_not_be_logged(self):
with capture_security_logs() as logged_data:
test_call_command('test_command')
assert_length_equal(logged_data.command_started, 0)
assert_length_equal(logged_data.command_finished, 0)
assert_length_equal(logged_data.command_output_updated, 0)
assert_length_equal(logged_data.command_error, 0)
def test_input_request_to_login_page_should_be_logged(self, user):
expected_input_request_started_data = {
'request_headers': {
'Content-Length': not_none_eq_obj,
'Content-Type': not_none_eq_obj,
'Cookie': '[Filtered]',
},
'request_body': (
'--BoUnDaRyStRiNg\r\n'
'Content-Disposition: form-data; name="username"\r\n'
'\r\n'
'test\r\n'
'--BoUnDaRyStRiNg\r\n'
'[Filtered]\n'
'--BoUnDaRyStRiNg--\r\n'
),
'user_id': None,
'method': 'POST',
'host': 'testserver',
'path': '/admin/login/',
'queries': {},
'is_secure': False,
'ip': '127.0.0.1',
'start': all_eq_obj,
'view_slug': 'admin:login',
}
expected_input_request_finished_data = {
**expected_input_request_started_data,
'stop': all_eq_obj,
'response_code': 302,
'response_headers': {
'Cache-Control': 'max-age=0, no-cache, no-store, must-revalidate, private',
'Content-Type': 'text/html; charset=utf-8',
'Expires': all_eq_obj,
'Location': '/accounts/profile/',
'Vary': 'Cookie',
'X-Frame-Options': 'DENY'
},
'response_body': '',
'user_id': user.pk,
}
with capture_security_logs() as logged_data:
assert_http_redirect(self.post('/admin/login/', data={'username': '******', 'password': '******'}))
assert_length_equal(logged_data.input_request_started, 1)
assert_length_equal(logged_data.input_request_finished, 1)
assert_equal_log_data(logged_data.input_request_started[0], expected_input_request_started_data)
assert_equal_log_data(logged_data.input_request_finished[0], expected_input_request_finished_data)
def test_input_request_to_homepage_should_be_logged(self):
expected_input_request_started_data = {
'request_headers': {'Cookie': '[Filtered]'},
'request_body': '',
'user_id': None,
'method': 'GET',
'host': 'testserver',
'path': '/home/',
'queries': {'name': 'value'},
'is_secure': False,
'ip': '127.0.0.1',
'start': all_eq_obj,
'view_slug': 'home',
}
expected_input_request_finished_data = {
**expected_input_request_started_data,
'stop': all_eq_obj,
'response_code': 200,
'response_headers': {'Content-Type': 'text/html; charset=utf-8', 'X-Frame-Options': 'DENY'},
'response_body': 'home page response',
}
with capture_security_logs() as logged_data:
assert_http_ok(self.get('/home/?name=value'))
assert_length_equal(logged_data.input_request_started, 1)
assert_length_equal(logged_data.input_request_finished, 1)
assert_length_equal(logged_data.input_request_error, 0)
assert_equal_log_data(logged_data.input_request_started[0], expected_input_request_started_data)
assert_equal_log_data(logged_data.input_request_finished[0], expected_input_request_finished_data)
def test_input_request_to_error_page_should_be_logged(self):
expected_input_request_started_data = {
'request_headers': {'Cookie': '[Filtered]'},
'request_body': '',
'user_id': None,
'method': 'GET',
'host': 'testserver',
'path': '/error/',
'queries': {},
'is_secure': False,
'ip': '127.0.0.1',
'start': all_eq_obj,
'view_slug': 'apps.test_security.views.error_view',
}
expected_input_request_error_data = {
**expected_input_request_started_data,
'error_message': all_eq_obj,
}
expected_input_request_finished_data = {
**expected_input_request_error_data,
'stop': all_eq_obj,
'response_code': 500,
'response_headers': all_eq_obj,
'response_body': all_eq_obj,
}
with capture_security_logs() as logged_data:
with assert_raises(RuntimeError):
assert_http_ok(self.get('/error/'))
assert_length_equal(logged_data.input_request_started, 1)
assert_length_equal(logged_data.input_request_finished, 1)
assert_length_equal(logged_data.input_request_error, 1)
assert_equal_log_data(logged_data.input_request_started[0], expected_input_request_started_data)
assert_equal_log_data(logged_data.input_request_finished[0], expected_input_request_finished_data)
assert_equal_log_data(logged_data.input_request_error[0], expected_input_request_error_data)
def test_command_should_be_logged(self):
expected_command_started_data = {
'name': 'test_command',
'input': 'verbosity=0',
'is_executed_from_command_line': False,
'start': all_eq_obj,
}
expected_command_finished_data = {
**expected_command_started_data,
'stop': all_eq_obj,
'output': not_none_eq_obj,
}
with capture_security_logs() as logged_data:
test_call_command('test_command', verbosity=0)
assert_length_equal(logged_data.command_started, 1)
assert_length_equal(logged_data.command_finished, 1)
assert_length_equal(logged_data.command_error, 0)
assert_equal_log_data(logged_data.command_started[0], expected_command_started_data)
assert_equal_log_data(logged_data.command_finished[0], expected_command_finished_data)
def test_error_command_should_be_logged(self):
expected_command_started_data = {
'name': 'test_error_command',
'input': '',
'is_executed_from_command_line': False,
'start': all_eq_obj,
}
expected_command_error_data = {
**expected_command_started_data,
'error_message': not_none_eq_obj,
'stop': all_eq_obj,
}
with capture_security_logs() as logged_data:
with assert_raises(RuntimeError):
test_call_command('test_error_command')
assert_length_equal(logged_data.command_started, 1)
assert_length_equal(logged_data.command_finished, 0)
assert_length_equal(logged_data.command_error, 1)
assert_equal_log_data(logged_data.command_started[0], expected_command_started_data)
assert_equal_log_data(logged_data.command_error[0], expected_command_error_data)
def test_command_log_string_io_flush_timeout_should_changed(self):
with capture_security_logs() as logged_data:
test_call_command('test_command')
assert_length_equal(logged_data.command_output_updated, 20)
def test_decorated_view_with_log_exempt_should_not_log_request(self):
with capture_security_logs() as logged_data:
self.get('/log-exempt/')
assert_length_equal(logged_data.input_request, 0)
def test_ignored_client_ip_should_not_be_logged(self):
with capture_security_logs() as logged_data:
assert_http_ok(self.get('/home/'))
assert_length_equal(logged_data.input_request, 0)