Skip to content

add tracing for handler chain#7908

Merged
thrau merged 1 commit intomasterfrom
trace-handler-chain
Mar 21, 2023
Merged

add tracing for handler chain#7908
thrau merged 1 commit intomasterfrom
trace-handler-chain

Conversation

@thrau
Copy link
Member

@thrau thrau commented Mar 19, 2023 •
edited
Loading

This PR targets localstack developers and adds tracing functionality to debug the handler chain.
I think this can be useful for work that involves a lot of debugging in the HTTP framework (thinking APIGW, S3, CORS, Lambda, issues with request streaming, ...) 👀 @bentsku @alexrashed @calvernaz @dfangl @dominikschubert

You can enable this behavior by setting DEBUG_HANDLER_CHAIN=1

By wrapping handlers and recording before/after state of the context, request, and response object, we can report in quite a detailed way what the handler did to the request/response.
This includes

  • attributes set on the context, like the service or operation
  • which headers where modified
  • whether pesky get_data methods were called on request/response objects

I'm sure there are better/more generic ways of implementing it than the way I did, but I feel for a first iteration it's OK.
Here are some examples of how the report looks like. I know they're not super pretty - happy for suggestions.

calling a non-implemented operation:

=====================================================================================
request:  POST http://localhost:4566/
response: 501
---- request handlers ---------------------------------------------------------------
localstack.aws.handlers.legacy              push_request_context               0.13ms
localstack.aws.handlers.metric_handler      method                             0.08ms
localstack.aws.chain                        CompositeHandler                   0.08ms
localstack.aws.handlers.service             ServiceNameParser                  9.69ms
                                              - set service = 'lightsail'
                                              - modify request headers
                                                - set 'x-localstack-tgt-api: lightsail'
localstack.aws.handlers.cors                CorsEnforcer                       0.10ms
localstack.aws.handlers.codec               ContentDecoder                     0.09ms
localstack.aws.handlers.internal            LocalstackResourceHandler          0.20ms
localstack.aws.handlers.legacy              DefaultListenerHandler             0.08ms
localstack.aws.handlers.legacy              EdgeRouterHandler                  0.11ms
localstack.aws.handlers.auth                MissingAuthHeaderInjector          0.10ms
localstack.aws.handlers.region              RegionContextEnricher              0.43ms
                                              - set region = 'us-east-1'
localstack.aws.handlers.auth                AccountIdEnricher                  0.44ms
                                              - set account_id = '000000000000'
                                              - modify request headers
                                                - set 'x-moto-account-id: 000000000000'
localstack.aws.handlers.internal_requests   InternalRequestParamsEnricher      0.09ms
localstack.aws.handlers.service             ServiceRequestParser               0.57ms
                                              - call request.get_data
                                              - call request._load_form_data
                                              - call request.get_data
                                              - set operation = 'GetBundles'
localstack.aws.handlers.metric_handler      method                             0.09ms
localstack.aws.chain                        CompositeHandler                   0.08ms
localstack.aws.handlers.service_plugin      ServiceLoader                      0.13ms
---- response handlers ---------------------------------------------------------------
localstack.aws.handlers.service             ServiceResponseHandlers            0.09ms
localstack.aws.handlers.service             ServiceResponseParser              0.09ms
localstack.aws.handlers.legacy              set_close_connection_header        0.10ms
                                              - modify response headers
                                                - set 'Connection: close'
localstack.aws.chain                        CompositeResponseHandler           0.09ms
localstack.aws.handlers.cors                CorsResponseEnricher               0.26ms
                                              - modify response headers
                                                - set 'Access-Control-Allow-Methods: HEAD,GET,PUT,POST,DELETE,OPTIONS,PATCH'
                                                - set 'Access-Control-Allow-Origin: *'
                                                - set 'Access-Control-Expose-Headers: etag,x-amz-version-id'
                                                - set 'Access-Control-Allow-Headers: authorization,cache-control,content-length,content-md5,content-type,etag,location,x-amz-acl,x-amz-content-sha256,x-amz-date,x-amz-request-id,x-amz-security-token,x-amz-tagging,x-amz-target,x-amz-user-agent,x-amz-version-id,x-amzn-requestid,x-localstack-target,amz-sdk-invocation-id,amz-sdk-request'
localstack.aws.handlers.logging             ResponseLogger                     0.29ms
localstack.aws.handlers.analytics           ServiceRequestCounter              0.66ms
localstack.aws.handlers.legacy              pop_request_context                0.13ms
localstack.aws.handlers.metric_handler      method                             0.11ms
---- exception handlers ---------------------------------------------------------------
localstack.aws.handlers.logging             ExceptionLogger                    0.70ms
localstack.aws.handlers.service             ServiceExceptionSerializer         5.00ms
                                              - set response stats_code = 501
                                              - modify response headers
                                                - set 'Content-Length: 220'
                                                - set 'x-amzn-requestid: OU72LH39VYZ3NUXXBGQNBONTIELQN10G783JHGP2JW46Q78DLE37'
                                                - set 'X-Amzn-Errortype: InternalFailure'
                                                - set 'Content-Type: application/json'
localstack.aws.handlers.fallback            InternalFailureHandler             0.14ms
==================================================================== total    21.37ms

calling awslocal opensearch list-domain-names

=====================================================================================
request:  GET http://localhost:4566/2021-01-01/domain
response: 200
---- request handlers ---------------------------------------------------------------
localstack.aws.handlers.legacy              push_request_context               0.19ms
localstack.aws.handlers.metric_handler      method                             0.09ms
localstack.aws.chain                        CompositeHandler                   0.06ms
localstack.aws.handlers.service             ServiceNameParser                  1.68ms
                                              - set service = 'opensearch'
                                              - modify request headers
                                                - set 'x-localstack-tgt-api: opensearch'
localstack.aws.handlers.cors                CorsEnforcer                       0.09ms
localstack.aws.handlers.codec               ContentDecoder                     0.08ms
localstack.aws.handlers.internal            LocalstackResourceHandler          0.13ms
localstack.aws.handlers.legacy              DefaultListenerHandler             0.07ms
localstack.aws.handlers.legacy              EdgeRouterHandler                  0.08ms
localstack.aws.handlers.auth                MissingAuthHeaderInjector          0.07ms
localstack.aws.handlers.region              RegionContextEnricher              0.09ms
                                              - set region = 'us-east-1'
localstack.aws.handlers.auth                AccountIdEnricher                  0.09ms
                                              - set account_id = '000000000000'
                                              - modify request headers
                                                - set 'x-moto-account-id: 000000000000'
localstack.aws.handlers.internal_requests   InternalRequestParamsEnricher      0.07ms
localstack.aws.handlers.service             ServiceRequestParser              55.38ms
                                              - call request.get_data
                                              - call request._load_form_data
                                              - set operation = 'ListDomainNames'
localstack.aws.handlers.metric_handler      method                             0.09ms
localstack.aws.chain                        CompositeHandler                   0.07ms
localstack.aws.handlers.service_plugin      ServiceLoader                     57.39ms
localstack.aws.handlers.service             ServiceRequestRouter             116.85ms
                                              - set service_response
                                              - modify response headers
                                                - set 'x-amz-request-id: OP0F0433URHYVS47YDAN1RCGNSZS3XBYXICYAG056R738O6Q2LJP'
                                                - set 'Content-Length: 19'
                                                - set 'x-amzn-requestid: KC0F54NE4YMTBHGW35N7UUECL0WPI0N8Q2TDF9DTLK55JEX1Y1DM'
localstack.aws.handlers.fallback            EmptyResponseHandler               0.10ms
---- response handlers ---------------------------------------------------------------
localstack.aws.handlers.service             ServiceResponseHandlers            0.08ms
localstack.aws.handlers.service             ServiceResponseParser              0.08ms
localstack.aws.handlers.legacy              set_close_connection_header        0.09ms
                                              - modify response headers
                                                - set 'Connection: close'
localstack.aws.chain                        CompositeResponseHandler           0.08ms
localstack.aws.handlers.cors                CorsResponseEnricher               0.15ms
                                              - modify response headers
                                                - set 'Access-Control-Allow-Methods: HEAD,GET,PUT,POST,DELETE,OPTIONS,PATCH'
                                                - set 'Access-Control-Allow-Origin: *'
                                                - set 'Access-Control-Expose-Headers: etag,x-amz-version-id'
                                                - set 'Access-Control-Allow-Headers: authorization,cache-control,content-length,content-md5,content-type,etag,location,x-amz-acl,x-amz-content-sha256,x-amz-date,x-amz-request-id,x-amz-security-token,x-amz-tagging,x-amz-target,x-amz-user-agent,x-amz-version-id,x-amzn-requestid,x-localstack-target,amz-sdk-invocation-id,amz-sdk-request'
localstack.aws.handlers.logging             ResponseLogger                     0.26ms
localstack.aws.handlers.analytics           ServiceRequestCounter              0.12ms
localstack.aws.handlers.legacy              pop_request_context                0.13ms
localstack.aws.handlers.metric_handler      method                             0.11ms
---- exception handlers ---------------------------------------------------------------
==================================================================== total   234.82ms

calling the health endpoint

=====================================================================================
request:  GET http://localhost:4566/_localstack/health
response: 200
---- request handlers ---------------------------------------------------------------
localstack.aws.handlers.legacy              push_request_context               0.11ms
localstack.aws.handlers.metric_handler      method                             0.07ms
localstack.aws.chain                        CompositeHandler                   0.05ms
localstack.aws.handlers.service             ServiceNameParser                  0.58ms
localstack.aws.handlers.cors                CorsEnforcer                       0.07ms
localstack.aws.handlers.codec               ContentDecoder                     0.06ms
localstack.aws.handlers.internal            LocalstackResourceHandler          1.63ms
                                              - stop chain
                                              - modify response headers
                                                - set 'Content-Length: 872'
                                                - set 'Content-Type: application/json'
---- response handlers ---------------------------------------------------------------
localstack.aws.handlers.service             ServiceResponseHandlers            0.06ms
localstack.aws.handlers.service             ServiceResponseParser              0.06ms
localstack.aws.handlers.legacy              set_close_connection_header        0.07ms
                                              - modify response headers
                                                - set 'Connection: close'
localstack.aws.chain                        CompositeResponseHandler           0.06ms
localstack.aws.handlers.cors                CorsResponseEnricher               0.12ms
                                              - modify response headers
                                                - set 'Access-Control-Allow-Methods: HEAD,GET,PUT,POST,DELETE,OPTIONS,PATCH'
                                                - set 'Access-Control-Allow-Origin: *'
                                                - set 'Access-Control-Expose-Headers: etag,x-amz-version-id'
                                                - set 'Access-Control-Allow-Headers: authorization,cache-control,content-length,content-md5,content-type,etag,location,x-amz-acl,x-amz-content-sha256,x-amz-date,x-amz-request-id,x-amz-security-token,x-amz-tagging,x-amz-target,x-amz-user-agent,x-amz-version-id,x-amzn-requestid,x-localstack-target,amz-sdk-invocation-id,amz-sdk-request'
localstack.aws.handlers.logging             ResponseLogger                     0.07ms
localstack.aws.handlers.analytics           ServiceRequestCounter              0.07ms
localstack.aws.handlers.legacy              pop_request_context                0.08ms
localstack.aws.handlers.metric_handler      method                             0.07ms
---- exception handlers ---------------------------------------------------------------
==================================================================== total     3.78ms

@thrau thrau requested a review from bentsku March 19, 2023 16:26
@thrau thrau temporarily deployed to localstack-ext-tests March 19, 2023 16:26 — with GitHub Actions Inactive
@coveralls
Copy link

coveralls commented Mar 19, 2023

Coverage Status

Coverage: 84.933% (-0.2%) from 85.121% when pulling 42efe6c on trace-handler-chain into 5949082 on master.

@github-actions
Copy link

github-actions bot commented Mar 19, 2023

LocalStack integration with Pro

       3 files  ±0         3 suites  ±0   1h 35m 29s ⏱️ + 2m 58s
1 814 tests ±0  1 430 ✔️ +1  384 💤  - 1  0 ❌ ±0 
2 532 runs  ±0  1 796 ✔️ +1  736 💤  - 1  0 ❌ ±0 

Results for commit 42efe6c. ± Comparison against base commit 5949082.

bentsku
bentsku approved these changes Mar 21, 2023
View reviewed changes
Copy link
Contributor

@bentsku bentsku left a comment

Choose a reason for hiding this comment

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

This is really awesome! I can really see us making use of this to debug.

I've had to wrangle with the handler chain before, and I remember setting print statement in each handler where I thought the issue was. I know, I could have also used the debugger, but I had to read a stream and I didn't know where it was consumed and was trying to consume it manually .The debugger didn't like showing the stream either (I think there's some issue there with pyCharm). Anyway, this is sidetracking, but it's exactly why this would be really useful.

Tracking each handler individually is really nice, that be for performance, consuming a stream, or any other issue we can encounter. So, thanks a lot for adding this functionality, I can see myself using it in the weeks coming.

Actually, I can see us using it pretty soon: we have an issue in CI where the body of an S3 pre-signed URL is consumed, but only in CI. We could set up a branch with a circleCI job with this feature enabled, running on some selected failing tests and see what exactly is happening. This is really awesome, I can't say it enough.

So, yeah, L(Super)GTM.

@thrau thrau merged commit f141482 into master Mar 21, 2023
@thrau thrau deleted the trace-handler-chain branch March 21, 2023 10:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@bentsku bentsku bentsku approved these changes

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

3 participants

@thrau @coveralls @bentsku