diff --git a/boxsdk/network/default_network.py b/boxsdk/network/default_network.py index 110a8c188..59ea9df92 100644 --- a/boxsdk/network/default_network.py +++ b/boxsdk/network/default_network.py @@ -20,7 +20,10 @@ def request(self, method, url, access_token, **kwargs): """Base class override. Make a network request using a requests.Session. """ - return DefaultNetworkResponse(self._session.request(method, url, **kwargs), access_token) + return self.network_response_constructor( + request_response=self._session.request(method, url, **kwargs), + access_token_used=access_token, + ) def retry_after(self, delay, request_method, *args, **kwargs): """Base class override. @@ -29,6 +32,16 @@ def retry_after(self, delay, request_method, *args, **kwargs): time.sleep(delay) return request_method(*args, **kwargs) + @property + def network_response_constructor(self): + """Baseclass override. + + A callable that accepts `request_response` and `access_token_used` + keyword arguments for the :class:`DefaultNetworkResponse` constructor, + and returns an instance of :class:`DefaultNetworkResponse`. + """ + return DefaultNetworkResponse + class DefaultNetworkResponse(NetworkResponse): """Implementation of the network interface using the requests library.""" diff --git a/boxsdk/network/logging_network.py b/boxsdk/network/logging_network.py index b1ea383ca..39d3fadb1 100644 --- a/boxsdk/network/logging_network.py +++ b/boxsdk/network/logging_network.py @@ -1,8 +1,14 @@ # coding: utf-8 -from __future__ import unicode_literals +from __future__ import absolute_import, unicode_literals + +from functools import partial from pprint import pformat -from boxsdk.network.default_network import DefaultNetwork +import sys + +from six import text_type + +from boxsdk.network.default_network import DefaultNetwork, DefaultNetworkResponse from boxsdk.util.log import setup_logging @@ -11,10 +17,11 @@ class LoggingNetwork(DefaultNetwork): SDK Network subclass that logs requests and responses. """ LOGGER_NAME = 'boxsdk.network' - REQUEST_FORMAT = '\x1b[36m%s %s %s\x1b[0m' - SUCCESSFUL_RESPONSE_FORMAT = '\x1b[32m%s\x1b[0m' - ERROR_RESPONSE_FORMAT = '\x1b[31m%s\n%s\n%s\n\x1b[0m' - STREAM_CONTENT_NOT_LOGGED = '' + REQUEST_FORMAT = '\x1b[36m%(method)s %(url)s %(request_kwargs)s\x1b[0m' + EXCEPTION_FORMAT = '\x1b[31mRequest "%(method)s %(url)s" failed with %(exc_type_name)s exception: %(exc_value)r\x1b[0m' + _COMMON_RESPONSE_FORMAT = '"%(method)s %(url)s" %(status_code)s %(content_length)s\n%(headers)s\n%(content)s\n' + SUCCESSFUL_RESPONSE_FORMAT = '\x1b[32m{0}\x1b[0m'.format(_COMMON_RESPONSE_FORMAT) + ERROR_RESPONSE_FORMAT = '\x1b[31m{0}\x1b[0m'.format(_COMMON_RESPONSE_FORMAT) def __init__(self, logger=None): """ @@ -48,32 +55,216 @@ def _log_request(self, method, url, **kwargs): :type access_token: `unicode` """ - self._logger.info(self.REQUEST_FORMAT, method, url, pformat(kwargs)) + self._logger.info(self.REQUEST_FORMAT, {'method': method, 'url': url, 'request_kwargs': pformat(kwargs)}) - def _log_response(self, response): - """ - Logs information about the Box API response. + def _log_exception(self, method, url, exc_info): + """Log information at WARNING level about the exception that was raised when trying to make the request. - :param response: The Box API response. + :param method: The HTTP verb that was used to make the request. + :type method: `unicode` + :param url: The URL for the request. + :type url: `unicode` + :param exc_info: The exception info returned from `sys.exc_info()`. """ - if response.ok: - if response.request_response.raw is not None: - self._logger.info(self.SUCCESSFUL_RESPONSE_FORMAT, self.STREAM_CONTENT_NOT_LOGGED) - else: - self._logger.info(self.SUCCESSFUL_RESPONSE_FORMAT, response.content) - else: - self._logger.warning( - self.ERROR_RESPONSE_FORMAT, - response.status_code, - response.headers, - pformat(response.content), - ) + exc_type, exc_value, _ = exc_info + self._logger.warning( + self.EXCEPTION_FORMAT, + {'method': method, 'url': url, 'exc_type_name': exc_type.__name__, 'exc_value': exc_value}, + ) def request(self, method, url, access_token, **kwargs): """ Base class override. Logs information about an API request and response in addition to making the request. + + Also logs exceptions before re-raising them. + + The logging of the response is deferred to + :class:`LoggingNetworkResponse`. See that class's docstring for more + info. """ self._log_request(method, url, **kwargs) - response = super(LoggingNetwork, self).request(method, url, access_token, **kwargs) - self._log_response(response) + try: + return super(LoggingNetwork, self).request(method, url, access_token, **kwargs) + except Exception: + self._log_exception(method, url, sys.exc_info()) + raise + + @property + def network_response_constructor(self): + """Baseclass override. + + A callable that passes additional required keyword arguments to the + :class:`LoggingNetworkResponse` constructor, and returns an instance of + :class:`LoggingNetworkResponse`. + """ + return partial( + LoggingNetworkResponse, + logger=self._logger, + successful_response_format=self.SUCCESSFUL_RESPONSE_FORMAT, + error_response_format=self.ERROR_RESPONSE_FORMAT, + ) + + +class LoggingNetworkResponse(DefaultNetworkResponse): + """Response subclass that defers LoggingNetwork response logging until it is safe to do so. + + :class:`DefaultNetwork` is based off the `requests` library. + :class:`requests.Response` has a few mutually-exclusive ways to read the + content of the response: + + - With the `Response.raw` attribute, an `io.IOBase` instance returned + from the `urllib3` library, that can be read once in chunks from + beginning to end. + - With `Response.iter_content()` and other iter_* generators, which + also can only be read once and advance the `Response.raw` IO stream. + - With the `Response.content` property (and other attributes such as + `Response.text` and `Response.json()`), which reads and caches the + remaining response content in memory. Can be accessed multiple times, + but cannot be safely accessed if any of the previous mechanisms have + been used at all. And if this property has already been accessed, + then the other mechanisms will have been exhausted, and attempting to + read from them will make it appear like the response content is + empty. + + Any of these mechanisms may be used to read any response, regardless of + whether `stream=True` or `stream=False` on the request. + + If the caller uses `Response.content`, then it is safe for + :class:`LoggingNetwork` to also access it. But if the caller uses any of + the streaming mechanisms, then it is not safe for :class:`LoggingNetwork` + to ever read any of the content. Thus, the options available are: + + - Never log the content of a response. + - Make logging part of the :class:`Network` interface, and add an + optional keyword argument that callers can use to specify when it is + unsafe to log the content of a response. + - Defer logging until it is possible to auto-detect which mechanism is + being used. + + This class is an implementation of the latter option. Instead of response + logging taking place in `LoggingNetwork.request()`, it takes place in this + `DefaultNetworkResponse` subclass, as soon as the caller starts reading the + content. If `content` or `json()` are accessed, then the response will be + logged with its content. Whereas if `response_as_stream` or + `request_response` are accessed, then the response will be logged with a + placeholder for the actual content. + + In theory, this could make the logs less useful, by adding a delay between + when the network response was actually received, and when it is logged. Or + the response may never be logged, if the content is never accessed. In + practice, this is unlikely to happen, because nearly all SDK methods + immediately read the content. + """ + + STREAM_CONTENT_NOT_LOGGED = '' + + def __init__(self, logger, successful_response_format, error_response_format, **kwargs): + """Extends baseclass method. + + :param logger: The logger to use. + :type logger: :class:`Logger` + :param successful_response_format: + The logger %-style format string to use for logging ok responses. + + May use the following format placeholders: + + - %(method)s : The HTTP request method ('GET', 'POST', etc.). + - %(url)s : The url of the request. + - %(status_code)s : The HTTP status code of the response. + - %(content_length)s : The Content-Length of the response body. + - %(headers)s : The HTTP headers (as a pretty-printed dict). + - %(content)s : The response body. + + :type successful_response_format: `unicode` + :param error_response_format: + The logger %-style format string to use for logging ok responses. + + May use the same format placeholders as + `successful_response_format`. + :type error_response_format: `unicode` + """ + super(LoggingNetworkResponse, self).__init__(**kwargs) + self._logger = logger + self._successful_response_format = successful_response_format + self._error_response_format = error_response_format + self._did_log = False + + def log(self, can_safely_log_content=False): + """Logs information about the Box API response. + + Will only execute once. Subsequent calls will be no-ops. This is + partially because we only want to log responses once, and partially + because this is necessary to prevent this method from infinite + recursing with its use of the `content` property. + + :param can_safely_log_content: + (optional) `True` if the caller is accessing the `content` + property, `False` otherwise. + + As stated in the class docstring, it is unsafe for this logging + method to access `content` unless the caller is also accessing it. + + Defaults to `False`. + :type can_safely_log_content: `bool` + """ + if self._did_log: + return + self._did_log = True + content_length = self.headers.get('Content-Length', None) + content = self.STREAM_CONTENT_NOT_LOGGED + if can_safely_log_content: + if content_length is None: + content_length = text_type(len(self.content)) + + # If possible, get the content as a JSON `dict`, that way + # `pformat(content)` will return pretty-printed JSON. + try: + content = self.json() + except ValueError: + content = self.content + content = pformat(content) + if content_length is None: + content_length = '?' + if self.ok: + logger_method, response_format = self._logger.info, self._successful_response_format + else: + logger_method, response_format = self._logger.warning, self._error_response_format + logger_method( + response_format, + { + 'method': self.request_response.request.method, + 'url': self.request_response.request.url, + 'status_code': self.status_code, + 'content_length': content_length, + 'headers': pformat(self.headers), + 'content': content, + }, + ) + + def json(self): + """Extends baseclass method.""" + try: + return super(LoggingNetworkResponse, self).json() + finally: + self.log(can_safely_log_content=True) + + @property + def content(self): + """Extends baseclass method.""" + content = super(LoggingNetworkResponse, self).content + self.log(can_safely_log_content=True) + return content + + @property + def response_as_stream(self): + """Extends baseclass method.""" + stream = super(LoggingNetworkResponse, self).response_as_stream + self.log(can_safely_log_content=False) + return stream + + @property + def request_response(self): + """Extends baseclass method.""" + response = super(LoggingNetworkResponse, self).request_response + self.log(can_safely_log_content=False) return response diff --git a/boxsdk/network/network_interface.py b/boxsdk/network/network_interface.py index 1c554ee0b..388dc44b2 100644 --- a/boxsdk/network/network_interface.py +++ b/boxsdk/network/network_interface.py @@ -2,7 +2,7 @@ from __future__ import unicode_literals -from abc import ABCMeta, abstractmethod +from abc import ABCMeta, abstractmethod, abstractproperty from six import add_metaclass @@ -29,6 +29,7 @@ def request(self, method, url, access_token, **kwargs): The OAuth2 access token used to authorize the request. :type access_token: `unicode` + :rtype: :class:`NetworkResponse` """ raise NotImplementedError # pragma: no cover @@ -45,9 +46,30 @@ def retry_after(self, delay, request_method, *args, **kwargs): A callable that will execute the request. :type request_method: `callable` + :rtype: :class:`NetworkResponse` """ raise NotImplementedError # pragma: no cover + @property + def network_response_constructor(self): + """The constructor to use for creating NetworkResponse instances. + + This is not implemented by default, and is not a required part of the + interface. + + It is recommended that implementations of `request()` call this to + construct their responses, rather than hard-coding the construction. + That way, subclasses of the implementation can easily extend the + construction of :class:`NetworkResponse` instances, by overriding this + property, instead of needing to override `request()`. + + :return: + A callable that returns an instance of :class:`NetworkResponse`. + Most commonly, this will be a subclass of :class:`NetworkResponse`. + :rtype: `type` or `callable` + """ + return NetworkResponse + @add_metaclass(ABCMeta) class NetworkResponse(object): @@ -62,7 +84,7 @@ def json(self): """ raise NotImplementedError # pragma: no cover - @abstractmethod + @abstractproperty def content(self): """Return the content of the response body. @@ -71,7 +93,7 @@ def content(self): """ raise NotImplementedError # pragma: no cover - @abstractmethod + @abstractproperty def status_code(self): """Return the HTTP status code of the response. @@ -80,7 +102,7 @@ def status_code(self): """ raise NotImplementedError # pragma: no cover - @abstractmethod + @abstractproperty def ok(self): """Return whether or not the request was successful. @@ -90,7 +112,7 @@ def ok(self): # pylint:disable=invalid-name raise NotImplementedError # pragma: no cover - @abstractmethod + @abstractproperty def headers(self): """Return the response headers. @@ -99,7 +121,7 @@ def headers(self): """ raise NotImplementedError # pragma: no cover - @abstractmethod + @abstractproperty def response_as_stream(self): """Return a stream containing the raw network response. @@ -108,7 +130,7 @@ def response_as_stream(self): """ raise NotImplementedError # pragma: no cover - @abstractmethod + @abstractproperty def access_token_used(self): """Return the access token used to make the request. diff --git a/test/conftest.py b/test/conftest.py index e1f3b0c50..673b44ace 100644 --- a/test/conftest.py +++ b/test/conftest.py @@ -1,24 +1,67 @@ # coding: utf-8 -from __future__ import unicode_literals +from __future__ import absolute_import, unicode_literals + import json +import logging +import sys + from mock import Mock import pytest +import requests +from six import binary_type + from boxsdk.network.default_network import DefaultNetworkResponse +@pytest.fixture(autouse=True, scope='session') +def logger(): + logging.basicConfig(stream=sys.stdout, level=logging.DEBUG) + return logging.getLogger(__name__.split('.')[0]) + + +def _set_content_and_json_from_json(mock_response, json_value): + mock_response.json.return_value = json_value + mock_response.content = content = json.dumps(json_value).encode('utf-8') + mock_response.headers['Content-Length'] = str(len(content)) + + +def _set_content_and_json_from_content(mock_response, content): + if not isinstance(content, binary_type): + raise TypeError("Expected 'content' to be byte string, got {!r}.".format(content.__class__.__name__)) + mock_response.content = content + mock_response.headers['Content-Length'] = str(len(content)) + try: + mock_response.json.return_value = json.loads(content.decode('utf-8')) + except ValueError as exc: + mock_response.json.side_effect = exc + + @pytest.fixture() -def generic_successful_response(): +def generic_successful_request_response(): + mock_request_response = Mock(requests.Response(), headers=dict([('header{0}'.format(i), 'value{0}'.format(i)) for i in range(4)])) + _set_content_and_json_from_json(mock_request_response, json_value=dict([('key{0}'.format(i), 'value{0}'.format(i)) for i in range(8)])) + mock_request_response.status_code = 200 + mock_request_response.ok = True + return mock_request_response + + +def _network_response_mock_from_request_response(request_response): mock_network_response = Mock(DefaultNetworkResponse) - mock_network_response.content = b'{"message": "success"}' - mock_network_response.status_code = 200 - mock_network_response.ok = True - mock_network_response.raw = Mock() - mock_network_response.request_response = Mock() - mock_network_response.request_response.raw = None + mock_network_response.request_response = request_response + mock_network_response.json.side_effect = request_response.json + mock_network_response.content = request_response.content + mock_network_response.headers = request_response.headers + mock_network_response.status_code = request_response.status_code + mock_network_response.ok = request_response.ok return mock_network_response +@pytest.fixture() +def generic_successful_response(generic_successful_request_response): + return _network_response_mock_from_request_response(generic_successful_request_response) + + @pytest.fixture(scope='session') def successful_token_json_response(access_token, refresh_token): # pylint:disable=redefined-outer-name @@ -31,70 +74,118 @@ def successful_token_json_response(access_token, refresh_token): } -@pytest.fixture(scope='session') -def successful_token_response(successful_token_mock, successful_token_json_response): +@pytest.fixture() +def successful_token_request_response(successful_token_json_response): # pylint:disable=redefined-outer-name - successful_token_mock.json = Mock(return_value=successful_token_json_response) + successful_token_mock = Mock(requests.Response(), headers={}) + _set_content_and_json_from_json(successful_token_mock, json_value=successful_token_json_response) successful_token_mock.ok = True - successful_token_mock.content = json.dumps(successful_token_json_response) successful_token_mock.status_code = 200 return successful_token_mock -@pytest.fixture(scope='session') -def successful_token_mock(): - return Mock(DefaultNetworkResponse) +@pytest.fixture() +def successful_token_response(successful_token_request_response): + return _network_response_mock_from_request_response(successful_token_request_response) -@pytest.fixture(scope='session') +@pytest.fixture() +def successful_token_mock(successful_token_response): + return successful_token_response + + +@pytest.fixture() def unauthorized_response(): - res = Mock(DefaultNetworkResponse) - res.content = b'' + res = Mock(DefaultNetworkResponse, headers={}) + _set_content_and_json_from_content(res, content=b'') res.status_code = 401 res.ok = False return res -@pytest.fixture(scope='session') +@pytest.fixture() def non_json_response(): - mock_network_response = Mock(DefaultNetworkResponse) - mock_network_response.content = b'' + mock_network_response = Mock(DefaultNetworkResponse, headers={}) + _set_content_and_json_from_content(mock_network_response, content=b'') mock_network_response.ok = True mock_network_response.status_code = 200 - mock_network_response.json.side_effect = ValueError('No JSON object could be decoded') return mock_network_response -@pytest.fixture(scope='session', params=[202, 429]) -def retry_after_response(request): - mock_network_response = Mock(DefaultNetworkResponse) - mock_network_response.status_code = int(request.param) - mock_network_response.headers = {'Retry-After': '1'} +def _retry_after_response(status_code): + mock_network_response = Mock(DefaultNetworkResponse, headers={}) + mock_network_response.status_code = status_code + mock_network_response.headers.update({'Retry-After': '1'}) return mock_network_response -@pytest.fixture(scope='session', params=[502, 503]) -def server_error_response(request): - mock_network_response = Mock(DefaultNetworkResponse) - mock_network_response.status_code = int(request.param) - mock_network_response.ok = False - return mock_network_response +@pytest.fixture() +def retry_after_response_202(): + return _retry_after_response(202) -@pytest.fixture(scope='session') +@pytest.fixture() +def retry_after_response_429(): + return _retry_after_response(429) + + +@pytest.fixture(params=[202, 429]) +def retry_after_response(retry_after_response_202, retry_after_response_429, request): + if request.param == 202: + return retry_after_response_202 + elif request.param == 429: + return retry_after_response_429 + else: + raise ValueError + + +def _server_error_request_response(status_code): + mock_request_response = Mock(requests.Response(), headers=dict([('header{0}'.format(i), 'value{0}'.format(i)) for i in range(4)])) + _set_content_and_json_from_json(mock_request_response, json_value=dict([('key{0}'.format(i), 'value{0}'.format(i)) for i in range(8)])) + mock_request_response.status_code = status_code + mock_request_response.ok = False + return mock_request_response + + +@pytest.fixture() +def server_error_request_response_502(): + return _server_error_request_response(502) + + +@pytest.fixture() +def server_error_request_response_503(): + return _server_error_request_response(503) + + +@pytest.fixture(params=[502, 503]) +def server_error_request_response(server_error_request_response_502, server_error_request_response_503, request): + if request.param == 502: + return server_error_request_response_502 + elif request.param == 503: + return server_error_request_response_503 + else: + raise ValueError + + +@pytest.fixture +def server_error_response(server_error_request_response): + return _network_response_mock_from_request_response(server_error_request_response) + + +@pytest.fixture() def bad_network_response(): - mock_network_response = Mock(DefaultNetworkResponse) + mock_network_response = Mock(DefaultNetworkResponse, headers={}) mock_network_response.status_code = 404 - mock_network_response.json.return_value = {'code': 404, 'message': 'Not Found'} + _set_content_and_json_from_json(mock_network_response, json_value={'code': 404, 'message': 'Not Found'}) mock_network_response.ok = False return mock_network_response -@pytest.fixture(scope='session') +@pytest.fixture() def failed_non_json_response(): - mock_network_response = Mock(DefaultNetworkResponse) + mock_network_response = Mock(DefaultNetworkResponse, headers={}) mock_network_response.status_code = 404 - mock_network_response.json.side_effect = ValueError('No JSON object could be decoded') + _set_content_and_json_from_content(mock_network_response, content=b'') mock_network_response.ok = False return mock_network_response diff --git a/test/functional/conftest.py b/test/functional/conftest.py index 61efb2c09..987cc4862 100644 --- a/test/functional/conftest.py +++ b/test/functional/conftest.py @@ -12,21 +12,34 @@ from boxsdk.auth.oauth2 import OAuth2 from boxsdk.config import API -from boxsdk.client import Client +from boxsdk.client import LoggingClient +from boxsdk.network.logging_network import LoggingNetwork +from boxsdk.session.box_session import BoxSession from test.functional.mock_box.box import Box from test.util.streamable_mock_open import streamable_mock_open +@pytest.fixture(scope='session') +def network_layer(logger): + return LoggingNetwork(logger=logger) + + @pytest.fixture() -def box_client(box_oauth): +def box_client(box_oauth, box_session, network_layer): + # pylint:disable=redefined-outer-name + return LoggingClient(box_oauth, session=box_session, network_layer=network_layer) + + +@pytest.fixture +def box_session(box_oauth, network_layer): # pylint:disable=redefined-outer-name - return Client(box_oauth) + return BoxSession(oauth=box_oauth, network_layer=network_layer) @pytest.fixture() -def box_oauth(client_id, client_secret, user_login): +def box_oauth(client_id, client_secret, user_login, network_layer): # pylint:disable=redefined-outer-name - oauth2 = OAuth2(client_id, client_secret, box_device_name='mock_box functional test') + oauth2 = OAuth2(client_id, client_secret, box_device_name='mock_box functional test', network_layer=network_layer) url, _ = oauth2.get_authorization_url('http://localhost') form = requests.get(url + '&box_login=' + user_login).content.decode('utf-8') form_action = re.search('action="([^"]*)"', form).group(1) diff --git a/test/integration/conftest.py b/test/integration/conftest.py index bf44eba36..b0572bed1 100644 --- a/test/integration/conftest.py +++ b/test/integration/conftest.py @@ -1,10 +1,11 @@ # coding: utf-8 -from __future__ import unicode_literals -import json +from __future__ import absolute_import, unicode_literals + from mock import Mock import pytest from requests import Response + from boxsdk import Client from boxsdk.auth.oauth2 import OAuth2 from test.integration.mock_network import MockNetwork @@ -33,21 +34,14 @@ def mock_box_network(): return MockNetwork() -@pytest.fixture(scope='session') -def generic_successful_response(): - mock_network_response = Mock(Response) - content = '{"message": "success"}' - mock_network_response.content = content.encode('utf-8') - mock_network_response.status_code = 200 - mock_network_response.ok = True - mock_network_response.raw = Mock() - mock_network_response.json.return_value = json.loads(content) - return mock_network_response +@pytest.fixture +def generic_successful_response(generic_successful_request_response): + return generic_successful_request_response -@pytest.fixture(scope='session') -def successful_token_mock(): - return Mock(Response) +@pytest.fixture +def successful_token_mock(successful_token_request_response): + return successful_token_request_response @pytest.fixture(scope='session') diff --git a/test/unit/auth/test_jwt_auth.py b/test/unit/auth/test_jwt_auth.py index c65af57ad..63b553c7c 100644 --- a/test/unit/auth/test_jwt_auth.py +++ b/test/unit/auth/test_jwt_auth.py @@ -38,7 +38,7 @@ def rsa_passphrase(request): return request.param -@pytest.fixture(scope='module') +@pytest.fixture(scope='function') def successful_token_response(successful_token_mock, successful_token_json_response): # pylint:disable=redefined-outer-name response = successful_token_json_response.copy() diff --git a/test/unit/network/conftest.py b/test/unit/network/conftest.py index b9e08f69d..8d6671cb1 100644 --- a/test/unit/network/conftest.py +++ b/test/unit/network/conftest.py @@ -2,9 +2,47 @@ from __future__ import unicode_literals, absolute_import +from mock import Mock import pytest +from requests import Session @pytest.fixture(params=('GET', 'POST', 'PUT', 'DELETE', 'OPTIONS')) def http_verb(request): return request.param + + +@pytest.fixture() +def mock_request(monkeypatch): + mock_session_factory = Mock() + mock_session_factory.return_value = session = Mock(Session(), request=Mock()) + monkeypatch.setattr('requests.Session', mock_session_factory) + return session.request + + +@pytest.fixture(params=['generic_successful_request_response', 'server_error_request_response_502', 'server_error_request_response_503']) +def request_response(generic_successful_request_response, server_error_request_response_502, server_error_request_response_503, request): + # pylint:disable=unused-argument + return locals()[request.param] + + +@pytest.fixture +def make_request_with_request_response(mock_request, http_verb, test_url, access_token): + + def _make_request_with_request_response(network, request_response, **kwargs): + mock_request.return_value = request_response + response = network.request(http_verb, test_url, access_token, **kwargs) + mock_request.assert_called_once_with(http_verb, test_url, **kwargs) + assert response.access_token_used == access_token + return response + + return _make_request_with_request_response + + +@pytest.fixture +def make_network_request(make_request_with_request_response, request_response): + + def _make_network_request(network, **kwargs): + return make_request_with_request_response(network, request_response, **kwargs) + + return _make_network_request diff --git a/test/unit/network/test_logging_network.py b/test/unit/network/test_logging_network.py index 33a3764b7..8857528ec 100644 --- a/test/unit/network/test_logging_network.py +++ b/test/unit/network/test_logging_network.py @@ -2,11 +2,79 @@ from __future__ import unicode_literals, absolute_import +from functools import partial +import json from logging import Logger +from operator import attrgetter +from pprint import pformat + +import mock from mock import Mock, patch +import pytest +from six import text_type +from six.moves import map from boxsdk.network import default_network, logging_network -from boxsdk.network.logging_network import LoggingNetwork +from boxsdk.network.logging_network import LoggingNetwork, LoggingNetworkResponse + + +class ExceptionSubclass(Exception): + pass + + +@pytest.fixture +def logger(): + return Mock(Logger) + + +@pytest.fixture +def network(logger): + return LoggingNetwork(logger) + + +@pytest.fixture(scope='module') +def logger_method_names(): + return ['critical', 'debug', 'error', 'exception', 'fatal', 'info', 'log', 'warn', 'warning'] + + +@pytest.fixture +def logger_methods(logger, logger_method_names): + return list(map(partial(getattr, logger), logger_method_names)) + + +@pytest.fixture +def assert_logger_called_once_with(logger, logger_method_names): + + def _assert_logger_called_once_with(method_name, *args, **kwargs): + getattr(logger, method_name).assert_called_once_with(*args, **kwargs) + method_names = set(logger_method_names) + method_names.discard(method_name) + for method_name in method_names: + getattr(logger, method_name).assert_not_called() + + return _assert_logger_called_once_with + + +@pytest.fixture +def assert_logger_not_called(logger_methods): + + def _assert_logger_not_called(): + for method in logger_methods: + method.assert_not_called() + + return _assert_logger_not_called + + +@pytest.fixture +def logger_call_count(logger_methods): + + def _logger_call_count(): + return sum(map(attrgetter('call_count'), logger_methods)) + + return _logger_call_count + + +# BEGIN Tests for LoggingNetwork. def test_logging_network_calls_setup_logging_if_logger_is_none(): @@ -16,67 +84,204 @@ def test_logging_network_calls_setup_logging_if_logger_is_none(): assert network.logger is setup_logging.return_value -def test_logging_network_can_be_initialized_if_logger_is_none(): +def test_logging_network_can_be_initialized_if_logger_is_none(logger): with patch('logging.getLogger') as get_logger: - get_logger.return_value = Mock(Logger) + get_logger.return_value = logger network = LoggingNetwork() assert network.logger is get_logger.return_value get_logger.assert_called_once_with(LoggingNetwork.LOGGER_NAME) -def test_logging_network_does_not_call_setup_logging_if_logger_is_not_none(): - logger = Mock(Logger) +def test_logging_network_does_not_call_setup_logging_if_logger_is_not_none(logger): with patch.object(logging_network, 'setup_logging') as setup_logging: network = LoggingNetwork(logger) setup_logging.assert_not_called() assert network.logger is logger -def test_logging_network_logs_requests(http_verb, test_url, access_token): - logger = Mock(Logger) - network = LoggingNetwork(logger) - with patch.object(logging_network, 'pformat') as pformat: - with patch.object(default_network.DefaultNetwork, 'request') as super_request: - network.request(http_verb, test_url, access_token, custom_kwarg='foo') - kwargs = pformat.return_value - super_request.assert_called_once_with(http_verb, test_url, access_token, custom_kwarg='foo') - pformat.assert_called_once_with(dict(custom_kwarg='foo')) - logger.info.assert_any_call(network.REQUEST_FORMAT, http_verb, test_url, kwargs) +def test_logging_network_logs_requests(make_network_request, http_verb, test_url, network, assert_logger_called_once_with): + kwargs = dict(custom_kwarg='foo') + make_network_request(network, **kwargs) + assert_logger_called_once_with( + 'info', + network.REQUEST_FORMAT, + {'method': http_verb, 'url': test_url, 'request_kwargs': pformat(kwargs)}, + ) -def test_logging_network_logs_successful_responses(http_verb, test_url, access_token, generic_successful_response): - logger = Mock(Logger) - network = LoggingNetwork(logger) +def test_logging_network_logs_request_exception(make_network_request, http_verb, test_url, logger, network): with patch.object(default_network.DefaultNetwork, 'request') as super_request: - super_request.return_value = generic_successful_response - network.request(http_verb, test_url, access_token) - super_request.assert_called_once_with(http_verb, test_url, access_token) - logger.info.assert_called_with(network.SUCCESSFUL_RESPONSE_FORMAT, generic_successful_response.content) + super_request.side_effect = expected_exception = ExceptionSubclass('exception raised from request()') + with pytest.raises(ExceptionSubclass) as pytest_exc_info: + make_network_request(network) + assert pytest_exc_info.value is expected_exception + logger.warning.assert_called_once_with( + network.EXCEPTION_FORMAT, + {'method': http_verb, 'url': test_url, 'exc_type_name': ExceptionSubclass.__name__, 'exc_value': expected_exception}, + ) -def test_logging_network_does_not_log_download_content(http_verb, test_url, access_token, generic_successful_response): - logger = Mock(Logger) - network = LoggingNetwork(logger) - generic_successful_response.request_response.raw = Mock() - with patch.object(default_network.DefaultNetwork, 'request') as super_request: - super_request.return_value = generic_successful_response - network.request(http_verb, test_url, access_token) - super_request.assert_called_once_with(http_verb, test_url, access_token) - logger.info.assert_called_with(network.SUCCESSFUL_RESPONSE_FORMAT, network.STREAM_CONTENT_NOT_LOGGED) - - -def test_logging_network_logs_non_successful_responses(http_verb, test_url, access_token, server_error_response): - logger = Mock(Logger) - network = LoggingNetwork(logger) - with patch.object(logging_network, 'pformat') as pformat: - with patch.object(default_network.DefaultNetwork, 'request') as super_request: - super_request.return_value = server_error_response - network.request(http_verb, test_url, access_token) - super_request.assert_called_once_with(http_verb, test_url, access_token) - pformat.assert_called_with(server_error_response.content) - logger.warning.assert_called_once_with( - network.ERROR_RESPONSE_FORMAT, - server_error_response.status_code, - server_error_response.headers, - pformat.return_value, +def test_logging_network_request_returns_logging_network_response(make_network_request, request_response, network): + response = make_network_request(network) + assert response.request_response is request_response + assert isinstance(response, LoggingNetworkResponse) + + +def test_logging_network_response_constructor(make_network_request, access_token, logger, network): + mock_response = Mock(LoggingNetworkResponse, access_token_used=access_token) + with patch.object(logging_network, 'LoggingNetworkResponse') as mock_logging_network_response_class: + mock_logging_network_response_class.return_value = mock_response + assert make_network_request(network) is mock_response + assert mock_logging_network_response_class.call_count == 1 + kwargs = mock_logging_network_response_class.call_args[1] + assert ('logger' in kwargs) and (kwargs['logger'] is logger) + assert ('successful_response_format' in kwargs) and (kwargs['successful_response_format'] is network.SUCCESSFUL_RESPONSE_FORMAT) + assert ('error_response_format' in kwargs) and (kwargs['error_response_format'] is network.ERROR_RESPONSE_FORMAT) + + +# END Tests for LoggingNetwork. + + +# BEGIN Tests for LoggingNetworkResponse. + + +@pytest.fixture +def construct_logging_network_response(logger, access_token): + + def _construct_logging_network_response(request_response): + return LoggingNetworkResponse( + logger=logger, + successful_response_format=LoggingNetwork.SUCCESSFUL_RESPONSE_FORMAT, + error_response_format=LoggingNetwork.ERROR_RESPONSE_FORMAT, + request_response=request_response, + access_token_used=access_token, + ) + + return _construct_logging_network_response + + +@pytest.fixture +def logging_network_response(construct_logging_network_response, request_response): + return construct_logging_network_response(request_response) + + +@pytest.fixture(params=['content', 'json']) +def get_content_from_response(request): + + def _get_content_from_response(response): + content = getattr(response, request.param) + if request.param in ['json']: + try: + content = content() + except ValueError: + pass + + return _get_content_from_response + + +@pytest.fixture(params=['response_as_stream', 'request_response', 'log']) +def do_not_get_content_from_response(request): + + def _do_not_get_content_from_response(response): + attribute = getattr(response, request.param) + if request.param in ['log']: + attribute() + + return _do_not_get_content_from_response + + +def test_logging_network_response_does_not_log_anything_immediately(logging_network_response, logger_call_count): + # pylint:disable=unused-argument + # Need to load the `logging_network_response` fixture for this test to be + # meaningful. + assert logger_call_count() == 0 + + +def test_logging_network_response_only_logs_once(logging_network_response, logger_call_count): + logging_network_response.log() + assert logger_call_count() == 1 + logging_network_response.log() + assert logger_call_count() == 1 + + +@pytest.mark.parametrize('content_length_header', [False, True]) +def test_logging_network_logs_successful_responses( + construct_logging_network_response, generic_successful_request_response, assert_logger_called_once_with, + get_content_from_response, http_verb, test_url, content_length_header, +): + expected_content_length = text_type(len(generic_successful_request_response.content)) + if content_length_header: + generic_successful_request_response.headers['Content-Length'] = expected_content_length + else: + generic_successful_request_response.headers.pop('Content-Length', None) + generic_successful_request_response.request.method = http_verb + generic_successful_request_response.request.url = test_url + logging_network_response = construct_logging_network_response(generic_successful_request_response) + get_content_from_response(logging_network_response) + assert_logger_called_once_with( + 'info', + LoggingNetwork.SUCCESSFUL_RESPONSE_FORMAT, + { + 'method': http_verb, + 'url': test_url, + 'status_code': generic_successful_request_response.status_code, + 'content_length': expected_content_length, + 'headers': pformat(generic_successful_request_response.headers), + 'content': pformat(generic_successful_request_response.json()), + } + ) + + +@pytest.mark.parametrize('content_length_header', [False, True]) +def test_logging_network_logs_successful_responses_with_stream_placeholder( + construct_logging_network_response, generic_successful_request_response, assert_logger_called_once_with, + do_not_get_content_from_response, logger, content_length_header, +): + if content_length_header: + expected_content_length = text_type(len(generic_successful_request_response.content)) + generic_successful_request_response.headers['Content-Length'] = expected_content_length + else: + generic_successful_request_response.headers.pop('Content-Length', None) + expected_content_length = '?' + logging_network_response = construct_logging_network_response(generic_successful_request_response) + do_not_get_content_from_response(logging_network_response) + assert_logger_called_once_with('info', LoggingNetwork.SUCCESSFUL_RESPONSE_FORMAT, mock.ANY) + assert logger.info.call_args[0][1]['content'] == logging_network_response.STREAM_CONTENT_NOT_LOGGED + assert logger.info.call_args[0][1]['content_length'] == expected_content_length + + +def test_logging_network_logs_successful_responses_with_non_json_content( + construct_logging_network_response, generic_successful_request_response, assert_logger_called_once_with, + logger, get_content_from_response, +): + generic_successful_request_response.content = content = (b''.join(chr(i).encode('utf-8') for i in range(128)) * 4) + generic_successful_request_response.json.side_effect = lambda: json.loads(content.decode('utf-8')) + logging_network_response = construct_logging_network_response(generic_successful_request_response) + get_content_from_response(logging_network_response) + assert_logger_called_once_with('info', LoggingNetwork.SUCCESSFUL_RESPONSE_FORMAT, mock.ANY) + assert logger.info.call_args[0][1]['content'] == pformat(content) + + +def test_logging_network_logs_non_successful_responses( + construct_logging_network_response, server_error_request_response, assert_logger_called_once_with, + get_content_from_response, http_verb, test_url, +): + server_error_request_response.request.method = http_verb + server_error_request_response.request.url = test_url + logging_network_response = construct_logging_network_response(server_error_request_response) + get_content_from_response(logging_network_response) + assert_logger_called_once_with( + 'warning', + LoggingNetwork.ERROR_RESPONSE_FORMAT, + { + 'method': http_verb, + 'url': test_url, + 'status_code': server_error_request_response.status_code, + 'content_length': text_type(len(server_error_request_response.content)), + 'headers': pformat(server_error_request_response.headers), + 'content': pformat(server_error_request_response.json()), + } ) + + +# END Tests for LoggingNetworkResponse. diff --git a/test/unit/network/test_network.py b/test/unit/network/test_network.py index 8994e1784..9a734e18a 100644 --- a/test/unit/network/test_network.py +++ b/test/unit/network/test_network.py @@ -1,18 +1,26 @@ # coding: utf-8 -from __future__ import unicode_literals +from __future__ import absolute_import, unicode_literals + from mock import DEFAULT, Mock, patch import pytest -from requests import Response, Session +from requests import Response + from boxsdk.network.default_network import DefaultNetworkResponse, DefaultNetwork -@pytest.fixture() -def mock_request(monkeypatch): - mock_session_factory = Mock() - mock_session_factory.return_value = session = Mock(Session, request=Mock()) - monkeypatch.setattr('requests.Session', mock_session_factory) - return session.request +@pytest.fixture +def make_network_request(make_network_request, request_response, http_verb): + # pylint:disable=unused-argument + # Need to list `http_verb`, even though it isn't used in this override, + # because of . + + def _make_network_request(*args, **kwargs): + response = make_network_request(*args, **kwargs) + assert response.request_response is request_response + return response + + return _make_network_request def test_default_network_response_properties_pass_through_to_session_response_properties(access_token): @@ -30,14 +38,10 @@ def test_default_network_response_properties_pass_through_to_session_response_pr assert network_reponse.access_token_used == access_token -def test_default_network_request(mock_request, http_verb, test_url, access_token, generic_successful_response): +def test_default_network_request(make_network_request): # pylint:disable=redefined-outer-name default_network = DefaultNetwork() - mock_request.return_value = generic_successful_response - response = default_network.request(http_verb, test_url, access_token, custom_kwarg='test') - mock_request.assert_called_once_with(http_verb, test_url, custom_kwarg='test') - assert response.response_as_stream == generic_successful_response.raw - assert response.access_token_used == access_token + make_network_request(default_network, custom_kwargs='test') @pytest.mark.parametrize('delay', (0, 1)) @@ -49,3 +53,19 @@ def test_default_network_retry_after_sleeps(delay): default_network.retry_after(delay, retry_call, DEFAULT, kwarg=DEFAULT) mock_sleep.assert_called_once_with(delay) retry_call.assert_called_once_with(DEFAULT, kwarg=DEFAULT) + + +def test_network_response_constructor(make_network_request): + assert DefaultNetwork().network_response_constructor is DefaultNetworkResponse + + class DefaultNetworkResponseSubclass(DefaultNetworkResponse): + pass + + class DefaultNetworkSubclass(DefaultNetwork): + @property + def network_response_constructor(self): + return DefaultNetworkResponseSubclass + + network = DefaultNetworkSubclass() + response = make_network_request(network) + assert isinstance(response, DefaultNetworkResponseSubclass)