From 88076e46c71fe99c7d3e121bb0fc73aa6fbc80fa Mon Sep 17 00:00:00 2001 From: Jacob Hoffman-Andrews Date: Wed, 26 Oct 2016 18:07:33 -0700 Subject: [PATCH] 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 | 40 +++++++++++++++++++++++------------- acme/acme/client_test.py | 23 +++++++++++++++++++++ acme/acme/jose/json_util.py | 4 ---- tests/integration/_common.sh | 2 +- 4 files changed, 50 insertions(+), 19 deletions(-) diff --git a/acme/acme/client.py b/acme/acme/client.py index 6a648bb92..d041cc7d7 100644 --- a/acme/acme/client.py +++ b/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) diff --git a/acme/acme/client_test.py b/acme/acme/client_test.py index 374f8954c..e0403ef28 100644 --- a/acme/acme/client_test.py +++ b/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: diff --git a/acme/acme/jose/json_util.py b/acme/acme/jose/json_util.py index da38b55ba..cc66d77ff 100644 --- a/acme/acme/jose/json_util.py +++ b/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): diff --git a/tests/integration/_common.sh b/tests/integration/_common.sh index 935d44994..8d01ad763 100755 --- a/tests/integration/_common.sh +++ b/tests/integration/_common.sh @@ -32,6 +32,6 @@ certbot_test_no_force_renew () { --agree-tos \ --register-unsafely-without-email \ --debug \ - -vvvvvvv \ + -vv \ "$@" }