From 2746509ccf4513e882623fcd7ea83f1b5b29e6d7 Mon Sep 17 00:00:00 2001 From: ryandeivert Date: Tue, 26 Nov 2019 15:18:53 -0800 Subject: [PATCH] adding fix for box app request timeout (#1040) (#1057) * adding fix for #1040 * addressing pr feedback --- streamalert/apps/_apps/box.py | 20 +++-- .../streamalert/apps/test_apps/test_box.py | 76 +++++++++++-------- 2 files changed, 58 insertions(+), 38 deletions(-) diff --git a/streamalert/apps/_apps/box.py b/streamalert/apps/_apps/box.py index a6c36635f..b6117dc4c 100644 --- a/streamalert/apps/_apps/box.py +++ b/streamalert/apps/_apps/box.py @@ -18,7 +18,7 @@ from boxsdk import Client, JWTAuth from boxsdk.exception import BoxException from boxsdk.object.events import EnterpriseEventsStreamType -from requests.exceptions import ConnectionError as requestsConnectionError +import requests from . import AppIntegration, StreamAlertApp, get_logger, safe_timeout @@ -30,6 +30,7 @@ class BoxApp(AppIntegration): """BoxApp integration""" _MAX_CHUNK_SIZE = 500 + _MAX_RETRY_COUNT = 3 def __init__(self, event, context): super(BoxApp, self).__init__(event, context) @@ -117,7 +118,7 @@ def _make_request(self): LOGGER.debug('[%s] Requesting events', self) - def _perform_request(allow_retry=True): + def _perform_request(timeout, allow_retry=True, retry_count=0): try: # Get the events using a make_request call with the box api. This is to # support custom parameters such as 'created_after' and 'created_before' @@ -125,18 +126,25 @@ def _perform_request(allow_retry=True): 'GET', self._client.get_url('events'), params=params, - timeout=self._DEFAULT_REQUEST_TIMEOUT + timeout=timeout ) except BoxException: LOGGER.exception('[%s] Failed to get events', self) return False, {} # Return a tuple to conform to return value of safe_timeout - except requestsConnectionError: + except requests.exceptions.Timeout: + # Retry requests that timed out a few more times, with increased timeout + timeout *= 2 + LOGGER.debug('Attempting new request with timeout: %0.2f seconds', timeout) + if retry_count == self._MAX_RETRY_COUNT: + raise # eventually give up and raise this + return _perform_request(timeout, allow_retry, retry_count + 1) + except requests.exceptions.ConnectionError: # In testing, the requests connection seemed to get reset for no # obvious reason, and a simple retry once works fine so catch it # and retry once, but after that return False LOGGER.exception('Bad response received from host, will retry once') if allow_retry: - return _perform_request(allow_retry=False) + return _perform_request(timeout, allow_retry=False) return False, {} # Return a tuple to conform to return value of safe_timeout @@ -144,7 +152,7 @@ def _perform_request(allow_retry=True): # Return a tuple to conform to return value of safe_timeout return True, box_response.json() - return _perform_request() + return _perform_request(self._DEFAULT_REQUEST_TIMEOUT) def _gather_logs(self): """Gather the Box Admin Events diff --git a/tests/unit/streamalert/apps/test_apps/test_box.py b/tests/unit/streamalert/apps/test_apps/test_box.py index 78d16da2b..ddb14e9b3 100644 --- a/tests/unit/streamalert/apps/test_apps/test_box.py +++ b/tests/unit/streamalert/apps/test_apps/test_box.py @@ -17,10 +17,10 @@ import os from boxsdk.exception import BoxException -from mock import Mock, mock_open, patch +from mock import call, Mock, mock_open, patch from moto import mock_ssm from nose.tools import assert_equal, assert_false, assert_count_equal, assert_true -from requests.exceptions import ConnectionError as reConnectionError, Timeout +import requests from streamalert.apps._apps.box import BoxApp @@ -52,8 +52,7 @@ def test_required_auth_info(self): """BoxApp - Required Auth Info""" assert_count_equal(list(self._app.required_auth_info().keys()), {'keyfile'}) - @patch('streamalert.apps._apps.box.JWTAuth.from_settings_dictionary', - Mock(return_value=True)) + @patch('streamalert.apps._apps.box.JWTAuth.from_settings_dictionary', Mock()) def test_keyfile_validator(self): """BoxApp - Keyfile Validation, Success""" validation_function = self._app.required_auth_info()['keyfile']['format'] @@ -82,8 +81,7 @@ def test_keyfile_validator_bad_json(self, cred_mock): assert_false(validation_function('fakepath')) cred_mock.assert_not_called() - @patch('streamalert.apps._apps.box.JWTAuth.from_settings_dictionary', - Mock(return_value=True)) + @patch('streamalert.apps._apps.box.JWTAuth.from_settings_dictionary', Mock()) def test_load_credentials(self): """BoxApp - Load Auth, Success""" assert_true(self._app._load_auth('fakedata')) @@ -94,8 +92,6 @@ def test_load_credentials_bad(self, cred_mock): cred_mock.side_effect = ValueError('Bad things happened') assert_false(self._app._load_auth('fakedata')) - @patch('streamalert.apps._apps.box.Client', - Mock(return_value=True)) @patch('streamalert.apps._apps.box.BoxApp._load_auth') def test_create_client(self, auth_mock): """BoxApp - Create Client, Success""" @@ -109,8 +105,7 @@ def test_create_client_exists(self, log_mock): assert_true(self._app._create_client()) log_mock.assert_called_with('[%s] Client already instantiated', self._app) - @patch('streamalert.apps._apps.box.BoxApp._load_auth', - Mock(return_value=False)) + @patch('streamalert.apps._apps.box.BoxApp._load_auth', Mock(return_value=False)) def test_create_client_fail_auth(self): """BoxApp - Create Client, Auth Failure""" assert_false(self._app._create_client()) @@ -118,18 +113,12 @@ def test_create_client_fail_auth(self): def test_gather_logs(self): """BoxApp - Gather Logs, Success""" with patch.object(self._app, '_client') as client_mock: - payload = { - 'chunk_size': 10, - 'next_stream_position': '1152922976252290886', - 'entries': self._get_sample_logs(10) - } - client_mock.make_request.return_value.json.return_value = payload + client_mock.make_request.return_value.json.return_value = self._get_sample_payload(10) assert_equal(len(self._app._gather_logs()), 10) assert_equal(self._app._last_timestamp, '2017-10-27T12:31:22-07:00') - @patch('streamalert.apps._apps.box.BoxApp._create_client', - Mock(return_value=True)) + @patch('streamalert.apps._apps.box.BoxApp._create_client', Mock()) @patch('logging.Logger.exception') def test_gather_logs_box_error(self, log_mock): """BoxApp - Gather Logs, BoxException""" @@ -138,29 +127,47 @@ def test_gather_logs_box_error(self, log_mock): assert_false(self._app._gather_logs()) log_mock.assert_called_with('[%s] Failed to get events', self._app) - @patch('streamalert.apps._apps.box.BoxApp._create_client', - Mock(return_value=True)) + @patch('streamalert.apps._apps.box.BoxApp._create_client', Mock()) @patch('logging.Logger.exception') def test_gather_logs_requests_error(self, log_mock): """BoxApp - Gather Logs, requests.ConnectionError""" with patch.object(self._app, '_client') as client_mock: self._app._next_stream_position = 10241040195019 - client_mock.make_request.side_effect = reConnectionError(response='bad error') + client_mock.make_request.side_effect = requests.exceptions.ConnectionError( + response='bad error' + ) assert_false(self._app._gather_logs()) log_mock.assert_called_with('Bad response received from host, will retry once') - @patch('streamalert.apps._apps.box.BoxApp._create_client', - Mock(return_value=True)) + @patch('streamalert.apps._apps.box.BoxApp._create_client', Mock()) @patch('logging.Logger.exception') - def test_gather_logs_requests_timeout(self, log_mock): - """BoxApp - Gather Logs, Timeout""" + def test_gather_logs_requests_timeout_retry_fail(self, log_mock): + """BoxApp - Gather Logs, Timeout Retry and Fail""" with patch.object(self._app, '_client') as client_mock: - client_mock.make_request.side_effect = Timeout(response='request timed out') + client_mock.make_request.side_effect = requests.exceptions.Timeout( + response='request timed out' + ) assert_false(self._app._gather_logs()) log_mock.assert_called_with('[%s] Request timed out', '_make_request') - @patch('streamalert.apps._apps.box.BoxApp._load_auth', - Mock(return_value=False)) + @patch('streamalert.apps._apps.box.BoxApp._create_client', Mock()) + @patch('logging.Logger.debug') + def test_gather_logs_requests_timeout_retry_success(self, log_mock): + """BoxApp - Gather Logs, Timeout Retry and Succeed""" + with patch.object(self._app, '_client') as client_mock: + # client_mock.make_request.return_value.json.return_value = None + client_mock.make_request.side_effect = [ + requests.exceptions.Timeout(response='request timed out once'), + requests.exceptions.Timeout(response='request timed out twice'), + Mock(json=Mock(return_value=self._get_sample_payload(1))), + ] + assert_equal(bool(self._app._gather_logs()), True) + log_mock.assert_has_calls([ + call('Attempting new request with timeout: %0.2f seconds', 6.10), + call('Attempting new request with timeout: %0.2f seconds', 12.20), + ]) + + @patch('streamalert.apps._apps.box.BoxApp._load_auth', Mock(return_value=False)) def test_gather_logs_no_client(self): """BoxApp - Gather Logs, No Client""" with patch.object(self._app, '_client') as client_mock: @@ -168,8 +175,7 @@ def test_gather_logs_no_client(self): assert_false(self._app._gather_logs()) client_mock.make_request.assert_not_called() - @patch('streamalert.apps._apps.box.BoxApp._create_client', - Mock(return_value=True)) + @patch('streamalert.apps._apps.box.BoxApp._create_client', Mock()) @patch('logging.Logger.error') def test_gather_logs_no_results(self, log_mock): """BoxApp - Gather Logs, No Results From API""" @@ -178,8 +184,7 @@ def test_gather_logs_no_results(self, log_mock): assert_false(self._app._gather_logs()) log_mock.assert_called_with('[%s] No results received in request', self._app) - @patch('streamalert.apps._apps.box.BoxApp._create_client', - Mock(return_value=True)) + @patch('streamalert.apps._apps.box.BoxApp._create_client', Mock()) @patch('logging.Logger.info') def test_gather_logs_empty_items(self, log_mock): """BoxApp - Gather Logs, Empty Entries List""" @@ -193,6 +198,13 @@ def test_gather_logs_empty_items(self, log_mock): assert_false(self._app._gather_logs()) log_mock.assert_called_with('[%s] No events found in result', self._app) + def _get_sample_payload(self, count): + return { + 'chunk_size': 10, + 'next_stream_position': '1152922976252290886', + 'entries': self._get_sample_logs(count) + } + @staticmethod def _get_sample_logs(count): """Helper function for returning sample Box admin event logs"""