Logging refactors and improvements

Move response logging to a new `LoggingNetworkResponse` class.
This allows us to decide whether to log the response body, based
on whether the caller reads or streams the content. This fixes a
bug introduced by Pull Request #166, where the `LoggingNetwork`
would always omit logging the response body.

Add a `network_response_constructor` property to
`DefaultNetwork`, to make it easier for subclasses to return
their own `NetworkResponse` subclasses. Use this in
`LoggingNetwork`, to return `LoggingNetworkResponse` instances.
Also add it as an optional property on the `Network` interface
class.

In `network_interface.py`, switch some usages of
`@abc.abstractmethod` to `@abc.abstractproperty`. This doesn't
matter on recent versions of Python 3, but there is a difference
between the two on Python 2, plus it makes the interface
clearer. This is a backwards-compatible change, because the SDK
uses these as properties, so any custom implementations would've
needed to implement these with `property` anyway.

Update the logging format strings in `LoggingNetwork`, to make
them more informative and also easier to override (by using
keyword format placeholders instead of positional ones). This is
a breaking change for clients that were overriding these class
attributes.

Add logging for request exceptions in `LoggingNetwork`.

Use the `LoggingNetwork` during functional tests.

Switch some stateful mock fixtures from session scope to
function scope.

Author: jmoldow

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."""

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 = '<File download contents unavailable for logging>'
+    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 = '<File download contents unavailable for logging>'
+
+    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

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.