From f02d6dee275a5948b3c1e82f9e3635f87c4758cf Mon Sep 17 00:00:00 2001 From: "Daniel (dB.) Doubrovkine" Date: Sun, 12 Nov 2023 14:42:45 -0500 Subject: [PATCH] Avoid decoding request body unless it needs to be logged. (#571) Signed-off-by: dblock Signed-off-by: Daniel (dB.) Doubrovkine --- CHANGELOG.md | 1 + opensearchpy/_async/http_aiohttp.py | 6 +- opensearchpy/connection/base.py | 29 +++----- .../test_async/test_connection.py | 37 +++++++++- .../test_requests_http_connection.py | 74 ++++++++++++++----- .../test_urllib3_http_connection.py | 55 ++++++++++++-- 6 files changed, 155 insertions(+), 47 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 842b1022..b0af7511 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/opensearchpy/_async/http_aiohttp.py b/opensearchpy/_async/http_aiohttp.py index 6ed1e884..f301918f 100644 --- a/opensearchpy/_async/http_aiohttp.py +++ b/opensearchpy/_async/http_aiohttp.py @@ -315,7 +315,7 @@ async def perform_request( except Exception as e: self.log_request_fail( method, - str(url), + url, url_path, orig_body, self.loop.time() - start, @@ -337,7 +337,7 @@ async def perform_request( 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 @@ async def perform_request( ) 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 diff --git a/opensearchpy/connection/base.py b/opensearchpy/connection/base.py index 54308c72..a2774c15 100644 --- a/opensearchpy/connection/base.py +++ b/opensearchpy/connection/base.py @@ -189,6 +189,16 @@ def _pretty_json(self, data: Union[str, bytes]) -> str: # 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 @@ def log_request_success( """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 @@ def log_request_fail( exc_info=exception is not None, ) - # 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.debug("> %s", body) - + self._log_request_response(body, response) 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, diff --git a/test_opensearchpy/test_async/test_connection.py b/test_opensearchpy/test_async/test_connection.py index 7969e987..743add7b 100644 --- a/test_opensearchpy/test_async/test_connection.py +++ b/test_opensearchpy/test_async/test_connection.py @@ -44,7 +44,7 @@ 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 @@ async def test_uncompressed_body_logged(self, logger: Any) -> None: 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) diff --git a/test_opensearchpy/test_connection/test_requests_http_connection.py b/test_opensearchpy/test_connection/test_requests_http_connection.py index 7043ec54..bdfb97d7 100644 --- a/test_opensearchpy/test_connection/test_requests_http_connection.py +++ b/test_opensearchpy/test_connection/test_requests_http_connection.py @@ -33,7 +33,7 @@ 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 @@ def _get_mock_connection( 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 @@ def test_repr(self) -> None: ) 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 @@ def test_head_with_404_doesnt_get_logged(self, logger: Any) -> None: @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 @@ def test_uncompressed_body_logged(self, logger: Any) -> None: 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 @@ def test_uncompressed_body_logged(self, logger: Any) -> None: 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 @@ def send_raise(*_: Any, **__: Any) -> Any: 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 @@ def test_aws_signer_signs_with_query_string(self, mock_sign: Any) -> None: ) -class TestRequestsConnectionRedirect: +class TestRequestsConnectionRedirect(TestCase): server1: TestHTTPServer server2: TestHTTPServer @@ -495,20 +530,23 @@ def test_redirect_failure_when_allow_redirect_false(self) -> None: 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"] == { - "Host": "localhost:8090", - "Accept-Encoding": "identity", - "User-Agent": user_agent, - } + self.assertEqual( + data["headers"], + { + "Host": "localhost:8090", + "Accept-Encoding": "identity", + "User-Agent": user_agent, + }, + ) class TestSignerWithFrozenCredentials(TestRequestsHttpConnection): diff --git a/test_opensearchpy/test_connection/test_urllib3_http_connection.py b/test_opensearchpy/test_connection/test_urllib3_http_connection.py index 9720283b..e22e943f 100644 --- a/test_opensearchpy/test_connection/test_urllib3_http_connection.py +++ b/test_opensearchpy/test_connection/test_urllib3_http_connection.py @@ -36,25 +36,29 @@ 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 @@ def test_aws_signer_when_region_is_null(self) -> None: 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 @@ def test_aws_signer_when_credentials_is_null(self) -> None: 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 @@ def test_uncompressed_body_logged(self, logger: Any) -> None: 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 @@ def urlopen_raise(*_: Any, **__: Any) -> Any: 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):