Avoid decoding request body unless it needs to be logged. (#571)

Signed-off-by: dblock <[email protected]>
Signed-off-by: Daniel (dB.) Doubrovkine <[email protected]>

CHANGELOG.md

@@ -34,6 +34,7 @@ Inspired from [Keep a Changelog](https://keepachangelog.com/en/1.0.0/)
 - Removed leftover support for Python 2.7 ([#548](https://github.com/opensearch-project/opensearch-py/pull/548))
 ### Fixed
 - Fixed automatically built and deployed docs ([575](https://github.com/opensearch-project/opensearch-py/pull/575))
+- Avoid decoding request body unless it needs to be logged ([#571](https://github.com/opensearch-project/opensearch-py/pull/571))
 ### Security
 ### Dependencies
 - Bumps `sphinx` from <7.1 to <7.3

opensearchpy/_async/http_aiohttp.py

@@ -315,7 +315,7 @@ class AIOHttpConnection(AsyncConnection):
         except Exception as e:
             self.log_request_fail(
                 method,
-                str(url),
+                url,
                 url_path,
                 orig_body,
                 self.loop.time() - start,
@@ -337,7 +337,7 @@ class AIOHttpConnection(AsyncConnection):
         if not (200 <= response.status < 300) and response.status not in ignore:
             self.log_request_fail(
                 method,
-                str(url),
+                url,
                 url_path,
                 orig_body,
                 duration,
@@ -351,7 +351,7 @@ class AIOHttpConnection(AsyncConnection):
             )
 
         self.log_request_success(
-            method, str(url), url_path, orig_body, response.status, raw_data, duration
+            method, url, url_path, orig_body, response.status, raw_data, duration
         )
 
         return response.status, response.headers, raw_data

opensearchpy/connection/base.py

@@ -189,6 +189,16 @@ class Connection(object):
             # non-json data or a bulk request
             return data  # type: ignore
 
+    def _log_request_response(
+        self, body: Optional[Union[str, bytes]], response: Optional[str]
+    ) -> None:
+        if logger.isEnabledFor(logging.DEBUG):
+            if body and isinstance(body, bytes):
+                body = body.decode("utf-8", "ignore")
+            logger.debug("> %s", body)
+            if response is not None:
+                logger.debug("< %s", response)
+
     def _log_trace(
         self,
         method: str,
@@ -246,17 +256,11 @@ class Connection(object):
         """Log a successful API call."""
         #  TODO: optionally pass in params instead of full_url and do urlencode only when needed
 
-        # 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
-        if body and isinstance(body, bytes):
-            body = body.decode("utf-8", "ignore")
-
         logger.info(
             "%s %s [status:%s request:%.3fs]", method, full_url, status_code, duration
         )
-        logger.debug("> %s", body)
-        logger.debug("< %s", response)
 
+        self._log_request_response(body, response)
         self._log_trace(method, path, body, status_code, response, duration)
 
     def log_request_fail(
@@ -283,18 +287,9 @@ class Connection(object):
             exc_info=exception is not None,
         )
 
-        # body has already been serialized to utf-8, deserialize it for logging
+        self._log_request_response(body, response)
-        # TODO: find a better way to avoid (de)encoding the body back and forth
-        if body and isinstance(body, bytes):
-            body = body.decode("utf-8", "ignore")
-
-        logger.debug("> %s", body)
-
         self._log_trace(method, path, body, status_code, response, duration)
 
-        if response is not None:
-            logger.debug("< %s", response)
-
     def _raise_error(
         self,
         status_code: int,

test_opensearchpy/test_async/test_connection.py

@@ -44,7 +44,7 @@ from pytest import raises
 from opensearchpy import AIOHttpConnection, AsyncOpenSearch, __versionstr__, serializer
 from opensearchpy.compat import reraise_exceptions
 from opensearchpy.connection import Connection, async_connections
-from opensearchpy.exceptions import ConnectionError, TransportError
+from opensearchpy.exceptions import ConnectionError, NotFoundError, TransportError
 from test_opensearchpy.TestHttpServer import TestHTTPServer
 
 pytestmark: MarkDecorator = pytest.mark.asyncio
@@ -303,6 +303,41 @@ class TestAIOHttpConnection:
         assert '> {"example": "body"}' == req[0][0] % req[0][1:]
         assert "< {}" == resp[0][0] % resp[0][1:]
 
+    @patch("opensearchpy.connection.base.logger", return_value=MagicMock())
+    async def test_body_not_logged(self, logger: Any) -> None:
+        logger.isEnabledFor.return_value = False
+
+        con = await self._get_mock_connection()
+        await con.perform_request("GET", "/", body=b'{"example": "body"}')
+
+        assert logger.isEnabledFor.call_count == 1
+        assert logger.debug.call_count == 0
+
+    @patch("opensearchpy.connection.base.logger")
+    async def test_failure_body_logged(self, logger: Any) -> None:
+        con = await self._get_mock_connection(response_code=404)
+        with pytest.raises(NotFoundError) as e:
+            await con.perform_request("GET", "/invalid", body=b'{"example": "body"}')
+        assert str(e.value) == "NotFoundError(404, '{}')"
+
+        assert 2 == logger.debug.call_count
+        req, resp = logger.debug.call_args_list
+
+        assert '> {"example": "body"}' == req[0][0] % req[0][1:]
+        assert "< {}" == resp[0][0] % resp[0][1:]
+
+    @patch("opensearchpy.connection.base.logger", return_value=MagicMock())
+    async def test_failure_body_not_logged(self, logger: Any) -> None:
+        logger.isEnabledFor.return_value = False
+
+        con = await self._get_mock_connection(response_code=404)
+        with pytest.raises(NotFoundError) as e:
+            await con.perform_request("GET", "/invalid")
+        assert str(e.value) == "NotFoundError(404, '{}')"
+
+        assert logger.isEnabledFor.call_count == 1
+        assert logger.debug.call_count == 0
+
     async def test_surrogatepass_into_bytes(self) -> None:
         buf = b"\xe4\xbd\xa0\xe5\xa5\xbd\xed\xa9\xaa"
         con = await self._get_mock_connection(response_body=buf)

test_opensearchpy/test_connection/test_requests_http_connection.py

@@ -33,7 +33,7 @@ import warnings
 from typing import Any
 
 import pytest
-from mock import Mock, patch
+from mock import MagicMock, Mock, patch
 from requests.auth import AuthBase
 
 from opensearchpy.connection import Connection, RequestsHttpConnection
@@ -52,7 +52,7 @@ class TestRequestsHttpConnection(TestCase):
     def _get_mock_connection(
         self,
         connection_params: Any = {},
-        status_code: int = 200,
+        response_code: int = 200,
         response_body: bytes = b"{}",
     ) -> Any:
         con = RequestsHttpConnection(**connection_params)
@@ -60,7 +60,7 @@ class TestRequestsHttpConnection(TestCase):
         def _dummy_send(*args: Any, **kwargs: Any) -> Any:
             dummy_response = Mock()
             dummy_response.headers = {}
-            dummy_response.status_code = status_code
+            dummy_response.status_code = response_code
             dummy_response.content = response_body
             dummy_response.request = args[0]
             dummy_response.cookies = {}
@@ -229,20 +229,20 @@ class TestRequestsHttpConnection(TestCase):
         )
 
     def test_conflict_error_is_returned_on_409(self) -> None:
-        con = self._get_mock_connection(status_code=409)
+        con = self._get_mock_connection(response_code=409)
         self.assertRaises(ConflictError, con.perform_request, "GET", "/", {}, "")
 
     def test_not_found_error_is_returned_on_404(self) -> None:
-        con = self._get_mock_connection(status_code=404)
+        con = self._get_mock_connection(response_code=404)
         self.assertRaises(NotFoundError, con.perform_request, "GET", "/", {}, "")
 
     def test_request_error_is_returned_on_400(self) -> None:
-        con = self._get_mock_connection(status_code=400)
+        con = self._get_mock_connection(response_code=400)
         self.assertRaises(RequestError, con.perform_request, "GET", "/", {}, "")
 
     @patch("opensearchpy.connection.base.logger")
     def test_head_with_404_doesnt_get_logged(self, logger: Any) -> None:
-        con = self._get_mock_connection(status_code=404)
+        con = self._get_mock_connection(response_code=404)
         self.assertRaises(NotFoundError, con.perform_request, "HEAD", "/", {}, "")
         self.assertEqual(0, logger.warning.call_count)
 
@@ -250,7 +250,7 @@ class TestRequestsHttpConnection(TestCase):
     @patch("opensearchpy.connection.base.logger")
     def test_failed_request_logs_and_traces(self, logger: Any, tracer: Any) -> None:
         con = self._get_mock_connection(
-            response_body=b'{"answer": 42}', status_code=500
+            response_body=b'{"answer": 42}', response_code=500
         )
         self.assertRaises(
             TransportError,
@@ -326,7 +326,7 @@ class TestRequestsHttpConnection(TestCase):
 
         con = self._get_mock_connection(
             connection_params={"http_compress": True},
-            status_code=500,
+            response_code=500,
             response_body=b'{"hello":"world"}',
         )
         with pytest.raises(TransportError):
@@ -337,6 +337,41 @@ class TestRequestsHttpConnection(TestCase):
         self.assertEqual('> {"example": "body2"}', req[0][0] % req[0][1:])
         self.assertEqual('< {"hello":"world"}', resp[0][0] % resp[0][1:])
 
+    @patch("opensearchpy.connection.base.logger", return_value=MagicMock())
+    def test_body_not_logged(self, logger: Any) -> None:
+        logger.isEnabledFor.return_value = False
+
+        con = self._get_mock_connection()
+        con.perform_request("GET", "/", body=b'{"example": "body"}')
+
+        self.assertEqual(logger.isEnabledFor.call_count, 1)
+        self.assertEqual(logger.debug.call_count, 0)
+
+    @patch("opensearchpy.connection.base.logger")
+    def test_failure_body_logged(self, logger: Any) -> None:
+        con = self._get_mock_connection(response_code=404)
+        with pytest.raises(NotFoundError) as e:
+            con.perform_request("GET", "/invalid", body=b'{"example": "body"}')
+        self.assertEqual(str(e.value), "NotFoundError(404, '{}')")
+
+        self.assertEqual(2, logger.debug.call_count)
+        req, resp = logger.debug.call_args_list
+
+        self.assertEqual('> {"example": "body"}', req[0][0] % req[0][1:])
+        self.assertEqual("< {}", resp[0][0] % resp[0][1:])
+
+    @patch("opensearchpy.connection.base.logger", return_value=MagicMock())
+    def test_failure_body_not_logged(self, logger: Any) -> None:
+        logger.isEnabledFor.return_value = False
+
+        con = self._get_mock_connection(response_code=404)
+        with pytest.raises(NotFoundError) as e:
+            con.perform_request("GET", "/invalid")
+        self.assertEqual(str(e.value), "NotFoundError(404, '{}')")
+
+        self.assertEqual(logger.isEnabledFor.call_count, 1)
+        self.assertEqual(logger.debug.call_count, 0)
+
     def test_defaults(self) -> None:
         con = self._get_mock_connection()
         request = self._get_request(con, "GET", "/")
@@ -403,7 +438,7 @@ class TestRequestsHttpConnection(TestCase):
 
         with pytest.raises(RecursionError) as e:
             conn.perform_request("GET", "/")
-        assert str(e.value) == "Wasn't modified!"
+        self.assertEqual(str(e.value), "Wasn't modified!")
 
     def mock_session(self) -> Any:
         access_key = uuid.uuid4().hex
@@ -472,7 +507,7 @@ class TestRequestsHttpConnection(TestCase):
         )
 
 
-class TestRequestsConnectionRedirect:
+class TestRequestsConnectionRedirect(TestCase):
     server1: TestHTTPServer
     server2: TestHTTPServer
 
@@ -495,20 +530,23 @@ class TestRequestsConnectionRedirect:
         conn = RequestsHttpConnection("localhost", port=8080, use_ssl=False, timeout=60)
         with pytest.raises(TransportError) as e:
             conn.perform_request("GET", "/redirect", allow_redirects=False)
-        assert e.value.status_code == 302
+        self.assertEqual(e.value.status_code, 302)
 
     # allow_redirects = True (Default)
     def test_redirect_success_when_allow_redirect_true(self) -> None:
         conn = RequestsHttpConnection("localhost", port=8080, use_ssl=False, timeout=60)
         user_agent = conn._get_default_user_agent()
         status, headers, data = conn.perform_request("GET", "/redirect")
-        assert status == 200
+        self.assertEqual(status, 200)
         data = json.loads(data)
-        assert data["headers"] == {
+        self.assertEqual(
+            data["headers"],
+            {
                 "Host": "localhost:8090",
                 "Accept-Encoding": "identity",
                 "User-Agent": user_agent,
-        }
+            },
+        )
 
 
 class TestSignerWithFrozenCredentials(TestRequestsHttpConnection):

test_opensearchpy/test_connection/test_urllib3_http_connection.py

@@ -36,25 +36,29 @@ from typing import Any
 
 import pytest
 import urllib3
-from mock import Mock, patch
+from mock import MagicMock, Mock, patch
 from urllib3._collections import HTTPHeaderDict
 
 from opensearchpy import __versionstr__
 from opensearchpy.connection import Connection, Urllib3HttpConnection
+from opensearchpy.exceptions import NotFoundError
 
 from ..test_cases import SkipTest, TestCase
 
 
 class TestUrllib3HttpConnection(TestCase):
     def _get_mock_connection(
-        self, connection_params: Any = {}, response_body: bytes = b"{}"
+        self,
+        connection_params: Any = {},
+        response_body: bytes = b"{}",
+        response_code: int = 200,
     ) -> Any:
         con = Urllib3HttpConnection(**connection_params)
 
         def _dummy_urlopen(*args: Any, **kwargs: Any) -> Any:
             dummy_response = Mock()
             dummy_response.headers = HTTPHeaderDict({})
-            dummy_response.status = 200
+            dummy_response.status = response_code
             dummy_response.data = response_body
             _dummy_urlopen.call_args = (args, kwargs)  # type: ignore
             return dummy_response
@@ -219,11 +223,11 @@ class TestUrllib3HttpConnection(TestCase):
 
         with pytest.raises(ValueError) as e:
             Urllib3AWSV4SignerAuth(session, None)
-        assert str(e.value) == "Region cannot be empty"
+        self.assertEqual(str(e.value), "Region cannot be empty")
 
         with pytest.raises(ValueError) as e:
             Urllib3AWSV4SignerAuth(session, "")
-        assert str(e.value) == "Region cannot be empty"
+        self.assertEqual(str(e.value), "Region cannot be empty")
 
     def test_aws_signer_when_credentials_is_null(self) -> None:
         region = "us-west-1"
@@ -232,11 +236,11 @@ class TestUrllib3HttpConnection(TestCase):
 
         with pytest.raises(ValueError) as e:
             Urllib3AWSV4SignerAuth(None, region)
-        assert str(e.value) == "Credentials cannot be empty"
+        self.assertEqual(str(e.value), "Credentials cannot be empty")
 
         with pytest.raises(ValueError) as e:
             Urllib3AWSV4SignerAuth("", region)
-        assert str(e.value) == "Credentials cannot be empty"
+        self.assertEqual(str(e.value), "Credentials cannot be empty")
 
     def test_aws_signer_when_service_is_specified(self) -> None:
         region = "us-west-1"
@@ -339,6 +343,41 @@ class TestUrllib3HttpConnection(TestCase):
         self.assertEqual('> {"example": "body"}', req[0][0] % req[0][1:])
         self.assertEqual("< {}", resp[0][0] % resp[0][1:])
 
+    @patch("opensearchpy.connection.base.logger", return_value=MagicMock())
+    def test_body_not_logged(self, logger: Any) -> None:
+        logger.isEnabledFor.return_value = False
+
+        con = self._get_mock_connection()
+        con.perform_request("GET", "/", body=b'{"example": "body"}')
+
+        self.assertEqual(logger.isEnabledFor.call_count, 1)
+        self.assertEqual(logger.debug.call_count, 0)
+
+    @patch("opensearchpy.connection.base.logger")
+    def test_failure_body_logged(self, logger: Any) -> None:
+        con = self._get_mock_connection(response_code=404)
+        with pytest.raises(NotFoundError) as e:
+            con.perform_request("GET", "/invalid", body=b'{"example": "body"}')
+        self.assertEqual(str(e.value), "NotFoundError(404, '{}')")
+
+        self.assertEqual(2, logger.debug.call_count)
+        req, resp = logger.debug.call_args_list
+
+        self.assertEqual('> {"example": "body"}', req[0][0] % req[0][1:])
+        self.assertEqual("< {}", resp[0][0] % resp[0][1:])
+
+    @patch("opensearchpy.connection.base.logger", return_value=MagicMock())
+    def test_failure_body_not_logged(self, logger: Any) -> None:
+        logger.isEnabledFor.return_value = False
+
+        con = self._get_mock_connection(response_code=404)
+        with pytest.raises(NotFoundError) as e:
+            con.perform_request("GET", "/invalid")
+        self.assertEqual(str(e.value), "NotFoundError(404, '{}')")
+
+        self.assertEqual(logger.isEnabledFor.call_count, 1)
+        self.assertEqual(logger.debug.call_count, 0)
+
     def test_surrogatepass_into_bytes(self) -> None:
         buf = b"\xe4\xbd\xa0\xe5\xa5\xbd\xed\xa9\xaa"
         con = self._get_mock_connection(response_body=buf)
@@ -355,7 +394,7 @@ class TestUrllib3HttpConnection(TestCase):
 
         with pytest.raises(RecursionError) as e:
             conn.perform_request("GET", "/")
-        assert str(e.value) == "Wasn't modified!"
+        self.assertEqual(str(e.value), "Wasn't modified!")
 
 
 class TestSignerWithFrozenCredentials(TestUrllib3HttpConnection):