Improve debug logs. (#3126)

Print request and response bodies with newlines, rather than all on one line.
Remove "Omitted empty field" log, which gets logged meaninglessly for every JSON
serialization.
Remove duplicated logging of responses.
Log the base64 version of the nonce, rather than turning it into bytes and
logging the backslash-escaped version of those bytes.
Only pass -vv in tests.

acme/acme/client.py

@@ -1,4 +1,5 @@
 """ACME client API."""
+import base64
 import collections
 import datetime
 from email.utils import parsedate_tz
@@ -28,6 +29,8 @@ logger = logging.getLogger(__name__)
 if sys.version_info < (2, 7, 9):  # pragma: no cover
     requests.packages.urllib3.contrib.pyopenssl.inject_into_urllib3()
 
+DER_CONTENT_TYPE = 'application/pkix-cert'
+
 
 class Client(object):  # pylint: disable=too-many-instance-attributes
     """ACME client.
@@ -45,7 +48,6 @@ class Client(object):  # pylint: disable=too-many-instance-attributes
         `verify_ssl`.
 
     """
-    DER_CONTENT_TYPE = 'application/pkix-cert'
 
     def __init__(self, directory, key, alg=jose.RS256, verify_ssl=True,
                  net=None):
@@ -304,7 +306,7 @@ class Client(object):  # pylint: disable=too-many-instance-attributes
         # TODO: assert len(authzrs) == number of SANs
         req = messages.CertificateRequest(csr=csr)
 
-        content_type = self.DER_CONTENT_TYPE  # TODO: add 'cert_type 'argument
+        content_type = DER_CONTENT_TYPE  # TODO: add 'cert_type 'argument
         response = self.net.post(
             authzrs[0].new_cert_uri,  # TODO: acme-spec #90
             req,
@@ -406,7 +408,7 @@ class Client(object):  # pylint: disable=too-many-instance-attributes
         :rtype: tuple
 
         """
-        content_type = self.DER_CONTENT_TYPE  # TODO: make it a param
+        content_type = DER_CONTENT_TYPE  # TODO: make it a param
         response = self.net.get(uri, headers={'Accept': content_type},
                                 content_type=content_type)
         return response, jose.ComparableX509(OpenSSL.crypto.load_certificate(
@@ -521,10 +523,11 @@ class ClientNetwork(object):  # pylint: disable=too-many-instance-attributes
         :rtype: `.JWS`
 
         """
-        jobj = obj.json_dumps().encode()
-        logger.debug('Serialized JSON: %s', jobj)
+        jobj = obj.json_dumps(indent=2).encode()
+        logger.debug('JWS payload:\n%s', jobj)
         return jws.JWS.sign(
-            payload=jobj, key=self.key, alg=self.alg, nonce=nonce).json_dumps()
+            payload=jobj, key=self.key, alg=self.alg,
+            nonce=nonce).json_dumps(indent=2)
 
     @classmethod
     def _check_response(cls, response, content_type=None):
@@ -545,9 +548,6 @@ class ClientNetwork(object):  # pylint: disable=too-many-instance-attributes
         :raises .ClientError: In case of other networking errors.
 
         """
-        logger.debug('Received response %s (headers: %s): %r',
-                     response, response.headers, response.content)
-
         response_ct = response.headers.get('Content-Type')
         try:
             # TODO: response.json() is called twice, once here, and
@@ -599,14 +599,26 @@ class ClientNetwork(object):  # pylint: disable=too-many-instance-attributes
 
 
         """
-        logging.debug('Sending %s request to %s. args: %r, kwargs: %r',
-                      method, url, args, kwargs)
+        if method == "POST":
+            logging.debug('Sending POST request to %s:\n%s',
+                          url, kwargs['data'])
+        else:
+            logging.debug('Sending %s request to %s.', method, url)
         kwargs['verify'] = self.verify_ssl
         kwargs.setdefault('headers', {})
         kwargs['headers'].setdefault('User-Agent', self.user_agent)
         response = self.session.request(method, url, *args, **kwargs)
-        logging.debug('Received %s. Headers: %s. Content: %r',
-                      response, response.headers, response.content)
+        # If content is DER, log the base64 of it instead of raw bytes, to keep
+        # binary data out of the logs.
+        if response.headers.get("Content-Type") == DER_CONTENT_TYPE:
+            debug_content = base64.b64encode(response.content)
+        else:
+            debug_content = response.content
+        logger.debug('Received response:\nHTTP %d\n%s\n\n%s',
+                     response.status_code,
+                     "\n".join(["{0}: {1}".format(k, v)
+                                for k, v in response.headers.items()]),
+                     debug_content)
         return response
 
     def head(self, *args, **kwargs):
@@ -631,7 +643,7 @@ class ClientNetwork(object):  # pylint: disable=too-many-instance-attributes
                 decoded_nonce = jws.Header._fields['nonce'].decode(nonce)
             except jose.DeserializationError as error:
                 raise errors.BadNonce(nonce, error)
-            logger.debug('Storing nonce: %r', decoded_nonce)
+            logger.debug('Storing nonce: %s', nonce)
             self._nonces.add(decoded_nonce)
         else:
             raise errors.MissingNonce(response)

acme/acme/client_test.py

@@ -534,6 +534,29 @@ class ClientNetworkTest(unittest.TestCase):
             'HEAD', 'http://example.com/', 'foo',
             headers=mock.ANY, verify=mock.ANY, bar='baz')
 
+    @mock.patch('acme.client.logger')
+    def test_send_request_get_der(self, mock_logger):
+        self.net.session = mock.MagicMock()
+        self.net.session.request.return_value = mock.MagicMock(
+            ok=True, status_code=http_client.OK,
+            headers={"Content-Type": "application/pkix-cert"},
+            content=b"hi")
+        # pylint: disable=protected-access
+        self.net._send_request('HEAD', 'http://example.com/', 'foo', bar='baz')
+        mock_logger.debug.assert_called_once_with(
+            'Received response:\nHTTP %d\n%s\n\n%s', 200,
+            'Content-Type: application/pkix-cert', b'aGk=')
+
+    def test_send_request_post(self):
+        self.net.session = mock.MagicMock()
+        self.net.session.request.return_value = self.response
+        # pylint: disable=protected-access
+        self.assertEqual(self.response, self.net._send_request(
+            'POST', 'http://example.com/', 'foo', data='qux', bar='baz'))
+        self.net.session.request.assert_called_once_with(
+            'POST', 'http://example.com/', 'foo',
+            headers=mock.ANY, verify=mock.ANY, data='qux', bar='baz')
+
     def test_send_request_verify_ssl(self):
         # pylint: disable=protected-access
         for verify in True, False:

acme/acme/jose/json_util.py

@@ -253,10 +253,6 @@ class JSONObjectWithFields(util.ImmutableMap, interfaces.JSONDeSerializable):
                     raise errors.SerializationError(
                         'Could not encode {0} ({1}): {2}'.format(
                             slot, value, error))
-        if omitted:
-            # pylint: disable=star-args
-            logger.debug('Omitted empty fields: %s', ', '.join(
-                '{0!s}={1!r}'.format(*field) for field in omitted))
         return jobj
 
     def to_partial_json(self):

tests/integration/_common.sh

@@ -32,6 +32,6 @@ certbot_test_no_force_renew () {
         --agree-tos \
         --register-unsafely-without-email \
         --debug \
-        -vvvvvvv \
+        -vv \
         "$@"
 }