8000 Fix KeyError in log format for requests without AWS context by viren-nadkarni · Pull Request #9132 · localstack/localstack · GitHub
[go: up one dir, main page]
Skip to content

Fix KeyError in log format for requests without AWS context #9132

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

Jump to bottom
Merged
merged 1 commit into from
Sep 13, 2023
Merged

Fix KeyError in log format for requests without AWS context #9132

merged 1 commit into from
Sep 13, 2023

Conversation

viren-nadkarni
Copy link
Member

Motivation

With #9084, logs contain the account ID and region from the request context when trace logging is enabled.

However, not all HTTP requests have an AWS context, a la ones made to the health endpoint /_localstack/health or stack info /_localstack/stackinfo.

This was caused following:

localstack_main  | 2023-09-13T07:59:32.703 DEBUG --- [   asgi_gw_1] l.aws.serving.wsgi         : GET localhost.localstack.cloud:4566/_localstack/health
localstack_main  | 2023-09-13T07:59:32.712 DEBUG --- [   asgi_gw_0] l.aws.serving.wsgi         : GET localhost.localstack.cloud:4566/_localstack/stackinfo
localstack_main  | --- Logging error ---
localstack_main  | Traceback (most recent call last):
localstack_main  |   File "/usr/local/lib/python3.10/logging/__init__.py", line 440, in format
localstack_main  |     return self._format(record)
localstack_main  |   File "/usr/local/lib/python3.10/logging/__init__.py", line 436, in _format
localstack_main  |     return self._fmt % values
localstack_main  | KeyError: 'account_id'
localstack_main  |
localstack_main  | During handling of the above exception, another exception occurred:
localstack_main  |
localstack_main  | Traceback (most recent call last):
localstack_main  |   File "/usr/local/lib/python3.10/logging/__init__.py", line 1100, in emit
localstack_main  |     msg = self.format(record)
localstack_main  |   File "/usr/local/lib/python3.10/logging/__init__.py", line 943, in format
localstack_main  |     return fmt.format(record)
localstack_main  |   File "/usr/local/lib/python3.10/logging/__init__.py", line 681, in format
localstack_main  |     s = self.formatMessage(record)
localstack_main  |   File "/usr/local/lib/python3.10/logging/__init__.py", line 650, in formatMessage
localstack_main  |     return self._style.format(record)
localstack_main  |   File "/usr/local/lib/python3.10/logging/__init__.py", line 442, in format
localstack_main  |     raise ValueError('Formatting field not found in record: %s' % e)
localstack_main  | ValueError: Formatting field not found in record: 'account_id'
localstack_main  | Call stack:
localstack_main  |   File "/usr/local/lib/python3.10/threading.py", line 973, in _bootstrap
localstack_main  |     self._bootstrap_inner()
localstack_main  |   File "/usr/local/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
localstack_main  |     self.run()
localstack_main  |   File "/usr/local/lib/python3.10/threading.py", line 953, in run
localstack_main  |     self._target(*self._args, **self._kwargs)
localstack_main  |   File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83, in _worker
localstack_main  |     work_item.run()
localstack_main  |   File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
localstack_main  |     result = self.fn(*self.args, **self.kwargs)
localstack_main  |   File "/opt/code/localstack/.venv/lib/python3.10/site-packages/localstack/aws/serving/wsgi.py", line 50, in __call__
localstack_main  |     self.gateway.process(request, response)
localstack_main  |   File "/opt/code/localstack/.venv/lib/python3.10/site-packages/localstack/aws/gateway.py", line 37, in process
localstack_main  |     chain.handle(context, response)
localstack_main  |   File "/opt/code/localstack/.venv/lib/python3.10/site-packages/localstack/aws/chain.py", line 110, in handle
localstack_main  |     self._call_response_handlers(response)
localstack_main  |   File "/opt/code/localstack/.venv/lib/python3.10/site-packages/localstack/aws/chain.py", line 155, in _call_response_handlers
localstack_main  |     handler(self, self.context, response)
localstack_main  |   File "/opt/code/localstack/.venv/lib/python3.10/site-packages/localstack/aws/handlers/logging.py", line 47, in __call__
localstack_main  |     self._log(context, response)
localstack_main  |   File "/opt/code/localstack/.venv/lib/python3.10/site-packages/localstack/aws/handlers/logging.py", line 142, in _log
localstack_main  |     http_logger.info(
localstack_main  | Message: '%s %s => %d'
localstack_main  | Arguments: ('GET', '/_localstack/stackinfo', 200)

Implementation

This PR adjusts the log formatters so that the account ID and region is only included for requests with AWS context. Now,

Requests with an AWS context produce:

2023-09-13T14:31:11.096  INFO --- [   asgi_gw_0] localstack.request.aws     : AWS ec2.DescribeInstances => 200; 000000000000/eu-central-1; DescribeInstancesRequest({}, headers={'Host': 'localhost:4566', 'Accept-Encoding': 'identity', 'Content-Type': 'application/x-www-form-urlencoded; charset=utf-8', 'User-Agent': 'aws-cli/2.11.9 Python/3.11.2 Linux/6.2.0-32-generic exe/x86_64.neon.22 prompt/off command/ec2.describe-instances', 'X-Amz-Date': '20230913T090110Z', 'Authorization': 'AWS4-HMAC-SHA256 Credential=000000000000/20230913/eu-central-1/ec2/aws4_request, SignedHeaders=content-type;host;x-amz-date, Signature=f2af98c96887b4a619c5241f1f4249eb6b3b35f41fec0dced7b0d427512bdffd', 'Content-Length': '43', 'x-localstack-tgt-api': 'ec2', 'x-moto-account-id': '000000000000'}); DescribeInstancesResult({'Reservations': []}, headers={'Content-Type': 'text/xml', 'Content-Length': '219', 'Connection': 'close', 'Access-Control-Allow-Origin': '*', 'Access-Control-Allow-Methods': 'HEAD,GET,PUT,POST,DELETE,OPTIONS,PATCH', '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', 'Access-Control-Expose-Headers': 'etag,x-amz-version-id'})

All other requests produce:

2023-09-13T14:31:03.774  INFO --- [   asgi_gw_0] localstack.request.http    : GET /_localstack/stackinfo => 404; Request(b'', headers={'Host': 'localhost.localstack.cloud:4566', 'User-Agent': 'curl/7.81.0', 'Accept': '*/*'}); Response(b'', headers={'Content-Type': 'text/plain; charset=utf-8', 'Connection': 'close', 'Access-Control-Allow-Origin': '*', 'Access-Control-Allow-Methods': 'HEAD,GET,PUT,POST,DELETE,OPTIONS,PATCH', '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', 'Access-Control-Expose-Headers': 'etag,x-amz-version-id'})

2023-09-13T14:31:07.755 DEBUG --- [   asgi_gw_0] l.aws.serving.wsgi         : GET localhost.localstack.cloud:4566/_localstack/health

@viren-nadkarni viren-nadkarni self-assigned this Sep 13, 2023
@viren-nadkarni viren-nadkarni marked this pull request as ready for review September 13, 2023 09:12
@viren-nadkarni viren-nadkarni added the semver: patch Non-breaking changes which can be included in patch releases label Sep 13, 2023
@coveralls
Copy link

Coverage Status

coverage: 79.841% (-0.02%) from 79.862% when pulling 53cb0f6 on trace-logging-fmt into b93486d on master.

@github-actions
Copy link

LocalStack Community integration with Pro

       2 files         2 suites   1h 12m 18s ⏱️
2 199 tests 1 705 ✔️ 494 💤 0 ❌
2 200 runs  1 705 ✔️ 495 💤 0 ❌

Results for commit 53cb0f6.

alexrashed
alexrashed approved these changes Sep 13, 2023
View reviewed changes
Copy link
Member
@alexrashed alexrashed left a comment

Choose a reason for hiding this comment

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

Thanks for jumping on this! 🦸🏽 💯

@alexrashed alexrashed merged commit adefae0 into master Sep 13, 2023
@alexrashed alexrashed deleted the trace-logging-fmt branch September 13, 2023 11:52
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@alexrashed alexrashed alexrashed approved these changes

@thrau thrau Awaiting requested review from thrau

Assignees

@viren-nadkarni viren-nadkarni

Labels
semver: patch Non-breaking changes which can be included in patch releases
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@viren-nadkarni @coveralls @alexrashed
0