Fix AIOHttpConnection logging to include the URL query

Author: sethmlarson

elasticsearch/_async/http_aiohttp.py

@@ -242,8 +242,10 @@ async def perform_request(
         url_path = self.url_prefix + url
         if params:
             query_string = urlencode(params)
+            url_target = "%s?%s" % (url_path, query_string)
         else:
             query_string = ""
+            url_target = url_path
 
         # There is a bug in aiohttp that disables the re-use
         # of the connection in the pool when method=HEAD.
@@ -324,7 +326,7 @@ async def perform_request(
             self.log_request_fail(
                 method,
                 str(url),
-                url_path,
+                url_target,
                 orig_body,
                 self.loop.time() - start,
                 exception=e,
@@ -346,7 +348,7 @@ async def perform_request(
             self.log_request_fail(
                 method,
                 str(url),
-                url_path,
+                url_target,
                 orig_body,
                 duration,
                 status_code=response.status,
@@ -355,7 +357,7 @@ async def perform_request(
             self._raise_error(response.status, raw_data)
 
         self.log_request_success(
-            method, str(url), url_path, orig_body, response.status, raw_data, duration
+            method, str(url), url_target, orig_body, response.status, raw_data, duration
         )
 
         return response.status, response_headers, raw_data

test_elasticsearch/test_async/test_connection.py

@@ -19,6 +19,7 @@
 import gzip
 import io
 import json
+import re
 import ssl
 import warnings
 from platform import python_version
@@ -30,7 +31,7 @@
 
 from elasticsearch import AIOHttpConnection, AsyncElasticsearch, __versionstr__
 from elasticsearch.compat import reraise_exceptions
-from elasticsearch.exceptions import ConnectionError
+from elasticsearch.exceptions import ConnectionError, NotFoundError
 
 pytestmark = pytest.mark.asyncio
 
@@ -41,7 +42,9 @@ def gzip_decompress(data):
 
 
 class TestAIOHttpConnection:
-    async def _get_mock_connection(self, connection_params={}, response_body=b"{}"):
+    async def _get_mock_connection(
+        self, connection_params={}, status_code=200, response_body=b"{}"
+    ):
         con = AIOHttpConnection(**connection_params)
         await con._create_aiohttp_session()
 
@@ -61,7 +64,7 @@ async def read(self):
 
             dummy_response = DummyResponse()
             dummy_response.headers = CIMultiDict()
-            dummy_response.status = 200
+            dummy_response.status = status_code
             _dummy_request.call_args = (args, kwargs)
             return dummy_response
 
@@ -313,6 +316,91 @@ async def test_uncompressed_body_logged(self, logger):
         assert '> {"example": "body"}' == req[0][0] % req[0][1:]
         assert "< {}" == resp[0][0] % resp[0][1:]
 
+    @patch("elasticsearch.connection.base.logger")
+    async def test_full_url_logged(self, logger):
+        conn = await self._get_mock_connection()
+        await conn.perform_request(
+            "GET", "/", params={"key": "val"}, body=b'{"example": "body"}'
+        )
+
+        assert logger.info.call_count == 1
+        assert (
+            logger.info.call_args_list[0][0][0] % logger.info.call_args_list[0][0][1:]
+            == "GET http://localhost:9200/?key=val [status:200 request:0.000s]"
+        )
+
+        conn = await self._get_mock_connection(status_code=404)
+        with pytest.raises(NotFoundError):
+            await conn.perform_request(
+                "GET", "/", params={"key": "val"}, body=b'{"example": "body"}'
+            )
+
+        assert logger.warning.call_count == 1
+        assert (
+            logger.warning.call_args_list[0][0][0]
+            % logger.warning.call_args_list[0][0][1:]
+            == "GET http://localhost:9200/?key=val [status:404 request:0.000s]"
+        )
+
+    @patch("elasticsearch.connection.base.tracer")
+    @patch("elasticsearch.connection.base.logger")
+    async def test_failed_request_logs_and_traces(self, logger, tracer):
+        conn = await self._get_mock_connection(
+            response_body=b'{"answer": 42}', status_code=404
+        )
+        with pytest.raises(NotFoundError):
+            await conn.perform_request("GET", "/", params={"param": 42}, body=b"{}")
+
+        # trace request
+        assert 1 == tracer.info.call_count
+        # trace response
+        assert 1 == tracer.debug.call_count
+        # log url and duration
+        assert 1 == logger.warning.call_count
+        assert re.match(
+            r"^GET http://localhost:9200/\?param=42 \[status:404 request:0.[0-9]{3}s\]",
+            logger.warning.call_args[0][0] % logger.warning.call_args[0][1:],
+        )
+
+    @patch("elasticsearch.connection.base.tracer")
+    @patch("elasticsearch.connection.base.logger")
+    async def test_success_logs_and_traces(self, logger, tracer):
+        conn = await self._get_mock_connection(
+            response_body=b"""{"answer": "that's it!"}"""
+        )
+        await conn.perform_request(
+            "GET",
+            "/",
+            {"param": 42},
+            """{"question": "what's that?"}""".encode("utf-8"),
+        )
+
+        # trace request
+        assert 1 == tracer.info.call_count
+        assert (
+            """curl -H 'Content-Type: application/json' -XGET 'http://localhost:9200/?pretty&param=42' -d '{\n  "question": "what\\u0027s that?"\n}'"""
+            == tracer.info.call_args[0][0] % tracer.info.call_args[0][1:]
+        )
+        # trace response
+        assert 1 == tracer.debug.call_count
+        assert re.match(
+            r'#\[200\] \(0.[0-9]{3}s\)\n#{\n#  "answer": "that\\u0027s it!"\n#}',
+            tracer.debug.call_args[0][0] % tracer.debug.call_args[0][1:],
+        )
+
+        # log url and duration
+        assert 1 == logger.info.call_count
+        assert re.match(
+            r"GET http://localhost:9200/\?param=42 \[status:200 request:0.[0-9]{3}s\]",
+            logger.info.call_args[0][0] % logger.info.call_args[0][1:],
+        )
+
+        # log request body and response
+        assert 2 == logger.debug.call_count
+        req, resp = logger.debug.call_args_list
+        assert '> {"question": "what\'s that?"}' == req[0][0] % req[0][1:]
+        assert '< {"answer": "that\'s it!"}' == resp[0][0] % resp[0][1:]
+
     async def test_surrogatepass_into_bytes(self):
         buf = b"\xe4\xbd\xa0\xe5\xa5\xbd\xed\xa9\xaa"
         con = await self._get_mock_connection(response_body=buf)