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.

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

New debug log approach and fix logging setup #168

Merged
merged 8 commits into from
Nov 10, 2023
Merged

New debug log approach and fix logging setup #168

merged 8 commits into from
Nov 10, 2023

Conversation

mullermp
Copy link
Contributor

@mullermp mullermp commented Nov 9, 2023

Log level should be removed - it was previously for configuring the level that the SDK spits out.
Logger defaults to null.
Add better debug logging to middleware and a module to handle it.

I did not add error/info logging for the entire request - thoughts? This can be added later.

Example logging:

irb(main):001:0> HighScoreService::Client.new(endpoint: 'http://127.0.0.1:3000', logger: Logger.new($stdout)).get_high_score(id: '1')
D, [2023-11-09T16:12:59.951385 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Initialize] Initializing request
D, [2023-11-09T16:12:59.951471 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Validate] Validating input with: #<struct HighScoreService::Types::GetHighScoreInput id="1">
D, [2023-11-09T16:12:59.951511 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Validate] Validated input
D, [2023-11-09T16:12:59.951549 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Build] Building request with: #<struct HighScoreService::Types::GetHighScoreInput id="1">
D, [2023-11-09T16:12:59.951664 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Build] Built request: #<Hearth::HTTP::Request:0x000000011215f1e0 @uri=#<URI::HTTP http://127.0.0.1:3000/high_scores/1>, @body=#<StringIO:0x0000000111c353b8>, @http_method="GET", @fields=#<Hearth::HTTP::Fields:0x0000000111c35638 @encoding="utf-8">, @headers={}, @trailers={}>
D, [2023-11-09T16:12:59.951713 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::HTTP::Middleware::ContentLength] Set Content-Length to 0
D, [2023-11-09T16:12:59.951754 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Retry] Starting retry loop with token: #<struct Hearth::Retry::Token retry_count=0, retry_delay=nil>
D, [2023-11-09T16:12:59.951790 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Retry] Attempting request in retry loop
D, [2023-11-09T16:12:59.951811 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Auth] Resolving auth
D, [2023-11-09T16:12:59.951888 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Auth] Resolved auth options: [#<Hearth::AuthOption:0x0000000111c12200 @scheme_id="smithy.api#noAuth", @identity_properties={}, @signer_properties={}>]
D, [2023-11-09T16:12:59.951989 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Auth] Resolved auth: #<struct Hearth::Middleware::Auth::ResolvedAuth signer=#<Hearth::Signers::Anonymous:0x0000000112864670>, signer_properties={}, identity=#<Hearth::Identities::Anonymous:0x0000000111c10fb8 @expiration=nil>, identity_properties={}>
D, [2023-11-09T16:12:59.952055 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Sign] Signing request with: #<Hearth::Signers::Anonymous:0x0000000112864670>
D, [2023-11-09T16:12:59.952155 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Sign] Signed request: #<Hearth::HTTP::Request:0x000000011215f1e0 @uri=#<URI::HTTP http://127.0.0.1:3000/high_scores/1>, @body=#<StringIO:0x0000000111c353b8>, @http_method="GET", @fields=#<Hearth::HTTP::Fields:0x0000000111c35638 @encoding="utf-8">, @headers={"Content-Length"=>"0"}, @trailers={}>
D, [2023-11-09T16:12:59.952247 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Send] Sending request: #<Hearth::HTTP::Request:0x000000011215f1e0 @uri=#<URI::HTTP http://127.0.0.1:3000/high_scores/1>, @body=#<StringIO:0x0000000111c353b8>, @http_method="GET", @fields=#<Hearth::HTTP::Fields:0x0000000111c35638 @encoding="utf-8">, @headers={"Content-Length"=>"0"}, @trailers={}>
D, [2023-11-09T16:13:00.087678 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Send] Received response: #<Hearth::HTTP::Response:0x000000011215f190 @body=#<StringIO:0x0000000111c3edf0>, @status=200, @reason=nil, @fields=#<Hearth::HTTP::Fields:0x0000000111c34ff8 @encoding="utf-8">, @headers={"x-frame-options"=>"SAMEORIGIN", "x-xss-protection"=>"1; mode=block", "x-content-type-options"=>"nosniff", "x-download-options"=>"noopen", "x-permitted-cross-domain-policies"=>"none", "referrer-policy"=>"strict-origin-when-cross-origin", "content-type"=>"application/json; charset=utf-8", "vary"=>"Accept", "etag"=>"W/\"9a54e72eaccbc6e925bb43bda212b52e\"", "cache-control"=>"max-age=0, private, must-revalidate", "x-request-id"=>"a1e07357-0e53-483c-bc6d-8df80dc9ad2a", "x-runtime"=>"0.123711", "transfer-encoding"=>"chunked"}, @trailers={}>
D, [2023-11-09T16:13:00.089021 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Parse] Parsed data: #<struct HighScoreService::Types::GetHighScoreOutput high_score=#<struct HighScoreService::Types::HighScoreAttributes id=1, game="Frogger", score=9001, created_at=2021-12-07 01:43:34.566 UTC, updated_at=2021-12-07 01:43:34.566 UTC>>
D, [2023-11-09T16:13:00.089066 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Retry] Request succeeded
D, [2023-11-09T16:13:00.089083 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Retry] Finished retry loop
D, [2023-11-09T16:13:00.089095 #69585] DEBUG -- : [eee032ea-47b2-4cb3-9bc9-fd6d908d8835] [Hearth::Middleware::Initialize] Finished request
=> 
#<Hearth::Output:0x0000000111b3d938
 @data=
  #<struct HighScoreService::Types::GetHighScoreOutput
   high_score=#<struct HighScoreService::Types::HighScoreAttributes id=1, game="Frogger", score=9001, created_at=2021-12-07 01:43:34.566 UTC, updated_at=2021-12-07 01:43:34.566 UTC>>,
 @error=nil,
 @metadata={:request_id=>"a1e07357-0e53-483c-bc6d-8df80dc9ad2a"}>

@mullermp mullermp requested review from alextwoods and jterapin and removed request for alextwoods November 9, 2023 21:12
Copy link
Contributor

@alextwoods alextwoods left a comment

Choose a reason for hiding this comment

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

Nice - Looks good!

I think for adding info/error - it probably makes sense to do so either in the initialize middleware (ie, very last) or completly outside of middleware in the client operation method, right before the error is raised. If error, log error. else, log info of the invocation.

But agree those can be added later.

hearth/lib/hearth/middleware.rb Show resolved Hide resolved
@mullermp mullermp merged commit 4e176aa into main Nov 10, 2023
20 checks passed
@mullermp mullermp deleted the better-logging branch November 10, 2023 18:01
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants