feat: parse request/response for logging (#1696)

* feat: parse request/response for logging

* add test case for list

* address PR comments

* address PR feedback

* fix typo

* add test coverage

* add code coverage

Author: ohmayr

google/auth/_helpers.py

@@ -19,6 +19,7 @@
 import datetime
 from email.message import Message
 import hashlib
+import json
 import logging
 import sys
 from typing import Any, Mapping, Optional
@@ -344,7 +345,7 @@ def request_log(
     logger: logging.Logger,
     method: str,
     url: str,
-    body: Optional[Any],
+    body: Optional[bytes],
     headers: Optional[Mapping[str, str]],
 ) -> None:
     """
@@ -357,10 +358,84 @@ def request_log(
         body: The request body (can be None).
         headers: The request headers (can be None).
     """
-    # TODO(https://github.com/googleapis/google-auth-library-python/issues/1682): Add httpRequest extra to log event.
     # TODO(https://github.com/googleapis/google-auth-library-python/issues/1681): Hash sensitive information.
     if is_logging_enabled(logger):
-        logger.debug("Making request: %s %s", method, url)
+        content_type = (
+            headers["Content-Type"] if headers and "Content-Type" in headers else ""
+        )
+        json_body = _parse_request_body(body, content_type=content_type)
+        logger.debug(
+            "Making request...",
+            extra={
+                "httpRequest": {
+                    "method": method,
+                    "url": url,
+                    "body": json_body,
+                    "headers": headers,
+                }
+            },
+        )
+
+
+def _parse_request_body(body: Optional[bytes], content_type: str = "") -> Any:
+    """
+    Parses a request body, handling bytes and string types, and different content types.
+
+    Args:
+        body (Optional[bytes]): The request body.
+        content_type (str): The content type of the request body, e.g., "application/json",
+            "application/x-www-form-urlencoded", or "text/plain". If empty, attempts
+            to parse as JSON.
+
+    Returns:
+        Parsed body (dict, str, or None).
+        - JSON: Decodes if content_type is "application/json" or None (fallback).
+        - URL-encoded: Parses if content_type is "application/x-www-form-urlencoded".
+        - Plain text: Returns string if content_type is "text/plain".
+        - None: Returns if body is None, UTF-8 decode fails, or content_type is unknown.
+    """
+    if body is None:
+        return None
+    try:
+        body_str = body.decode("utf-8")
+    except (UnicodeDecodeError, AttributeError):
+        return None
+    content_type = content_type.lower()
+    if not content_type or "application/json" in content_type:
+        try:
+            return json.loads(body_str)
+        except (json.JSONDecodeError, TypeError):
+            return body_str
+    if "application/x-www-form-urlencoded" in content_type:
+        parsed_query = urllib.parse.parse_qs(body_str)
+        result = {k: v[0] for k, v in parsed_query.items()}
+        return result
+    if "text/plain" in content_type:
+        return body_str
+    return None
+
+
+def _parse_response(response: Any) -> Any:
+    """
+    Parses a response, attempting to decode JSON.
+
+    Args:
+        response: The response object to parse. This can be any type, but
+            it is expected to have a `json()` method if it contains JSON.
+
+    Returns:
+        The parsed response. If the response contains valid JSON, the
+        decoded JSON object (e.g., a dictionary or list) is returned.
+        If the response does not have a `json()` method or if the JSON
+        decoding fails, the original response object is returned.
+    """
+    try:
+        json_response = response.json()
+        return json_response
+    except AttributeError:
+        return response
+    except json.JSONDecodeError:
+        return response
 
 
 def response_log(logger: logging.Logger, response: Any) -> None:
@@ -371,7 +446,7 @@ def response_log(logger: logging.Logger, response: Any) -> None:
         logger: The logging.Logger instance to use.
         response: The HTTP response object to log.
     """
-    # TODO(https://github.com/googleapis/google-auth-library-python/issues/1683): Add httpResponse extra to log event.
     # TODO(https://github.com/googleapis/google-auth-library-python/issues/1681): Hash sensitive information.
     if is_logging_enabled(logger):
-        logger.debug("Response received...")
+        json_response = _parse_response(response)
+        logger.debug("Response received...", extra={"httpResponse": json_response})

tests/test__helpers.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 
 import datetime
+import json
 import logging
 from unittest import mock
 import urllib
@@ -100,7 +101,7 @@ def test_to_bytes_with_bytes():
 
 
 def test_to_bytes_with_unicode():
-    value = u"string-val"
+    value = "string-val"
     encoded_value = b"string-val"
     assert _helpers.to_bytes(value) == encoded_value
 
@@ -111,13 +112,13 @@ def test_to_bytes_with_nonstring_type():
 
 
 def test_from_bytes_with_unicode():
-    value = u"bytes-val"
+    value = "bytes-val"
     assert _helpers.from_bytes(value) == value
 
 
 def test_from_bytes_with_bytes():
     value = b"string-val"
-    decoded_value = u"string-val"
+    decoded_value = "string-val"
     assert _helpers.from_bytes(value) == decoded_value
 
 
@@ -306,10 +307,18 @@ def test_request_log_debug_enabled(logger, caplog):
             logger,
             "GET",
             "http://example.com",
-            {"key": "value"},
+            b'{"key": "value"}',
             {"Authorization": "Bearer token"},
         )
-    assert "Making request: GET http://example.com" in caplog.text
+    assert len(caplog.records) == 1
+    record = caplog.records[0]
+    assert record.message == "Making request..."
+    assert record.httpRequest == {
+        "method": "GET",
+        "url": "http://example.com",
+        "body": {"key": "value"},
+        "headers": {"Authorization": "Bearer token"},
+    }
 
 
 def test_request_log_debug_disabled(logger, caplog):
@@ -328,12 +337,137 @@ def test_request_log_debug_disabled(logger, caplog):
 def test_response_log_debug_enabled(logger, caplog):
     logger.setLevel(logging.DEBUG)
     with mock.patch("google.auth._helpers.CLIENT_LOGGING_SUPPORTED", True):
-        _helpers.response_log(logger, "response_object")
-    assert "Response received..." in caplog.text
+        _helpers.response_log(logger, {"payload": None})
+    assert len(caplog.records) == 1
+    record = caplog.records[0]
+    assert record.message == "Response received..."
+    assert record.httpResponse == {"payload": None}
 
 
 def test_response_log_debug_disabled(logger, caplog):
     logger.setLevel(logging.INFO)
     with mock.patch("google.auth._helpers.CLIENT_LOGGING_SUPPORTED", True):
         _helpers.response_log(logger, "another_response")
     assert "Response received..." not in caplog.text
+
+
+def test_response_log_debug_enabled_response_list(logger, caplog):
+    # NOTE: test the response log when response.json() returns a list as per
+    #  https://requests.readthedocs.io/en/latest/api/#requests.Response.json.
+    class MockResponse:
+        def json(self):
+            return ["item1", "item2", "item3"]
+
+    response = MockResponse()
+    logger.setLevel(logging.DEBUG)
+    with mock.patch("google.auth._helpers.CLIENT_LOGGING_SUPPORTED", True):
+        _helpers.response_log(logger, response)
+    assert len(caplog.records) == 1
+    record = caplog.records[0]
+    assert record.message == "Response received..."
+    assert record.httpResponse == ["item1", "item2", "item3"]
+
+
+def test_parse_request_body_bytes_valid():
+    body = b"key1=value1&key2=value2"
+    expected = {"key1": "value1", "key2": "value2"}
+    assert (
+        _helpers._parse_request_body(
+            body, content_type="application/x-www-form-urlencoded"
+        )
+        == expected
+    )
+
+
+def test_parse_request_body_bytes_empty():
+    body = b""
+    assert _helpers._parse_request_body(body) == ""
+
+
+def test_parse_request_body_bytes_invalid_encoding():
+    body = b"\xff\xfe\xfd"  # Invalid UTF-8 sequence
+    assert _helpers._parse_request_body(body) is None
+
+
+def test_parse_request_body_bytes_malformed_query():
+    body = b"key1=value1&key2=value2"  # missing equals
+    expected = {"key1": "value1", "key2": "value2"}
+    assert (
+        _helpers._parse_request_body(
+            body, content_type="application/x-www-form-urlencoded"
+        )
+        == expected
+    )
+
+
+def test_parse_request_body_none():
+    assert _helpers._parse_request_body(None) is None
+
+
+def test_parse_request_body_bytes_no_content_type():
+    body = b'{"key": "value"}'
+    expected = {"key": "value"}
+    assert _helpers._parse_request_body(body) == expected
+
+
+def test_parse_request_body_bytes_content_type_json():
+    body = b'{"key": "value"}'
+    expected = {"key": "value"}
+    assert (
+        _helpers._parse_request_body(body, content_type="application/json") == expected
+    )
+
+
+def test_parse_request_body_content_type_urlencoded():
+    body = b"key=value"
+    expected = {"key": "value"}
+    assert (
+        _helpers._parse_request_body(
+            body, content_type="application/x-www-form-urlencoded"
+        )
+        == expected
+    )
+
+
+def test_parse_request_body_bytes_content_type_text():
+    body = b"This is plain text."
+    expected = "This is plain text."
+    assert _helpers._parse_request_body(body, content_type="text/plain") == expected
+
+
+def test_parse_request_body_content_type_invalid():
+    body = b'{"key": "value"}'
+    assert _helpers._parse_request_body(body, content_type="invalid") is None
+
+
+def test_parse_request_body_other_type():
+    assert _helpers._parse_request_body(123) is None
+    assert _helpers._parse_request_body("string") is None
+
+
+def test_parse_response_json_valid():
+    class MockResponse:
+        def json(self):
+            return {"data": "test"}
+
+    response = MockResponse()
+    expected = {"data": "test"}
+    assert _helpers._parse_response(response) == expected
+
+
+def test_parse_response_json_invalid():
+    class MockResponse:
+        def json(self):
+            raise json.JSONDecodeError("msg", "doc", 0)
+
+    response = MockResponse()
+    assert _helpers._parse_response(response) == response
+
+
+def test_parse_response_no_json_method():
+    response = "plain text"
+    assert _helpers._parse_response(response) == "plain text"
+
+
+def test_parse_response_none():
+    assert _helpers._parse_response(None) is None