Add logging on successful request

elasticsearch/connection.py

@@ -18,6 +18,27 @@ class Connection(object):
     def __repr__(self):
         return '<%s: %s>' % (self.__class__.__name__, self.host)
 
+    def log_request_success(self, method, full_url, path, body, status_code, response, duration):
+        def _pretty_json(data):
+            # pretty JSON in tracer curl logs
+            data = json.dumps(json.loads(data), sort_keys=True, indent=2, separators=(',', ': '))
+            return data
+
+        logger.info(
+            '%s %s [status:%s request:%.3fs]', method, full_url,
+            status_code, duration
+        )
+        logger.debug('> %s', body)
+        logger.debug('< %s', response)
+
+        if tracer.isEnabledFor(logging.INFO):
+            # include pretty in trace curls
+            path = path.replace('?', '?pretty&', 1) if '?' in path else path + '?pretty'
+            tracer.info("curl -X%s 'http://localhost:9200%s' -d '%s'", method, path, _pretty_json(body) if body else '')
+
+        if tracer.isEnabledFor(logging.DEBUG):
+            tracer.debug('# [%s] (%.3fs)\n#%s', status_code, duration, _pretty_json(response).replace('\n', '\n#'))
+
 
 class RequestsHttpConnection(Connection):
     def __init__(self, **kwargs):
@@ -27,20 +48,24 @@ class RequestsHttpConnection(Connection):
     def perform_request(self, method, url, params=None, body=None):
         url = self.host + url
 
+        # use prepared requests so that requests formats url and params for us to log
         request = requests.Request(method, url, params=params or {}, data=body).prepare()
+        start = time.time()
         try:
             response = self.session.send(request)
+            duration = time.time() - start
             raw_data = response.text
         except requests.ConnectionError as e:
             raise TransportError(e)
 
         # raise errors based on http status codes, let the client handle those if needed
-        if response.status_code >= 300:
-
+        if not (200 <= response.status_code < 300):
             if response.status_code in HTTP_EXCEPTIONS:
                 raise HTTP_EXCEPTIONS[response.status_code]()
 
             raise TransportError()
 
+        self.log_request_success(method, request.url, request.path_url, body, response.status_code, raw_data, duration)
+
         return response.status_code, raw_data
 

test_elasticsearch/test_connection.py

@@ -1,6 +1,6 @@
 from unittest import TestCase
 
-from mock import Mock
+from mock import Mock, patch
 
 from elasticsearch.connection import RequestsHttpConnection
 
@@ -28,6 +28,44 @@ class TestRequestsConnection(TestCase):
         self.assertEquals(1, len(args))
         return args[0]
 
+
+    @patch('elasticsearch.connection.tracer')
+    @patch('elasticsearch.connection.logger')
+    def test_success_logs_and_traces(self, logger, tracer):
+        con = self._get_mock_connection(response_body='{"answer": 42}')
+        status, data = con.perform_request('GET', '/', {'param': 42}, '{}')
+
+        # trace request
+        self.assertEquals(1, tracer.info.call_count)
+        self.assertEquals(
+            "curl -XGET 'http://localhost:9200/?pretty&param=42' -d '{}'",
+            tracer.info.call_args[0][0] % tracer.info.call_args[0][1:]
+        )
+        # trace response
+        self.assertEquals(1, tracer.debug.call_count)
+        self.assertEquals(
+            '# [200] (0.000s)\n#{\n#  "answer": 42\n#}',
+            tracer.debug.call_args[0][0] % tracer.debug.call_args[0][1:]
+        )
+
+        # log url and duration
+        self.assertEquals(1, logger.info.call_count)
+        self.assertEquals(
+            'GET http://localhost:9200/?param=42 [status:200 request:0.000s]',
+            logger.info.call_args[0][0] % logger.info.call_args[0][1:]
+        )
+        # log request body and response
+        self.assertEquals(2, logger.debug.call_count)
+        req, resp = logger.debug.call_args_list
+        self.assertEquals(
+            '> {}',
+            req[0][0] % req[0][1:]
+        )
+        self.assertEquals(
+            '< {"answer": 42}',
+            resp[0][0] % resp[0][1:]
+        )
+
     def test_defaults(self):
         con = self._get_mock_connection()
         request = self._get_request(con, 'GET', '/')