Add DEBUG_API_REQUESTS Anymail setting to dump API communications.

Optionally dump API requests and responses to stdout, to simplify
debugging of the raw API communications. Currently implemented only
for Requests-based backends.

This (undocumented) setting can log things like API keys, so is not
appropriate for use in production.

CHANGELOG.rst

@@ -25,6 +25,20 @@ Release history
 ^^^^^^^^^^^^^^^
     ..  This extra heading level keeps the ToC from becoming unmanageably long
 
+v4.3
+----
+
+*In development*
+
+Features
+~~~~~~~~
+
+*  Add (undocumented) DEBUG_API_REQUESTS Anymail setting. When enabled, prints raw
+   API request and response during send. Currently implemented only for Requests-based
+   backends (all but Amazon SES and SparkPost). Because this can expose API keys and
+   other sensitive info in log files, it should not be used in production.
+
+
 v4.2
 ----
 

anymail/backends/base.py

@@ -29,6 +29,8 @@ class AnymailBaseBackend(BaseEmailBackend):
                                                                kwargs=kwargs, default=False)
         self.ignore_recipient_status = get_anymail_setting('ignore_recipient_status',
                                                            kwargs=kwargs, default=False)
+        self.debug_api_requests = get_anymail_setting('debug_api_requests',  # generate debug output
+                                                      kwargs=kwargs, default=False)
 
         # Merge SEND_DEFAULTS and <esp_name>_SEND_DEFAULTS settings
         send_defaults = get_anymail_setting('send_defaults', default={})  # but not from kwargs

anymail/backends/base_requests.py

@@ -1,4 +1,7 @@
+from __future__ import print_function
+
 import requests
+import six
 from six.moves.urllib.parse import urljoin
 
 from anymail.utils import get_anymail_setting
@@ -32,6 +35,8 @@ class AnymailRequestsBackend(AnymailBaseBackend):
             self.session.headers["User-Agent"] = "django-anymail/{version}-{esp} {orig}".format(
                 esp=self.esp_name.lower(), version=__version__,
                 orig=self.session.headers.get("User-Agent", ""))
+            if self.debug_api_requests:
+                self.session.hooks['response'].append(self._dump_api_request)
             return True
 
     def close(self):
@@ -100,6 +105,33 @@ class AnymailRequestsBackend(AnymailBaseBackend):
                                           email_message=message, payload=payload, response=response,
                                           backend=self)
 
+    @staticmethod
+    def _dump_api_request(response, **kwargs):
+        """Print the request and response for debugging"""
+        # (This is not byte-for-byte, but a readable text representation that assumes
+        # UTF-8 encoding if encoded, and that omits the CR in CRLF line endings.
+        # If you need the raw bytes, configure HTTPConnection logging as shown
+        # in http://docs.python-requests.org/en/v3.0.0/api/#api-changes)
+        request = response.request  # a PreparedRequest
+        print(u"\n===== Anymail API request")
+        print(u"{method} {url}\n{headers}".format(
+            method=request.method, url=request.url,
+            headers=u"".join(u"{header}: {value}\n".format(header=header, value=value)
+                             for (header, value) in request.headers.items()),
+        ))
+        if request.body is not None:
+            body_text = (request.body if isinstance(request.body, six.text_type)
+                         else request.body.decode("utf-8", errors="replace")
+                         ).replace("\r\n", "\n")
+            print(body_text)
+        print(u"\n----- Response")
+        print(u"HTTP {status} {reason}\n{headers}\n{body}".format(
+            status=response.status_code, reason=response.reason,
+            headers=u"".join(u"{header}: {value}\n".format(header=header, value=value)
+                             for (header, value) in response.headers.items()),
+            body=response.text,  # Let Requests decode body content for us
+        ))
+
 
 class RequestsPayload(BasePayload):
     """Abstract Payload for AnymailRequestsBackend"""

tests/test_base_backends.py

@@ -1,7 +1,8 @@
-from django.test import override_settings
+from django.test import override_settings, SimpleTestCase
 
 from anymail.backends.base_requests import AnymailRequestsBackend, RequestsPayload
 from anymail.message import AnymailMessage, AnymailRecipientStatus
+from tests.utils import AnymailTestMixin
 
 from .mock_requests_backend import RequestsBackendMockAPITestCase
 
@@ -10,12 +11,14 @@ class MinimalRequestsBackend(AnymailRequestsBackend):
     """(useful only for these tests)"""
 
     esp_name = "Example"
+    api_url = "https://httpbin.org/post"  # helpful echoback endpoint for live testing
 
     def __init__(self, **kwargs):
-        super(MinimalRequestsBackend, self).__init__("https://esp.example.com/api/", **kwargs)
+        super(MinimalRequestsBackend, self).__init__(self.api_url, **kwargs)
 
     def build_message_payload(self, message, defaults):
-        return MinimalRequestsPayload(message, defaults, self)
+        _payload_init = getattr(message, "_payload_init", {})
+        return MinimalRequestsPayload(message, defaults, self, **_payload_init)
 
     def parse_recipient_status(self, response, payload, message):
         return {'to@example.com': AnymailRecipientStatus('message-id', 'sent')}
@@ -49,7 +52,7 @@ class RequestsBackendBaseTestCase(RequestsBackendMockAPITestCase):
     def test_minimal_requests_backend(self):
         """Make sure the testing backend defined above actually works"""
         self.message.send()
-        self.assert_esp_called("https://esp.example.com/api/")
+        self.assert_esp_called("https://httpbin.org/post")
 
     def test_timeout_default(self):
         """All requests have a 30 second default timeout"""
@@ -63,3 +66,44 @@ class RequestsBackendBaseTestCase(RequestsBackendMockAPITestCase):
         self.message.send()
         timeout = self.get_api_call_arg('timeout')
         self.assertEqual(timeout, 5)
+
+
+@override_settings(EMAIL_BACKEND='tests.test_base_backends.MinimalRequestsBackend')
+class RequestsBackendLiveTestCase(SimpleTestCase, AnymailTestMixin):
+    @override_settings(ANYMAIL_DEBUG_API_REQUESTS=True)
+    def test_debug_logging(self):
+        message = AnymailMessage('Subject', 'Text Body', 'from@example.com', ['to@example.com'])
+        message._payload_init = dict(
+            data="Request body",
+            headers={
+                "Content-Type": "text/plain",
+                "Accept": "application/json",
+            },
+        )
+        with self.assertPrints("===== Anymail API request") as outbuf:
+            message.send()
+
+        # Header order and response data vary to much to do a full comparison, but make sure
+        # that the output contains some expected pieces of the request and the response"
+        output = outbuf.getvalue()
+        self.assertIn("\nPOST https://httpbin.org/post\n", output)
+        self.assertIn("\nUser-Agent: django-anymail/", output)
+        self.assertIn("\nAccept: application/json\n", output)
+        self.assertIn("\nContent-Type: text/plain\n", output)  # request
+        self.assertIn("\n\nRequest body\n", output)
+        self.assertIn("\n----- Response\n", output)
+        self.assertIn("\nHTTP 200 OK\n", output)
+        self.assertIn("\nContent-Type: application/json\n", output)  # response
+
+    def test_no_debug_logging(self):
+        # Make sure it doesn't output anything when DEBUG_API_REQUESTS is not set
+        message = AnymailMessage('Subject', 'Text Body', 'from@example.com', ['to@example.com'])
+        message._payload_init = dict(
+            data="Request body",
+            headers={
+                "Content-Type": "text/plain",
+                "Accept": "application/json",
+            },
+        )
+        with self.assertPrints("", match="equal"):
+            message.send()

tests/utils.py

@@ -12,6 +12,7 @@ from distutils.util import strtobool
 
 import six
 from django.test import Client
+from six.moves import StringIO
 
 
 def envbool(var, default=False):
@@ -173,6 +174,41 @@ class AnymailTestMixin:
             raise self.failureException(
                 msg or "%r is not a valid UUID" % uuid_str)
 
+    @contextmanager
+    def assertPrints(self, expected, match="contain", msg=None):
+        """Use as a context manager; checks that code writes `expected` to stdout.
+
+        `match` can be "contain", "equal", "start", "end", or the name of any str
+        method that takes one str argument and returns a boolean, or None to simply
+        capture stdout without checking it. Default is "contain".
+
+        Returns StringIO buffer; the output text is available as cm.getvalue().
+
+        >>> with self.assertPrints("foo") as cm:
+        ...     print("foo")
+        >>> self.assertNotIn("bar", cm.getvalue())
+        """
+        matchfn = {
+            "contain": "__contains__",
+            "equal": "__eq__",
+            "start": "startswith",
+            "end": "endswith",
+        }.get(match, match)
+        old_stdout = sys.stdout
+        buffer = StringIO()
+        try:
+            sys.stdout = buffer
+            yield buffer
+            if matchfn:
+                actual = buffer.getvalue()
+                bound_matchfn = getattr(actual, matchfn)
+                if not bound_matchfn(expected):
+                    raise self.failureException(
+                        msg or "Stdout {actual!r} does not {match} {expected!r}".format(
+                            actual=actual, match=match, expected=expected))
+        finally:
+            sys.stdout = old_stdout
+
 
 # Backported from Python 3.4
 class _AssertLogsContext(object):