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)