Skip to content
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.

Sign up for GitHub

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

Add basic logging #396

Draft
wants to merge 1 commit into
base: develop
Choose a base branch
from
Draft

Add basic logging #396

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
39 changes: 29 additions & 10 deletions codegen/core/src/main/java/software/amazon/smithy/python/codegen/ClientGenerator.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -229,7 +229,7 @@ async def _handle_execution(
event_response_deserializer: DeserializeableShape | None = None,
${/hasEventStream}
) -> Output:
logger.debug(f"Making request for operation {operation_name} with parameters: {input}")
logger.debug('Making request for operation "%s" with parameters: %s', operation_name, input)
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Example:

DEBUG:bedrock_runtime.client:Making request for operation "Converse" with parameters: ConverseInput(model_id='amazon.titan-text-express-v1', messages=[Message(role='user', content=[ContentBlockText(value='Create a list of 3 best songs from the 1990s')])], system=None, inference_config=None, tool_config=None, guardrail_config=None, additional_model_request_fields=None, prompt_variables=None, additional_model_response_field_paths=None, request_metadata=None, performance_config=None)

context: InterceptorContext[Input, None, None, None] = InterceptorContext(
request=input,
response=None,
Expand Down Expand Up @@ -326,17 +326,26 @@ async def _handle_execution(
)
except SmithyRetryException:
raise context_with_response.response
logger.debug(
"Retry needed. Attempting request #%s in %s seconds.",
Copy link
Contributor

Choose a reason for hiding this comment

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

Does retry_count start at 0 or 1 on our first call? i.e. is the first log message request 1 or 2?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

retry_count starts at 0. In the case where we need to retry a request, this get's increased to 1 before this log message. I'm adding 1 to this value to represent the number of the next attempt.

Here are our docs on retry_count:

retry_count: int
"""Retry count is the total number of attempts minus the initial attempt."""

Here is an example of the first log message that gets printed when testing this:

DEBUG:bedrock_runtime.client:Retry needed. Attempting request #2 in 0.012663600881869781 seconds.

Copy link
Contributor

Choose a reason for hiding this comment

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

Ok if the first log starts at 2, then this probably fine. I would say let's constrain the formatting a little though for seconds. Something like %.3f (or 4) should work to give us enough relevant information. I don't think we need full precision for this.

retry_token.retry_count + 1,
retry_token.retry_delay
)
await sleep(retry_token.retry_delay)
current_body = context_with_transport_request.transport_request.body
if (seek := getattr(current_body, "seek", None)) is not None:
await seek(0)
else:
# Step 8: Invoke record_success
logger.debug(
"Attempt %s succeeded. Not retrying request.",
Copy link
Contributor

Choose a reason for hiding this comment

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

We should probably quantify what attempt succeeded, I don't know if there's enough context here to be immediately clear.

I'm also not sure if we need to log this at all as it may produce more noise than value. Generally we want to record exceptional cases rather than noting everything that happened.

Suggested change
"Attempt %s succeeded. Not retrying request.",
"Request attempt %s succeeded. Not retrying request.",

retry_token.retry_count + 1
)
retry_strategy.record_success(token=retry_token)
break
except Exception as e:
if context.response is not None:
logger.exception(f"Exception occurred while handling: {context.response}")
logger.exception("Exception occurred while handling: %s", context.response)
Copy link
Contributor

Choose a reason for hiding this comment

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

What gets logged with this? Do we have an example response payload?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yup, here is an example response:

ERROR:bedrock_runtime.client:Exception occurred while handling: Missing Authentication Token

pass
context._response = e

Expand Down Expand Up @@ -443,10 +452,12 @@ async def _handle_attempt(
raise $1T(
"No endpoint_uri found on the operation config."
)

endpoint_resolver_parameters = StaticEndpointParams(uri=config.endpoint_uri)
logger.debug("Calling endpoint resolver with parameters: %s", endpoint_resolver_parameters)
Comment on lines +455 to +456
Copy link
Contributor

Choose a reason for hiding this comment

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

We may need to rationalize this against Alex's other Endpoint work. I hope we don't need to add different log statements for each endpoint resolver.

Copy link

Choose a reason for hiding this comment

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

Yeah - I'm planning on doing a small refactor of the endpoint generator so that this code wouldn't be duplicated between them. (IE - the only thing that should be different between different endpoint generators is the parameter classes and how they are constructed)

Copy link

Choose a reason for hiding this comment

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

See refactoring: 2a4e6f0

This should play nicely with the logging above.

endpoint = await config.endpoint_resolver.resolve_endpoint(
StaticEndpointParams(uri=config.endpoint_uri)
endpoint_resolver_parameters
)
logger.debug("Endpoint resolver result: %s", endpoint)
if not endpoint.uri.path:
path = ""
elif endpoint.uri.path.endswith("/"):
Expand Down Expand Up @@ -484,6 +495,11 @@ async def _handle_attempt(
writer.write("""
# Step 7i: sign the request
if auth_option and signer:
logger.debug("HTTP request to sign: %s", context.transport_request)
logger.debug(
"Signer properties: %s",
auth_option.signer_properties
)
Comment on lines +498 to +502
Copy link
Contributor

Choose a reason for hiding this comment

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

I can build this to check but if you have a quick answer, what does the output of these look like? I haven't checked our repr's for them.

context._transport_request = await signer.sign(
http_request=context.transport_request,
identity=identity,
Expand Down Expand Up @@ -518,10 +534,13 @@ async def _handle_attempt(
context_with_response = cast(
InterceptorContext[Input, None, $1T, $2T], context
)
logger.debug("HTTP request config: %s", request_config)
logger.debug("Sending HTTP request: %s", context_with_response.transport_request)
Comment on lines +537 to +538
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Example:

DEBUG:bedrock_runtime.client:HTTP request config: HTTPRequestConfiguration(read_timeout=None)
DEBUG:bedrock_runtime.client:Sending HTTP request: HTTPRequest(destination=URI(scheme='https', username=None, password=None, host='bedrock-runtime.us-east-1.amazonaws.com', port=None, path='/model/amazon.titan-text-express-v1/converse', query='', fragment=None), method='POST', fields=Fields(OrderedDict({'content-type': Field(name='Content-Type', value=['application/json'], kind=<FieldPosition.HEADER: 0>), 'content-length': Field(name='Content-Length', value=['98'], kind=<FieldPosition.HEADER: 0>)})))

Copy link
Contributor

Choose a reason for hiding this comment

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

I may need to tweak our reprs for fields and URIs so they're more readable. What we have now isn't great for logging.

context_with_response._transport_response = await config.http_client.send(
request=context_with_response.transport_request,
request_config=request_config,
)
logger.debug("Received HTTP response: %s", context_with_response.transport_response)
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Example:

DEBUG:bedrock_runtime.client:Received HTTP response: HTTPResponse(status=403, fields=Fields(OrderedDict({'date': Field(name='Date', value=['Fri, 28 Feb 2025 18:54:22 GMT'], kind=<FieldPosition.HEADER: 0>), 'content-type': Field(name='Content-Type', value=['application/json'], kind=<FieldPosition.HEADER: 0>), 'content-length': Field(name='Content-Length', value=['42'], kind=<FieldPosition.HEADER: 0>), 'connection': Field(name='Connection', value=['keep-alive'], kind=<FieldPosition.HEADER: 0>), 'x-amzn-requestid': Field(name='x-amzn-RequestId', value=['af2aa5a0-aeae-406b-8082-c131293508e3'], kind=<FieldPosition.HEADER: 0>), 'x-amzn-errortype': Field(name='x-amzn-ErrorType', value=['MissingAuthenticationTokenException:http://internal.amazon.com/coral/com.amazon.coral.service/'], kind=<FieldPosition.HEADER: 0>)})), reason='Forbidden')


""", transportRequest, transportResponse);
}
Expand Down Expand Up @@ -556,7 +575,7 @@ async def _handle_attempt(
interceptor.read_after_deserialization(context_with_output)
except Exception as e:
if context.response is not None:
logger.exception(f"Exception occurred while handling: {context.response}")
logger.exception("Exception occurred while handling: %s", context.response)
pass
context._response = e

Expand All @@ -582,7 +601,7 @@ async def _finalize_attempt(
)
except Exception as e:
if context.response is not None:
logger.exception(f"Exception occurred while handling: {context.response}")
logger.exception("Exception occurred while handling: %s", context.response)
pass
context._response = e

Expand All @@ -592,7 +611,7 @@ async def _finalize_attempt(
interceptor.read_after_attempt(context)
except Exception as e:
if context.response is not None:
logger.exception(f"Exception occurred while handling: {context.response}")
logger.exception("Exception occurred while handling: %s", context.response)
pass
context._response = e

Expand All @@ -613,11 +632,11 @@ async def _finalize_execution(
pass
except Exception as e:
# log and ignore exceptions
logger.exception(f"Exception occurred while dispatching trace events: {e}")
logger.exception("Exception occurred while dispatching trace events: %s", e)
pass
except Exception as e:
if context.response is not None:
logger.exception(f"Exception occurred while handling: {context.response}")
logger.exception("Exception occurred while handling: %s", context.response)
pass
context._response = e

Expand All @@ -627,7 +646,7 @@ async def _finalize_execution(
interceptor.read_after_execution(context)
except Exception as e:
if context.response is not None:
logger.exception(f"Exception occurred while handling: {context.response}")
logger.exception("Exception occurred while handling: %s", context.response)
pass
context._response = e

Expand Down
2 changes: 1 addition & 1 deletion ...re/src/main/java/software/amazon/smithy/python/codegen/generators/StructureGenerator.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -412,7 +412,7 @@ def _consumer(schema: Schema, de: ShapeDeserializer) -> None:
match schema.expect_member_index():
${C|}
case _:
logger.debug(f"Unexpected member schema: {schema}")
logger.debug("Unexpected member schema: %s", schema)

deserializer.read_struct($T, consumer=_consumer)
return kwargs
Expand Down
2 changes: 1 addition & 1 deletion ...n/core/src/main/java/software/amazon/smithy/python/codegen/generators/UnionGenerator.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -162,7 +162,7 @@ def _consumer(self, schema: Schema, de: ShapeDeserializer) -> None:
match schema.expect_member_index():
${4C|}
case _:
logger.debug(f"Unexpected member schema: {schema}")
logger.debug("Unexpected member schema: %s", schema)

def _set_result(self, value: $2T) -> None:
if self._result is not None:
Expand Down
Loading