feat: add debug log when sending requests via REST (#2270)

Co-authored-by: ohmayr <[email protected]>
Co-authored-by: Victor Chudnovsky <[email protected]>

Author: 3 people

gapic/templates/%namespace/%name_%version/%sub/services/%service/_shared_macros.j2

@@ -195,13 +195,15 @@ def _get_http_options():
     Args:
         body_spec (str): The http options body i.e. method.http_options[0].body
         method_name (str): The method name.
-        service_name (str): The service name.
+        service: The service.
         is_async (bool): Used to determine the code path i.e. whether for sync or async call. #}
-{% macro rest_call_method_common(body_spec, method_name, service_name, is_async=False) %}
+{% macro rest_call_method_common(body_spec, method_name, service, is_async=False) %}
+{% set service_name = service.name %}
 {% set await_prefix = "await " if is_async else "" %}
 {% set async_class_prefix = "Async" if is_async else "" %}
 
     http_options = _Base{{ service_name }}RestTransport._Base{{method_name}}._get_http_options()
+    {# TODO(https://github.com/googleapis/gapic-generator-python/issues/2274): Add debug log before intercepting a request #} 
     request, metadata = {{ await_prefix }}self._interceptor.pre_{{ method_name|snake_case }}(request, metadata)
     transcoded_request = _Base{{ service_name }}RestTransport._Base{{method_name}}._get_transcoded_request(http_options, request)
 
@@ -212,6 +214,24 @@ def _get_http_options():
     # Jsonify the query params
     query_params = _Base{{ service_name }}RestTransport._Base{{method_name}}._get_query_params_json(transcoded_request)
 
+    if CLIENT_LOGGING_SUPPORTED and _LOGGER.isEnabledFor(logging.DEBUG):  # pragma: NO COVER
+        request_url = "{host}{uri}".format(host=self._host, uri=transcoded_request['uri'])
+        method = transcoded_request['method']
+        http_request = {
+          "payload":   type(request).to_json(request),
+          "requestMethod": method,
+          "requestUrl": request_url,
+        }
+        _LOGGER.debug(
+            f"Sending request for  {{ service.meta.address.proto_package_versioned }}.{{ service.client_name }}.{{ method_name }}",
+            extra = {
+                "serviceName": "{{ service.meta.address.proto }}",
+                "rpcName": "{{ method_name }}",
+                "metadata": str(dict(metadata)),
+                "httpRequest": http_request,
+            },
+        )
+
     # Send the request
     response = {{ await_prefix }}{{ async_class_prefix }}{{ service_name }}RestTransport._{{method_name}}._get_response(self._host, metadata, query_params, self._session, timeout, transcoded_request{% if body_spec %}, body{% endif %})
 
@@ -434,7 +454,7 @@ class _{{ name }}(_Base{{ service.name }}RestTransport._Base{{name}}, {{ async_m
             {{ sig.response_type }}: Response from {{ name }} method.
         {% endif %}
         """
-        {{ rest_call_method_common(body_spec, name, service.name, is_async)|indent(4) }}
+        {{ rest_call_method_common(body_spec, name, service, is_async)|indent(4) }}
 
         {% if sig.response_type == "None" %}
         return {{ await_prefix }}self._interceptor.post_{{ name|snake_case }}(None)
@@ -447,6 +467,22 @@ class _{{ name }}(_Base{{ service.name }}RestTransport._Base{{name}}, {{ async_m
         resp = {{ sig.response_type }}()
         resp = json_format.Parse(content, resp)
         resp = {{ await_prefix }}self._interceptor.post_{{ name|snake_case }}(resp)
+        if CLIENT_LOGGING_SUPPORTED and _LOGGER.isEnabledFor(logging.DEBUG):  # pragma: NO COVER
+            http_response = {
+                "payload": json_format.MessageToJson(response),
+                "headers":  dict(response.headers),
+                "status": response.status_code,
+            }        
+            _LOGGER.debug(
+                "Received response for {{ service.meta.address.proto_package_versioned }}.{{ service.async_client_name }}.{{ name }}",
+                extra = {
+                    "serviceName": "{{ service.meta.address.proto }}",
+                    "rpcName": "{{ name }}",
+                    {# TODO(https://github.com/googleapis/gapic-generator-python/issues/2275): logging `metadata` seems repetitive and may need to be cleaned up #}
+                    "metadata": http_response["headers"],
+                    "httpResponse": http_response,
+                },
+            )
         return resp
         {% endif %}
 

gapic/templates/%namespace/%name_%version/%sub/services/%service/client.py.j2

@@ -617,8 +617,8 @@ class {{ service.client_name }}(metaclass={{ service.client_name }}Meta):
                     extra = {
                         "serviceName": "{{ service.meta.address.proto }}",
                         "universeDomain": getattr(self._transport._credentials, "universe_domain", ""),
-                        "credentialType": f"{type(self._transport._credentials).__module__}.{type(self._transport._credentials).__qualname__}",
-                        "credentialInfo": getattr(self.transport._credentials, "get_cred_info", lambda: None)(),
+                        "credentialsType": f"{type(self._transport._credentials).__module__}.{type(self._transport._credentials).__qualname__}",
+                        "credentialsInfo": getattr(self.transport._credentials, "get_cred_info", lambda: None)(),
                     },
                 )
 

gapic/templates/%namespace/%name_%version/%sub/services/%service/transports/rest.py.j2

@@ -3,9 +3,10 @@
 
 {% block content %}
 
+import logging
+import json  # type: ignore
 
 from google.auth.transport.requests import AuthorizedSession  # type: ignore
-import json  # type: ignore
 from google.auth import credentials as ga_credentials  # type: ignore
 from google.api_core import exceptions as core_exceptions
 from google.api_core import retry as retries
@@ -40,6 +41,13 @@ try:
 except AttributeError:  # pragma: NO COVER
     OptionalRetry = Union[retries.Retry, object, None]  # type: ignore
 
+try:  # pragma: NO COVER
+    from google.api_core import client_logging  # type: ignore
+    CLIENT_LOGGING_SUPPORTED = True
+except ImportError:
+    CLIENT_LOGGING_SUPPORTED = False
+
+_LOGGER = logging.getLogger(__name__)
 
 DEFAULT_CLIENT_INFO = gapic_v1.client_info.ClientInfo(
     gapic_version=BASE_DEFAULT_CLIENT_INFO.gapic_version,
@@ -227,7 +235,7 @@ class {{service.name}}RestTransport(_Base{{ service.name }}RestTransport):
             {% endif %}
             """
 
-            {{ shared_macros.rest_call_method_common(body_spec, method.name, service.name)|indent(8) }}
+            {{ shared_macros.rest_call_method_common(body_spec, method.name, service)|indent(8) }}
 
             {% if not method.void %}
             # Return the response
@@ -246,7 +254,24 @@ class {{service.name}}RestTransport(_Base{{ service.name }}RestTransport):
 
             json_format.Parse(response.content, pb_resp, ignore_unknown_fields=True)
             {% endif %}{# method.lro #}
+            {#- TODO(https://github.com/googleapis/gapic-generator-python/issues/2274): Add debug log before intercepting a request #} 
             resp = self._interceptor.post_{{ method.name|snake_case }}(resp)
+            if CLIENT_LOGGING_SUPPORTED and _LOGGER.isEnabledFor(logging.DEBUG):  # pragma: NO COVER
+                http_response = {
+                "payload": {% if method.output.ident.is_proto_plus_type %}{{ method.output.ident }}.to_json(resp){% else %}json_format.MessageToJson(resp){% endif %},
+                "headers":  dict(response.headers),
+                "status": response.status_code,
+                }
+                _LOGGER.debug(
+                    "Received response for {{ service.meta.address.proto_package_versioned }}.{{ service.client_name }}.{{ method.transport_safe_name|snake_case }}",
+                    extra = {
+                        "serviceName": "{{ service.meta.address.proto }}",
+                        "rpcName": "{{ method.name }}",
+                        {# TODO(https://github.com/googleapis/gapic-generator-python/issues/2275): logging `metadata` seems repetitive and may need to be cleaned up #}
+                        "metadata": http_response["headers"],
+                        "httpResponse": http_response,
+                    },
+                )
             return resp
 
             {% endif %}{# method.void #}

gapic/templates/%namespace/%name_%version/%sub/services/%service/transports/rest_asyncio.py.j2

@@ -58,6 +58,17 @@ from .rest_base import _Base{{ service.name }}RestTransport
 
 from .base import DEFAULT_CLIENT_INFO as BASE_DEFAULT_CLIENT_INFO
 
+
+import logging
+
+try:  # pragma: NO COVER
+    from google.api_core import client_logging  # type: ignore
+    CLIENT_LOGGING_SUPPORTED = True
+except ImportError:
+    CLIENT_LOGGING_SUPPORTED = False
+
+_LOGGER = logging.getLogger(__name__)
+
 try:
     OptionalRetry = Union[retries.AsyncRetry, gapic_v1.method._MethodDefault, None]
 except AttributeError:  # pragma: NO COVER
@@ -188,7 +199,7 @@ class Async{{service.name}}RestTransport(_Base{{ service.name }}RestTransport):
             {% endif %}
             """
 
-            {{ shared_macros.rest_call_method_common(body_spec, method.name, service.name, is_async=True)|indent(8) }}
+            {{ shared_macros.rest_call_method_common(body_spec, method.name, service, is_async=True)|indent(8) }}
 
             {% if not method.void %}
             # Return the response
@@ -206,6 +217,22 @@ class Async{{service.name}}RestTransport(_Base{{ service.name }}RestTransport):
             json_format.Parse(content, pb_resp, ignore_unknown_fields=True)
             {% endif %}{# if method.server_streaming #}
             resp = await self._interceptor.post_{{ method.name|snake_case }}(resp)
+            if CLIENT_LOGGING_SUPPORTED and _LOGGER.isEnabledFor(logging.DEBUG):  # pragma: NO COVER
+                http_response = {
+                    "payload": {% if method.output.ident.is_proto_plus_type %}{{ method.output.ident }}.to_json(response){% else %}json_format.MessageToJson(response){% endif %},
+                    "headers":  str(dict(response.headers)),
+                    "status": "OK", # need to obtain this properly
+                }
+                _LOGGER.debug(
+                    "Received response for {{ service.meta.address.proto_package_versioned }}.{{ service.async_client_name }}.{{ method.transport_safe_name|snake_case }}",
+                    extra = {
+                        "serviceName": "{{ service.meta.address.proto }}",
+                        "rpcName": "{{ method.name }}",
+                        "metadata": http_response["headers"],
+                        "httpResponse": http_response,
+                    },
+                )
+            
             return resp
 
             {% endif %}{# method.void #}

tests/integration/goldens/asset/google/cloud/asset_v1/services/asset_service/client.py

@@ -638,8 +638,8 @@ def __init__(self, *,
                     extra = {
                         "serviceName": "google.cloud.asset.v1.AssetService",
                         "universeDomain": getattr(self._transport._credentials, "universe_domain", ""),
-                        "credentialType": f"{type(self._transport._credentials).__module__}.{type(self._transport._credentials).__qualname__}",
-                        "credentialInfo": getattr(self.transport._credentials, "get_cred_info", lambda: None)(),
+                        "credentialsType": f"{type(self._transport._credentials).__module__}.{type(self._transport._credentials).__qualname__}",
+                        "credentialsInfo": getattr(self.transport._credentials, "get_cred_info", lambda: None)(),
                     },
                 )