Fix: Log request body (#6404) #6536
Conversation
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
5 times, most recently
from
f7083d1
to
2246652
Compare
Codecov ReportAttention: Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## develop #6536 +/- ##
===========================================
+ Coverage 85.57% 85.58% +0.01%
===========================================
Files 154 154
Lines 20915 20932 +17
===========================================
+ Hits 17897 17915 +18
+ Misses 3018 3017 -1 ☔ View full report in Codecov by Sentry. 🚨 Try these New Features:
|
src/azul/chalice.py
Outdated
| else: | ||
| if config.debug == 2: |
There was a problem hiding this comment.
| else: | |
| if config.debug == 2: | |
| elif config.debug == 2: |
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
7 times, most recently
from
2395ab7
to
6d3f998
Compare
test/service/test_app_logging.py
Outdated
| def test_request_logs(self): | ||
| for level in INFO, DEBUG: |
There was a problem hiding this comment.
Instead of having two loops for level and azul_debug, how about you only loop over the three values of azul_debug:
def test_request_logs(self):
for azul_debug in (0, 1, 2):
for authenticated in False, True:
for request_body in False, True:
headers = {'authorization': 'Bearer foo_token'} if authenticated else {}
if request_body:
request_body = json.dumps({'filters': json.dumps({'organ': {'is': ['foo']}})})
headers = {
'content-length': str(len(request_body)),
'content-type': 'application/json',
**headers,
}
with mock_patch.object(Config,
'debug',
new=PropertyMock(return_value=azul_debug)):
self._assert_request_logs(authenticated, request_body, headers, azul_debug)
then in _assert_request_logs you can set level based on azul_debug:
level = [INFO, DEBUG, DEBUG][azul_debug]
test/service/test_app_logging.py
Outdated
| @@ -3,15 +3,22 @@ | |||
| DEBUG, | |||
| INFO, | |||
| ) | |||
| from unittest.mock import ( | |||
| PropertyMock, | |||
| patch as mock_patch, | |||
There was a problem hiding this comment.
| patch as mock_patch, | |
| patch, |
What's wrong with patch?
There was a problem hiding this comment.
I felt compelled to denote the mock relationship to patch.
There was a problem hiding this comment.
We don't do that anywhere else and I see no good reason to start now.
src/azul/chalice.py
Outdated
| body = json.dumps(body, cls=self._LogJSONEncoder) | ||
| msg = f' ({len(body)} characters)' | ||
| else: | ||
| msg = f' (first {str(n := 1024)} characters)' |
There was a problem hiding this comment.
| msg = f' (first {str(n := 1024)} characters)' | |
| n = 1024 | |
| msg = f' (first {str(n)} characters)' |
The walrus operator can be useful in an if condition, but here seems unnecessary and the code is easier to read without it.
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
from
0e6add6
to
cd97e59
Compare
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
3 times, most recently
from
cc35a8b
to
730d487
Compare
src/azul/chalice.py
Outdated
| body = self.current_request.json_body | ||
| if body is None: | ||
| len_msg = '' | ||
| elif config.debug == 2: |
There was a problem hiding this comment.
| elif config.debug == 2: | |
| elif config.debug > 1: |
If we ever add a fourth level m we would want this condition to be True there as well.
src/azul/chalice.py
Outdated
| n = 1024 | ||
| len_msg = f' (first {str(n)} characters)' | ||
| body = json_head(n, body) if not isinstance(body, str | bytes) else body[:n] | ||
| log.info('%s', http_body_log_message('request', body, verbatim=True) + len_msg) |
There was a problem hiding this comment.
| log.info('%s', http_body_log_message('request', body, verbatim=True) + len_msg) | |
| log.info(http_body_log_message('request', body, verbatim=True) + len_msg) |
src/azul/chalice.py
Outdated
| len_msg = f' ({len(body)} characters)' | ||
| else: | ||
| n = 1024 | ||
| len_msg = f' (first {str(n)} characters)' |
There was a problem hiding this comment.
| len_msg = f' (first {str(n)} characters)' | |
| len_msg = f' (first {n} characters)' |
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
3 times, most recently
from
2abc349
to
c7030a5
Compare
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
from
c7030a5
to
98b64f4
Compare
|
Re-requesting peer review since previously approved changes were mostly removed. |
src/azul/chalice.py
Outdated
| response.status_code, | ||
| json.dumps(response.headers, cls=self._LogJSONEncoder), | ||
| n, body) | ||
| log.info('With %s body size of %i bytes.', body_type, len(body)) |
There was a problem hiding this comment.
| log.info('With %s body size of %i bytes.', body_type, len(body)) | |
| log.info('… with %s body size of %i bytes.', body_type, len(body)) |
Consider modifying http_body_log_message() so that it can return this message, perhaps by adding a include_body: bool = True parameter. This would keep all the different … with message strings in the same place.
test/service/test_app_logging.py
Outdated
| } | ||
| } | ||
| } | ||
| )[:1024] # … upto the first 1024 characters. |
There was a problem hiding this comment.
| )[:1024] # … upto the first 1024 characters. | |
| ) |
Consider returning the full value here, then slicing at the call sites where a comment won't be necessary since it'll be clear from the nearby log lines why the value is sliced.
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
from
98b64f4
to
0defdbd
Compare
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
achave11-ucsc
force-pushed
the
issues/achave11-ucsc/6404-log-req-body
branch
from
0defdbd
to
1c2f71b
Compare
There was a problem hiding this comment.
Subject: [PATCH] Suppress worrying but harmless and expected terminal output from doctest
---
Index: src/azul/logging.py
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
diff --git a/src/azul/logging.py b/src/azul/logging.py
--- a/src/azul/logging.py (revision 1c2f71bb6de2cb5c12e1467694ec342e952d11a0)
+++ b/src/azul/logging.py (date 1732560462253)
@@ -13,9 +13,6 @@
)
import azul
-from azul import (
- config,
-)
from azul.strings import (
trunc_ellipses,
)
@@ -24,14 +21,11 @@
from azul.chalice import (
AzulChaliceApp,
)
-else:
- class AzulChaliceApp:
- pass
@attr.s(frozen=False, kw_only=False, auto_attribs=True)
class LambdaLogFilter(logging.Filter):
- app: Optional[AzulChaliceApp] = None
+ app: Optional['AzulChaliceApp'] = None
def filter(self, record):
if self.app is None or self.app.lambda_context is None:
@@ -51,7 +45,7 @@
lambda_log_date_format = '%Y-%m-%dT%H:%M:%S'
-def configure_app_logging(app: AzulChaliceApp, *loggers):
+def configure_app_logging(app: 'AzulChaliceApp', *loggers):
_configure_log_levels(app.log, *loggers)
if not app.unit_test:
# Environment is not unit test
@@ -157,7 +151,7 @@
client. If other threads use the ES client concurrently, their logging will
be affected, too.
"""
- if config.debug > 1:
+ if azul.config.debug > 1:
yield
else:
patched_log_level = silent_es_log_level()| json_body = json.loads(request_body) if request_body else None | ||
| response = requests.get(str(url), headers=headers, json=json_body) | ||
| logs = [(r.levelno, r.getMessage()) for r in logs.records] | ||
| last_log_level, last_log = logs.pop() # … to validate separetly. |
There was a problem hiding this comment.
| last_log_level, last_log = logs.pop() # … to validate separetly. | |
| last_log_level, last_log = logs.pop() # to validate separately |
| 'content-type': 'application/json', | ||
| **headers, | ||
| } | ||
| with self.subTest(level=level, |
There was a problem hiding this comment.
The subtests should be labeled with the test cases (in this case the loop variables), not the state derived from them.
| with self.subTest(level=level, | |
| with self.subTest(level=level, |
| @@ -169,6 +175,7 @@ def http_body_log_message(body_type: str, | |||
| body: bytes | bytearray | str | None, | |||
| *, | |||
| verbatim: bool = False, | |||
| size_only: bool = False, | |||
There was a problem hiding this comment.
| size_only: bool = False, | |
| size_only: bool = False |
There was a problem hiding this comment.
I'd rather not add this parameter because its relationship with verbatim is not immediately apparent. Logging the size is cheap so it doesn't need to be conditional. This method is used for ES, AWS and general HTTP requests, too, so I am fine if the size is logged for them as well.
Connected issues: #6404
Checklist
Author
developissues/<GitHub handle of author>/<issue#>-<slug>1 when the issue title describes a problem, the corresponding PR
title is
Fix:followed by the issue titleAuthor (partiality)
ptag to titles of partial commitspartialor completely resolves all connected issuespartiallabelAuthor (chains)
baseor this PR is not chained to another PRchainedor is not chained to another PRAuthor (reindex, API changes)
rtag to commit title or the changes introduced by this PR will not require reindexing of any deploymentreindex:devor the changes introduced by it will not require reindexing ofdevreindex:anvildevor the changes introduced by it will not require reindexing ofanvildevreindex:anvilprodor the changes introduced by it will not require reindexing ofanvilprodreindex:prodor the changes introduced by it will not require reindexing ofprodreindex:partialand its description documents the specific reindexing procedure fordev,anvildev,anvilprodandprodor requires a full reindex or carries none of the labelsreindex:dev,reindex:anvildev,reindex:anvilprodandreindex:prodAPIor this PR does not modify a REST APIa(A) tag to commit title for backwards (in)compatible changes or this PR does not modify a REST APIapp.pyor this PR does not modify a REST APIAuthor (upgrading deployments)
make docker_images.jsonand committed the resulting changes or this PR does not modifyazul_docker_images, or any other variables referenced in the definition of that variableutag to commit title or this PR does not require upgrading deploymentsupgradeor does not require upgrading deploymentsdeploy:sharedor does not modifydocker_images.json, and does not require deploying thesharedcomponent for any other reasondeploy:gitlabor does not require deploying thegitlabcomponentdeploy:runneror does not require deploying therunnerimageAuthor (hotfixes)
Ftag to main commit title or this PR does not include permanent fix for a temporary hotfixanvilprodandprod) have temporary hotfixes for any of the issues connected to this PRAuthor (before every review)
develop, squashed old fixupsmake requirements_updateor this PR does not modifyrequirements*.txt,common.mk,MakefileandDockerfileRtag to commit title or this PR does not modifyrequirements*.txtreqsor does not modifyrequirements*.txtmake integration_testpasses in personal deployment or this PR does not modify functionality that could affect the IT outcomePeer reviewer (after approval)
System administrator (after approval)
demoorno demono demono sandboxN reviewslabel is accurateOperator (before pushing merge the commit)
reindex:…labels andrcommit title tagno demodevelop_select dev.shared && CI_COMMIT_REF_NAME=develop make -C terraform/shared apply_keep_unusedor this PR is not labeleddeploy:shared_select dev.gitlab && CI_COMMIT_REF_NAME=develop make -C terraform/gitlab applyor this PR is not labeleddeploy:gitlab_select anvildev.shared && CI_COMMIT_REF_NAME=develop make -C terraform/shared apply_keep_unusedor this PR is not labeleddeploy:shared_select anvildev.gitlab && CI_COMMIT_REF_NAME=develop make -C terraform/gitlab applyor this PR is not labeleddeploy:gitlabdeploy:gitlabdeploy:gitlabSystem administrator
dev.gitlabare complete or this PR is not labeleddeploy:gitlabanvildev.gitlabare complete or this PR is not labeleddeploy:gitlabOperator (before pushing merge the commit)
_select dev.gitlab && make -C terraform/gitlab/runneror this PR is not labeleddeploy:runner_select anvildev.gitlab && make -C terraform/gitlab/runneror this PR is not labeleddeploy:runnersandboxlabel or PR is labeledno sandboxdevor PR is labeledno sandboxanvildevor PR is labeledno sandboxsandboxdeployment or PR is labeledno sandboxanvilboxdeployment or PR is labeledno sandboxsandboxdeployment or PR is labeledno sandboxanvilboxdeployment or PR is labeledno sandboxsandboxor this PR does not remove catalogs or otherwise causes unreferenced indices indevanvilboxor this PR does not remove catalogs or otherwise causes unreferenced indices inanvildevsandboxor this PR is not labeledreindex:devanvilboxor this PR is not labeledreindex:anvildevsandboxor this PR is not labeledreindex:devanvilboxor this PR is not labeledreindex:anvildevpif the PR is also labeledpartialOperator (chain shortening)
developor this PR is not labeledbasechainedlabel from the blocked PR or this PR is not labeledbasebasebaselabel from this PR or this PR is not labeledbaseOperator (after pushing the merge commit)
devanvildevdevdevanvildevanvildev_select dev.shared && make -C terraform/shared applyor this PR is not labeleddeploy:shared_select anvildev.shared && make -C terraform/shared applyor this PR is not labeleddeploy:shareddevanvildevOperator (reindex)
devor this PR is neither labeledreindex:partialnorreindex:devanvildevor this PR is neither labeledreindex:partialnorreindex:anvildevdevor this PR is neither labeledreindex:partialnorreindex:devanvildevor this PR is neither labeledreindex:partialnorreindex:anvildevdevor this PR is neither labeledreindex:partialnorreindex:devanvildevor this PR is neither labeledreindex:partialnorreindex:anvildevdevor this PR does not require reindexingdevanvildevor this PR does not require reindexinganvildevdevor this PR does not require reindexingdevanvildevor this PR does not require reindexinganvildevdevor this PR does not require reindexingdevanvildevor this PR does not require reindexinganvildevOperator
deploy:shared,deploy:gitlab,deploy:runner,API,reindex:partial,reindex:anvilprodandreindex:prodlabels to the next promotion PRs or this PR carries none of these labelsdeploy:shared,deploy:gitlab,deploy:runner,API,reindex:partial,reindex:anvilprodandreindex:prodlabels, from the description of this PR to that of the next promotion PRs or this PR carries none of these labelsShorthand for review comments
Lline is too longWline wrapping is wrongQbad quotesFother formatting problem