Change the trace logger to also include failed requests

Changelog.rst

@@ -10,6 +10,9 @@ Version compatible with elasticsearch 5.0
 
  * when using SSL certificate validation is now on by default. Install
    ``certifi`` or supply root certificate bundle.
+ * ``elasticsearch.trace`` logger now also logs failed requests, signature of
+   internal logging method ``log_request_fail`` has changed, all custom
+   connection classes need to be updated
  * added ``headers`` arg to connections to support custom http headers
  * passing in a keyword parameter with ``None`` as value will cause that param
    to be ignored 

elasticsearch/connection/base.py

@@ -45,16 +45,30 @@ class Connection(object):
     def __repr__(self):
         return '<%s: %s>' % (self.__class__.__name__, self.host)
 
+    def _pretty_json(self, data):
+        # pretty JSON in tracer curl logs
+        try:
+            return json.dumps(json.loads(data), sort_keys=True, indent=2, separators=(',', ': ')).replace("'", r'\u0027')
+        except (ValueError, TypeError):
+            # non-json data or a bulk request
+            return data
+
+    def _log_trace(self, method, path, body, status_code, response, duration):
+        if not tracer.isEnabledFor(logging.INFO) or not tracer.handlers:
+            return
+
+        # include pretty in trace curls
+        path = path.replace('?', '?pretty&', 1) if '?' in path else path + '?pretty'
+        if self.url_prefix:
+            path = path.replace(self.url_prefix, '', 1)
+        tracer.info("curl -X%s 'http://localhost:9200%s' -d '%s'", method, path, self._pretty_json(body) if body else '')
+
+        if tracer.isEnabledFor(logging.DEBUG):
+            tracer.debug('#[%s] (%.3fs)\n#%s', status_code, duration, self._pretty_json(response).replace('\n', '\n#') if response else '')
+
     def log_request_success(self, method, full_url, path, body, status_code, response, duration):
         """ Log a successful API call.  """
         #  TODO: optionally pass in params instead of full_url and do urlencode only when needed
-        def _pretty_json(data):
-            # pretty JSON in tracer curl logs
-            try:
-                return json.dumps(json.loads(data), sort_keys=True, indent=2, separators=(',', ': ')).replace("'", r'\u0027')
-            except (ValueError, TypeError):
-                # non-json data or a bulk request
-                return data
 
         # body has already been serialized to utf-8, deserialize it for logging
         # TODO: find a better way to avoid (de)encoding the body back and forth
@@ -68,17 +82,9 @@ class Connection(object):
         logger.debug('> %s', body)
         logger.debug('< %s', response)
 
-        if tracer.isEnabledFor(logging.INFO) and tracer.handlers:
-            # include pretty in trace curls
-            path = path.replace('?', '?pretty&', 1) if '?' in path else path + '?pretty'
-            if self.url_prefix:
-                path = path.replace(self.url_prefix, '', 1)
-            tracer.info("curl -X%s 'http://localhost:9200%s' -d '%s'", method, path, _pretty_json(body) if body else '')
+        self._log_trace(method, path, body, status_code, response, duration)
 
-        if tracer.isEnabledFor(logging.DEBUG):
-            tracer.debug('#[%s] (%.3fs)\n#%s', status_code, duration, _pretty_json(response).replace('\n', '\n#') if response else '')
-
-    def log_request_fail(self, method, full_url, body, duration, status_code=None, response=None, exception=None):
+    def log_request_fail(self, method, full_url, path, body, duration, status_code=None, response=None, exception=None):
         """ Log an unsuccessful API call.  """
         # do not log 404s on HEAD requests
         if method == 'HEAD' and status_code == 404:
@@ -95,6 +101,8 @@ class Connection(object):
 
         logger.debug('> %s', body)
 
+        self._log_trace(method, path, body, status_code, response, duration)
+
         if response is not None:
             logger.debug('< %s', response)
 

elasticsearch/connection/http_requests.py

@@ -71,18 +71,18 @@ class RequestsHttpConnection(Connection):
             duration = time.time() - start
             raw_data = response.text
         except requests.exceptions.SSLError as e:
-            self.log_request_fail(method, url, body, time.time() - start, exception=e)
+            self.log_request_fail(method, url, response.request.path_url, body, time.time() - start, exception=e)
             raise SSLError('N/A', str(e), e)
         except requests.Timeout as e:
-            self.log_request_fail(method, url, body, time.time() - start, exception=e)
+            self.log_request_fail(method, url, response.request.path_url, body, time.time() - start, exception=e)
             raise ConnectionTimeout('TIMEOUT', str(e), e)
         except requests.ConnectionError as e:
-            self.log_request_fail(method, url, body, time.time() - start, exception=e)
+            self.log_request_fail(method, url, response.request.path_url, body, time.time() - start, exception=e)
             raise ConnectionError('N/A', str(e), e)
 
         # raise errors based on http status codes, let the client handle those if needed
         if not (200 <= response.status_code < 300) and response.status_code not in ignore:
-            self.log_request_fail(method, url, body, duration, response.status_code, raw_data)
+            self.log_request_fail(method, url, response.request.path_url, body, duration, response.status_code, raw_data)
             self._raise_error(response.status_code, raw_data)
 
         self.log_request_success(method, url, response.request.path_url, body, response.status_code, raw_data, duration)

elasticsearch/connection/http_urllib3.py

@@ -110,17 +110,17 @@ class Urllib3HttpConnection(Connection):
             duration = time.time() - start
             raw_data = response.data.decode('utf-8')
         except UrllibSSLError as e:
-            self.log_request_fail(method, full_url, body, time.time() - start, exception=e)
+            self.log_request_fail(method, full_url, url, body, time.time() - start, exception=e)
             raise SSLError('N/A', str(e), e)
         except ReadTimeoutError as e:
-            self.log_request_fail(method, full_url, body, time.time() - start, exception=e)
+            self.log_request_fail(method, full_url, url, body, time.time() - start, exception=e)
             raise ConnectionTimeout('TIMEOUT', str(e), e)
         except Exception as e:
-            self.log_request_fail(method, full_url, body, time.time() - start, exception=e)
+            self.log_request_fail(method, full_url, url, body, time.time() - start, exception=e)
             raise ConnectionError('N/A', str(e), e)
 
         if not (200 <= response.status < 300) and response.status not in ignore:
-            self.log_request_fail(method, url, body, duration, response.status, raw_data)
+            self.log_request_fail(method, full_url, url, body, duration, response.status, raw_data)
             self._raise_error(response.status, raw_data)
 
         self.log_request_success(method, full_url, url, body, response.status,

test_elasticsearch/test_connection.py

@@ -138,10 +138,10 @@ class TestRequestsConnection(TestCase):
         con = self._get_mock_connection(response_body='{"answer": 42}', status_code=500)
         self.assertRaises(TransportError, con.perform_request, 'GET', '/', {'param': 42}, '{}'.encode('utf-8'))
 
-        # no trace request
-        self.assertEquals(0, tracer.info.call_count)
-        # no trace response
-        self.assertEquals(0, tracer.debug.call_count)
+        # trace request
+        self.assertEquals(1, tracer.info.call_count)
+        # trace response
+        self.assertEquals(1, tracer.debug.call_count)
         # log url and duration
         self.assertEquals(1, logger.warning.call_count)
         self.assertTrue(re.match(