Skip to content

feat: add client debug logging support for unary-stream gRPC/REST calls #794

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 8 commits into
base: main
Choose a base branch
from

Conversation

parthea
Copy link
Collaborator

@parthea parthea commented Feb 14, 2025

Towards b/383403001

@product-auto-label product-auto-label bot added the size: m Pull request size is medium. label Feb 14, 2025
@parthea parthea force-pushed the add-unary-stream-logging branch from ae07484 to 3b29113 Compare February 14, 2025 22:37
@parthea parthea self-assigned this Feb 14, 2025
@parthea parthea force-pushed the add-unary-stream-logging branch from 739a255 to fdf6bd6 Compare February 14, 2025 23:02
@parthea parthea marked this pull request as ready for review February 19, 2025 14:34
@parthea parthea requested review from a team as code owners February 19, 2025 14:34
@parthea parthea assigned ohmayr and vchudnov-g and unassigned parthea Feb 19, 2025
@parthea parthea changed the title feat: add client debug logging support for unary-stream gRPC calls feat: add client debug logging support for unary-stream gRPC/REST calls Feb 19, 2025
@parthea parthea force-pushed the add-unary-stream-logging branch from 8908765 to 9fac30c Compare March 19, 2025 15:13
@@ -97,19 +100,38 @@ def _process_chunk(self, chunk: str):
self._obj += char
self._escape_next = not self._escape_next if char == "\\" else False

def _log_response_payload(self, response_payload: str): # pragma: NO COVER
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we need to skip coverage here?

_LOGGER.debug(
"Received response via REST stream",
extra={
"response": rest_response,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should we be using httpResponse here instead for structured logs?

)

return grab
elif issubclass(self._response_message_cls, google.protobuf.message.Message):

def grab(this):
return Parse(this._ready_objs.popleft(), this._response_message_cls())
response_payload = this._ready_objs.popleft()
if logging_enabled: # pragma: NO COVER
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we add coverage for this?

Comment on lines +120 to +140
else:
result = next(self._wrapped)
logging_enabled = _LOGGER.isEnabledFor(logging.DEBUG)
if logging_enabled: # pragma: NO COVER
if isinstance(result, proto.Message):
response_payload = type(result).to_json(result)
elif isinstance(result, google.protobuf.message.Message):
response_payload = google.protobuf.json_format.MessageToJson(result)
else:
response_payload = (
f"{type(result).__name__}: {str(pickle.dumps(result))}"
)
grpc_response = {
"payload": response_payload,
"status": "OK",
}
_LOGGER.debug(
f"Received response of type {type(result)} via gRPC stream",
extra={
"response": grpc_response,
},
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can this be added as a helper function and re-used in grpc_helpers_async?

result = await self._call.read()
logging_enabled = _LOGGER.isEnabledFor(logging.DEBUG)
if logging_enabled: # pragma: NO COVER
if isinstance(result, proto.Message):
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you link

{# TODO(https://github.com/googleapis/gapic-generator-python/issues/2293): Investigate if we can improve this logic or wait for next gen protobuf. #}

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, can the parsing logic be added as a helper function and re-used in the gapic? We can file a TODO for the latter.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1

This ties into the issue I still want to get back to b/382299158. Maybe we reference that issue instead of creating a new one, and in that issue we reference these changes so we have easy access.

Comment on lines +104 to +111
rest_response = {
"payload": response_payload,
"status": "OK",
}
_LOGGER.debug(
"Received response via REST stream",
extra={
"response": rest_response,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure we should be using/reference any sort of HTTP response here at all. This helper is being called from grab, and grab simply passes already received messages reconstituted from chunks. So what we should log in grab is something like passing next message to stream: <message>.

We should log http responses where we actually receive the HTTP chunks.

Comment on lines +132 to +134
grpc_response = {
"payload": response_payload,
"status": "OK",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As in the REST case, I don't think we should be logging things here as though we're receiving a response from the server. We should log that we're passing the next item in the stream. (Because, for example, we might be getting _stored_first_result that was received and stored earlier.)

So let's log that we're returning the next item here, but wherever we do receive the item from the server (is it next(self.wrapped)?), we should log that we received X message from the server: <msg> <msg> ....

IOW, let's not conflate for ourselves or our users receiving the streaming data from the server vs passing eached streamed message to the GAPIC user. This is particularly important for async streaming.

result = await self._call.read()
logging_enabled = _LOGGER.isEnabledFor(logging.DEBUG)
if logging_enabled: # pragma: NO COVER
if isinstance(result, proto.Message):
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1

This ties into the issue I still want to get back to b/382299158. Maybe we reference that issue instead of creating a new one, and in that issue we reference these changes so we have easy access.

@@ -94,7 +100,28 @@ def __init__(self):

async def read(self) -> P:
try:
return await self._call.read()
result = await self._call.read()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IIUC, this gRPC doing an actual read from the network, so logging it as such below makes sense.

(just pointing this out to contrast with my other comments about logging returning previously streamed messages to the user)

@vchudnov-g
Copy link
Contributor

Also, could you reference googleapis/gapic-generator-python#2289 rather than the mirrored internal issue in this PR's description?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
size: m Pull request size is medium.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants