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_data_change_should_be_connected_with_command_log(self):
with capture_security_logs() as logged_data:
test_call_command('create_user')
assert_equal(
logged_data.command[0].extra_data,
{'reversion': {'revisions': [{'id': not_none_eq_obj}], 'total_count': 1}}
)
def test_input_logged_request_should_have_set_data(self, user):
with capture_security_logs() as logged_data:
assert_http_redirect(self.post('/admin/login/', data={'username': '******', 'password': '******'}))
assert_http_ok(self.get('/home/'))
assert_equal(len(logged_data.input_request[1].related_objects), 1)
assert_equal(list(logged_data.input_request[1].related_objects)[0], get_object_triple(user))
assert_equal(logged_data.input_request_finished[1].slug, 'user-home')
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_homepage_should_be_logged_in_elasticsearch_backend(self, user):
with log_with_data(related_objects=[user]):
with capture_security_logs() as logged_data:
assert_http_ok(self.get('/home/?name=value'))
elasticsearch_input_request_log = ElasticsearchInputRequestLog.get(
id=logged_data.input_request[0].id
)
assert_equal_model_fields(
elasticsearch_input_request_log,
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',
view_slug='home',
slug=None,
time=(elasticsearch_input_request_log.stop - elasticsearch_input_request_log.start).total_seconds(),
extra_data={},
error_message=None,
response_code=200,
response_headers='{"Content-Type": "text/html; charset=utf-8", "X-Frame-Options": "DENY"}',
response_body='home page response',
state=RequestLogState.INFO,
)
assert_equal(
[rel_obj for rel_obj in elasticsearch_input_request_log.related_objects],
['default|3|{}'.format(user.id)]
)
def test_output_logged_request_should_be_related_with_object(self, user):
with capture_security_logs() as logged_data:
assert_http_redirect(self.post('/admin/login/', data={'username': '******', 'password': '******'}))
responses.add(responses.GET, 'http://localhost', body='test')
assert_equal(self.get('/proxy/?url=http://localhost').content, b'test')
assert_equal(len(logged_data.output_request[0].related_objects), 1)
assert_equal(list(logged_data.output_request[0].related_objects)[0], get_object_triple(user))
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_sensitive_data_body_in_json_should_be_hidden(self):
with capture_security_logs() as logged_data:
self.c.post('/admin/login/', data=json.dumps({'username': '******', 'password': '******'}),
content_type='application/json')
assert_in('"password": "******"', logged_data.input_request[0].request_body)
assert_not_in(
'"password": "******"', logged_data.input_request[0].request_body
)
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_json_request_data_should_be_truncated(self):
with capture_security_logs() as logged_data:
self.c.post('/admin/login/', data=json.dumps({'a': 50 * 'a', 'b': 50 * 'b'}),
content_type='application/json')
assert_equal(
json.loads(logged_data.input_request[0].request_body),
json.loads('{"a": "%s%s", "b": "%s%s"}' % (
9 * 'a', TRUNCATION_CHAR, 9 * 'b', TRUNCATION_CHAR
))
)
def test_input_request_to_404_page_should_be_logged_in_elasticsearch_backend(self):
with capture_security_logs() as logged_data:
assert_http_not_found(self.get('/404/'))
elasticsearch_input_request_log = ElasticsearchInputRequestLog.get(
id=logged_data.input_request[0].id
)
assert_equal_model_fields(
elasticsearch_input_request_log,
response_code=404,
state=RequestLogState.WARNING,
)
def test_command_should_be_logged_in_elasticsearch_backend_through_logstash(self, user):
with capture_security_logs() as logged_data:
with self.assertLogs('security.logstash', level='INFO') as cm:
test_call_command('test_command', verbosity=0)
command_log = logged_data.command[0]
assert_equal(len(cm.output), 3)
start_log, output_updated_log, success_log = cm.output
start_log_expected_data = {
'slug': None,
'release': None,
'related_objects': [],
'extra_data': {},
'parent_log': None,
'name': 'test_command',
'input': 'verbosity=0',
'is_executed_from_command_line': False,
'start': not_none_eq_obj,
'state': 'ACTIVE'
}
output_updated_log_expected_data = {
**start_log_expected_data,
'output': not_none_eq_obj,
}
success_log_expected_data = {
**output_updated_log_expected_data,
'stop': not_none_eq_obj,
'state': 'SUCCEEDED',
'time': not_none_eq_obj
}
assert_equal_logstash(
start_log,
'security-command-log',
0,
command_log.id,
start_log_expected_data
)
assert_equal_logstash(
output_updated_log,
'security-command-log',
1,
command_log.id,
output_updated_log_expected_data
)
assert_equal_logstash(
success_log,
'security-command-log',
9999,
command_log.id,
success_log_expected_data
)
def test_input_request_to_homepage_should_be_logged_in_elasticsearch_backend_through_logstash(self, user):
with log_with_data(related_objects=[user]):
with capture_security_logs() as logged_data:
with self.assertLogs('security.logstash', level='INFO') as cm:
assert_http_ok(self.get('/home/?name=value'))
input_request_log = logged_data.input_request[0]
assert_equal(len(cm.output), 2)
request_log, response_log = cm.output
request_log_expected_data = {
'slug': None,
'release': None,
'related_objects': ['|'.join(str(v) for v in get_object_triple(user))],
'extra_data': {},
'parent_log': None,
'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': not_none_eq_obj,
'view_slug': 'home',
'state': 'INCOMPLETE'
}
response_log_expected_data = {
**request_log_expected_data,
'state': 'INFO',
'stop': not_none_eq_obj,
'time': not_none_eq_obj,
'response_body': 'home page response',
'response_code': 200,
'response_headers': '{"Content-Type": "text/html; charset=utf-8", ''"X-Frame-Options": "DENY"}',
}
assert_equal_logstash(
request_log,
'security-input-request-log',
0,
input_request_log.id,
request_log_expected_data
)
assert_equal_logstash(
response_log,
'security-input-request-log',
9999,
input_request_log.id,
response_log_expected_data
)
def test_elasticsearch_purge_logs_should_remove_logged_data(self):
responses.add(responses.GET, 'https://localhost/test', body='test')
with capture_security_logs() as logged_data:
test_call_command('test_command')
sum_task.apply(args=(5, 8))
assert_http_ok(self.get('/home/'))
requests.get('https://localhost/test')
elasticsearch_type_model_receivers = (
('input-request', ElasticsearchInputRequestLog,
'input_request'),
('output-request', ElasticsearchOutputRequestLog,
'output_request'),
('command', ElasticsearchCommandLog, 'command'),
('celery-task-invocation',
ElasticsearchCeleryTaskInvocationLog,
'celery_task_invocation'),
('celery-task-run', ElasticsearchCeleryTaskRunLog,
'celery_task_run'),
)
for log_type, log_model, log_data_name in elasticsearch_type_model_receivers:
log_directory = os.path.join(settings.BACKUP_STORAGE_PATH,
log_type)
os.makedirs(log_directory)
test_call_command('purge_logs',
type=log_type,
interactive=False,
expiration='1d',
backup=log_type)
log_model._index.refresh()
assert_equal(
log_model.search().filter(
'ids',
values=[logged_data[log_data_name][0].id]).count(), 1)
with freeze_time(now() + timedelta(days=1, minutes=1)):
test_call_command('purge_logs',
type=log_type,
interactive=False,
expiration='1d',
backup=log_type)
log_model._index.refresh()
assert_equal(
log_model.search().filter(
'ids',
values=[logged_data[log_data_name][0].id]).count(),
0)
assert_equal(len(os.listdir(log_directory)), 1)
shutil.rmtree(settings.BACKUP_STORAGE_PATH)
def test_command_with_response_should_be_logged_with_parent_data(self, user):
responses.add(responses.POST, 'http://localhost/test', body='test')
with log_with_data(related_objects=[user], slug='TEST', extra_data={'test': 'test'}):
with capture_security_logs() as logged_data:
test_call_command('test_command_with_response')
command_logger = logged_data.command[0]
output_request_logger = logged_data.output_request[0]
assert_equal(output_request_logger._get_parent_with_id(), command_logger)
assert_equal(command_logger.slug, 'TEST')
assert_equal(command_logger.related_objects, {get_object_triple(user)})
assert_equal(command_logger.extra_data, {'test': 'test'})
assert_equal(output_request_logger.slug, 'TEST')
assert_equal(output_request_logger.related_objects, {get_object_triple(user)})
assert_equal(output_request_logger.extra_data, {'test': 'test'})
def test_input_request_to_homepage_should_be_logged_in_logging_backend(self):
with capture_security_logs() as logged_data:
with self.assertLogs('security.input_request', level='INFO') as cm:
assert_http_ok(self.get('/home/?name=value'))
assert_equal(
cm.output,
[
f'INFO:security.input_request:'
f'Input request "{logged_data.input_request[0].id}" '
f'to "testserver" with path "/home/" was started',
f'INFO:security.input_request:'
f'Input request "{logged_data.input_request[0].id}" '
f'to "testserver" with path "/home/" was finished'
]
)
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_error_page_should_be_logged_in_elasticsearch_backend(self):
with capture_security_logs() as logged_data:
with assert_raises(RuntimeError):
self.get('/error/')
elasticsearch_input_request_log = ElasticsearchInputRequestLog.get(
id=logged_data.input_request[0].id
)
assert_equal_model_fields(
elasticsearch_input_request_log,
method='GET',
path='/error/',
time=(elasticsearch_input_request_log.stop - elasticsearch_input_request_log.start).total_seconds(),
response_code=500,
state=RequestLogState.ERROR,
)
assert_is_not_none(elasticsearch_input_request_log.error_message)
def test_command_should_be_logged_in_logging_backend(self, user):
with capture_security_logs() as logged_data:
with self.assertLogs('security.command', level='INFO') as cm:
test_call_command('test_command', verbosity=0)
command_log = logged_data.command[0]
assert_equal(
cm.output,
[
f'INFO:security.command:'
f'Command "{command_log.id}" '
f'with name "test_command" was started',
f'INFO:security.command:'
f'Command "{command_log.id}" '
f'with name "test_command" was successful',
]
)
def test_error_command_should_be_logged_in_logging_backend(self, user):
with capture_security_logs() as logged_data:
with self.assertLogs('security.command', level='INFO') as cm:
with assert_raises(RuntimeError):
test_call_command('test_error_command')
command_log = logged_data.command[0]
assert_equal(
cm.output,
[
f'INFO:security.command:'
f'Command "{command_log.id}" '
f'with name "test_error_command" was started',
f'ERROR:security.command:'
f'Command "{command_log.id}" '
f'with name "test_error_command" failed',
]
)
def test_error_command_should_be_logged_in_elasticsearch_backend_through_logstash(self, user):
with capture_security_logs() as logged_data:
with log_with_data(related_objects=[user]):
with self.assertLogs('security.logstash', level='INFO') as cm:
with assert_raises(RuntimeError):
test_call_command('test_error_command')
command_log = logged_data.command[0]
assert_equal(len(cm.output), 2)
start_log, error_log = cm.output
start_log_expected_data = {
'slug': None,
'release': None,
'related_objects': ['|'.join(str(v) for v in get_object_triple(user))],
'extra_data': {},
'parent_log': None,
'name': 'test_error_command',
'input': '',
'is_executed_from_command_line': False,
'start': not_none_eq_obj,
'state': 'ACTIVE'
}
error_log_expected_data = {
**start_log_expected_data,
'stop': not_none_eq_obj,
'error_message': not_none_eq_obj,
'state': 'FAILED',
'time': not_none_eq_obj
}
assert_equal_logstash(
start_log,
'security-command-log',
0,
command_log.id,
start_log_expected_data
)
assert_equal_logstash(
error_log,
'security-command-log',
9999,
command_log.id,
error_log_expected_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_input_request_to_error_page_should_be_logged_in_logging_backend(self):
with capture_security_logs() as logged_data:
with self.assertLogs('security.input_request', level='INFO') as cm:
with assert_raises(RuntimeError):
self.get('/error/')
assert_equal(
cm.output,
[
f'INFO:security.input_request:'
f'Input request "{logged_data.input_request[0].id}" '
f'to "testserver" with path "/error/" was started',
f'ERROR:security.input_request:'
f'Input request "{logged_data.input_request[0].id}" '
f'to "testserver" with path "/error/" failed',
f'INFO:security.input_request:'
f'Input request "{logged_data.input_request[0].id}" '
f'to "testserver" with path "/error/" was finished'
]
)
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_error_command_should_be_logged_in_elasticsearch_backend(self, user):
with capture_security_logs() as logged_data:
with log_with_data(related_objects=[user]):
with assert_raises(RuntimeError):
test_call_command('test_error_command')
elasticsearch_command_log = ElasticsearchCommandLog.get(
id=logged_data.command[0].id
)
assert_equal_model_fields(
elasticsearch_command_log,
name='test_error_command',
input='',
is_executed_from_command_line=False,
time=(elasticsearch_command_log.stop - elasticsearch_command_log.start).total_seconds(),
state=CommandState.FAILED,
output=None,
)
assert_is_not_none(elasticsearch_command_log.error_message)
assert_equal(
[rel_obj for rel_obj in elasticsearch_command_log.related_objects],
['default|3|{}'.format(user.id)]
)
def test_command_should_be_logged_in_elasticsearch_backend(self, user):
with capture_security_logs() as logged_data:
with log_with_data(related_objects=[user]):
test_call_command('test_command', verbosity=0)
elasticsearch_command_log = ElasticsearchCommandLog.get(
id=logged_data.command[0].id
)
assert_equal_model_fields(
elasticsearch_command_log,
name='test_command',
input='verbosity=0',
is_executed_from_command_line=False,
time=(elasticsearch_command_log.stop - elasticsearch_command_log.start).total_seconds(),
state=CommandState.SUCCEEDED,
error_message=None,
)
assert_is_not_none(elasticsearch_command_log.output)
assert_equal(
[rel_obj for rel_obj in elasticsearch_command_log.related_objects],
['default|3|{}'.format(user.id)]
)
ElasticsearchCommandLog._index.refresh()
assert_equal(get_logs_related_with_object(LoggerName.COMMAND, user), [elasticsearch_command_log])
def test_slug_and_related_data_should_be_send_to_input_request_logger(self, user):
with log_with_data(related_objects=[user], slug='TEST'):
with capture_security_logs() as logged_data:
assert_http_ok(self.get('/home/'))
assert_equal(logged_data.input_request[0].related_objects, {get_object_triple(user)})
assert_equal(logged_data.input_request[0].slug, 'TEST')
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_hide_request_body_should_not_log_request_body(self):
with capture_security_logs() as logged_data:
self.post('/hide-request-body/', data={'a': 20 * 'a', 'b': 20 * 'b'})
assert_equal(logged_data.input_request[0].request_body, '[Filtered]')
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)
