feat: add client debug logging support for streaming gRPC calls

[parthea]

Fixes #2289

Also see necessary changes in googleapis/python-api-core#794 to add logging in the response iterator each time a chunk is received in the stream.

Sync Server Streaming

tests/system/test_streams.py 
{"timestamp": "2025-02-19 14:31:06,113", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.client", "message": "Created client `google.showcase_v1beta1.EchoClient`.", "serviceName": "google.showcase.v1beta1.Echo", "credentialsType": "builtins.NoneType", "universeDomain": ""}
{"timestamp": "2025-02-19 14:31:06,130", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"The\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,131", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"hail\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,132", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"in\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,133", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"Wales\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,134", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"falls\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,135", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"mainly\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,135", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"on\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,136", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"the\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-19 14:31:06,137", "severity": "DEBUG", "name": "google.api_core.grpc_helpers", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"snails.\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
.
============================== 1 passed in 4.24s ===============================

Async Server Streaming

tests/system/test_streams.py 
{"timestamp": "2025-02-14 22:09:14,950", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.async_client", "message": "Created client `google.showcase_v1beta1.EchoAsyncClient`.", "serviceName": "google.showcase.v1beta1.Echo", "credentialsType": "builtins.NoneType", "universeDomain": ""}
{"timestamp": "2025-02-14 22:09:14,959", "severity": "DEBUG", "name": "google.showcase_v1beta1.services.echo.transports.grpc_asyncio", "message": "Sending request for b'/google.showcase.v1beta1.Echo/Expand'", "rpcName": "b'/google.showcase.v1beta1.Echo/Expand'", "serviceName": "google.showcase.v1beta1.Echo", "request": {"payload": "{\n  \"content\": \"The hail in Wales falls mainly on the snails.\"\n}", "requestMethod": "grpc", "metadata": {"showcase-trailer": "hello world", "x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.1 gapic/0.0.0"}}, "metadata": {"showcase-trailer": "hello world", "x-goog-api-version": "v1_20240408", "x-goog-api-client": "gl-python/3.9.16 grpc/1.67.1 gax/2.24.1 gapic/0.0.0"}}
{"timestamp": "2025-02-14 22:09:14,967", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"The\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,969", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"hail\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,970", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"in\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,971", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"Wales\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,972", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"falls\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,973", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"mainly\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,973", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"on\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,974", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"the\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
{"timestamp": "2025-02-14 22:09:14,975", "severity": "DEBUG", "name": "google.api_core.grpc_helpers_async", "message": "Received response of type <class 'google.showcase_v1beta1.types.echo.EchoResponse'> via gRPC stream", "response": {"payload": "{\n  \"content\": \"snails.\",\n  \"severity\": 0,\n  \"requestId\": \"\",\n  \"otherRequestId\": \"\"\n}", "status": "OK"}}
.

[ohmayr]

Can we add a note here to clarify that:

• request logging for streaming calls lives in the generator but response logging for streaming calls lives in python-api-core, briefly explaining why.
• request / response logging for unary calls lives in the generator.

This'll make it easier for us to track down the implementation in the future.

[parthea]

Fixed in 84c7986

[vchudnov-g]

I don't think I've encountered the term "unary-stream" before, and it took me seeing the examples in the PR description to be sure I understood what you meant. I suggest using standard terminology, "server streaming", or clarifying that that's what you mean by "unary-stream".

Furthermore, this "logging-stream-from-the-server" functionality should also apply to bidi streaming. Does it? Do we have an example/golden? (Apologies if I've missed it; I focused this review on just looking at the redis golden files)

[parthea]

Unary Stream is a term used in gRPC. I can't change any references to that but I have updated terminology in this PR which can be changed to use Server Streaming instead of Unary-Stream
https://grpc.github.io/grpc/python/grpc.html#grpc.UnaryStreamClientInterceptor.intercept_unary_stream