Fix: Log request body (#6404) #6536

achave11-ucsc · 2024-08-31T01:10:01Z

Connected issues: #6404

Checklist

Author

PR is a draft
Target branch is develop
Name of PR branch matches issues/<GitHub handle of author>/<issue#>-<slug>
On ZenHub, PR is connected to all issues it (partially) resolves
PR description links to connected issues
PR title matches¹ that of a connected issue _{or comment in PR explains why they're different}
PR title references all connected issues
For each connected issue, there is at least one commit whose title references that issue

¹ when the issue title describes a problem, the corresponding PR
title is Fix: followed by the issue title

Author (partiality)

Added p tag to titles of partial commits
This PR is labeled partial _{or completely resolves all connected issues}
This PR partially resolves each of the connected issues _{or does not have the partial label}

Author (chains)

This PR is blocked by previous PR in the chain _{or is not chained to another PR}
The blocking PR is labeled base _{or this PR is not chained to another PR}
This PR is labeled chained _{or is not chained to another PR}

Author (reindex, API changes)

Added r tag to commit title _{or the changes introduced by this PR will not require reindexing of any deployment}
This PR is labeled reindex:dev _{or the changes introduced by it will not require reindexing of dev}
This PR is labeled reindex:anvildev _{or the changes introduced by it will not require reindexing of anvildev}
This PR is labeled reindex:anvilprod _{or the changes introduced by it will not require reindexing of anvilprod}
This PR is labeled reindex:prod _{or the changes introduced by it will not require reindexing of prod}
This PR is labeled reindex:partial and its description documents the specific reindexing procedure for dev, anvildev, anvilprod and prod _{or requires a full reindex or carries none of the labels reindex:dev, reindex:anvildev, reindex:anvilprod and reindex:prod}
This PR and its connected issues are labeled API _{or this PR does not modify a REST API}
Added a (A) tag to commit title for backwards (in)compatible changes _{or this PR does not modify a REST API}
Updated REST API version number in app.py _{or this PR does not modify a REST API}

Author (upgrading deployments)

Ran make docker_images.json and committed the resulting changes _{or this PR does not modify azul_docker_images, or any other variables referenced in the definition of that variable}
Documented upgrading of deployments in UPGRADING.rst _{or this PR does not require upgrading deployments}
Added u tag to commit title _{or this PR does not require upgrading deployments}
This PR is labeled upgrade _{or does not require upgrading deployments}
This PR is labeled deploy:shared _{or does not modify docker_images.json, and does not require deploying the shared component for any other reason}
This PR is labeled deploy:gitlab _{or does not require deploying the gitlab component}
This PR is labeled deploy:runner _{or does not require deploying the runner image}

Author (hotfixes)

Added F tag to main commit title _{or this PR does not include permanent fix for a temporary hotfix}
Reverted the temporary hotfixes for any connected issues _{or the none of the stable branches (anvilprod and prod) have temporary hotfixes for any of the issues connected to this PR}

Author (before every review)

Rebased PR branch on develop, squashed old fixups
Ran make requirements_update _{or this PR does not modify requirements*.txt, common.mk, Makefile and Dockerfile}
Added R tag to commit title _{or this PR does not modify requirements*.txt}
This PR is labeled reqs _{or does not modify requirements*.txt}
make integration_test passes in personal deployment _{or this PR does not modify functionality that could affect the IT outcome}

Peer reviewer (after approval)

PR is not a draft
Ticket is in Review requested column
PR is awaiting requested review from system administrator
PR is assigned to only the system administrator

System administrator (after approval)

Actually approved the PR
Labeled connected issues as demo or no demo
Commented on connected issues about demo expectations _{or all connected issues are labeled no demo}
Decided if PR can be labeled no sandbox
A comment to this PR details the completed security design review
PR title is appropriate as title of merge commit
N reviews label is accurate
Moved connected issues to Approved column
PR is assigned to only the operator

Operator (before pushing merge the commit)

System administrator

Background migrations for dev.gitlab are complete _{or this PR is not labeled deploy:gitlab}
Background migrations for anvildev.gitlab are complete _{or this PR is not labeled deploy:gitlab}
PR is assigned to only the operator

Operator (before pushing merge the commit)

Operator (chain shortening)

Changed the target branch of the blocked PR to develop _{or this PR is not labeled base}
Removed the chained label from the blocked PR _{or this PR is not labeled base}
Removed the blocking relationship from the blocked PR _{or this PR is not labeled base}
Removed the base label from this PR _{or this PR is not labeled base}

Operator (after pushing the merge commit)

Operator (reindex)

Operator

Propagated the deploy:shared, deploy:gitlab, deploy:runner, API, reindex:partial, reindex:anvilprod and reindex:prod labels to the next promotion PRs _{or this PR carries none of these labels}
Propagated any specific instructions related to the deploy:shared, deploy:gitlab, deploy:runner, API, reindex:partial, reindex:anvilprod and reindex:prod labels, from the description of this PR to that of the next promotion PRs _{or this PR carries none of these labels}
PR is assigned to no one

Shorthand for review comments

L line is too long
W line wrapping is wrong
Q bad quotes
F other formatting problem

codecov · 2024-10-01T21:22:50Z

Codecov Report

Attention: Patch coverage is 97.87234% with 2 lines in your changes missing coverage. Please review.

Project coverage is 85.58%. Comparing base (93637ff) to head (1c2f71b).

Files with missing lines	Patch %	Lines
src/azul/logging.py	87.50%	1 Missing ⚠️
test/service/test_app_logging.py	98.50%	1 Missing ⚠️

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.
📢 Have feedback on the report? Share it here.

🚨 Try these New Features:

Flaky Tests Detection - Detect and resolve failed and flaky tests
JS Bundle Analysis - Avoid shipping oversized bundles

coveralls · 2024-10-01T21:23:15Z

coverage: 85.621% (+0.03%) from 85.587%
when pulling 1c2f71b on issues/achave11-ucsc/6404-log-req-body
into 93637ff on develop.

dsotirho-ucsc

Currently the logging tests only cover GET requests. Consider adding a logging test of a PUT or POST request with a body. Maybe this can be done in IT when a manifest request is made, or against a dummy endpoint like in TestAppLogging.test

dsotirho-ucsc · 2024-10-02T16:39:59Z

src/azul/chalice.py

+            else:
+                if config.debug == 2:


Suggested change

else:

if config.debug == 2:

elif config.debug == 2:

test/service/test_app_logging.py

dsotirho-ucsc · 2024-10-17T21:53:41Z

test/service/test_app_logging.py

    def test_request_logs(self):
        for level in INFO, DEBUG:


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]

Great idea, ty!

dsotirho-ucsc · 2024-10-17T22:03:39Z

test/service/test_app_logging.py

@@ -3,15 +3,22 @@
    DEBUG,
    INFO,
 )
+from unittest.mock import (
+    PropertyMock,
+    patch as mock_patch,


Suggested change

patch as mock_patch,

patch,

What's wrong with patch?

I felt compelled to denote the mock relationship to patch.

We don't do that anywhere else and I see no good reason to start now.

dsotirho-ucsc · 2024-10-17T22:27:31Z

src/azul/chalice.py

+                body = json.dumps(body, cls=self._LogJSONEncoder)
+                msg = f' ({len(body)} characters)'
+            else:
+                msg = f' (first {str(n := 1024)} characters)'


Suggested change

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.

dsotirho-ucsc

Approved.

hannes-ucsc

We should discuss in PL how we can match up the different levels of detail logged at which log level for the request and response. Currently these two methods look worryingly dissimilar.

hannes-ucsc · 2024-11-02T07:33:23Z

src/azul/chalice.py

+            body = self.current_request.json_body
+            if body is None:
+                len_msg = ''
+            elif config.debug == 2:


Suggested change

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.

hannes-ucsc · 2024-11-02T07:38:00Z

src/azul/chalice.py

+                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)


Suggested change

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)

hannes-ucsc · 2024-11-02T07:43:52Z

src/azul/chalice.py

+                len_msg = f' ({len(body)} characters)'
+            else:
+                n = 1024
+                len_msg = f' (first {str(n)} characters)'


Suggested change

len_msg = f' (first {str(n)} characters)'

len_msg = f' (first {n} characters)'

achave11-ucsc · 2024-11-20T19:27:44Z

Re-requesting peer review since previously approved changes were mostly removed.

dsotirho-ucsc · 2024-11-20T21:22:07Z

src/azul/chalice.py

-                      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))


Suggested change

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.

dsotirho-ucsc · 2024-11-20T21:36:36Z

test/service/test_app_logging.py

+                    }
+                }
+            }
+        )[:1024]  # … upto the first 1024 characters.


Suggested change

)[: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 · 2024-11-21T18:24:08Z

src/azul/chalice.py

-    json_head,
+)
+from azul.logging import (
+    http_body_log_message,


@dsotirho-ucsc, note this is likely a false positive finding.

dsotirho-ucsc

Approved.

github-actions bot added the orange [process] Done by the Azul team label Aug 31, 2024

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch 5 times, most recently from f7083d1 to 2246652 Compare October 1, 2024 21:01

achave11-ucsc requested a review from dsotirho-ucsc October 1, 2024 23:38

achave11-ucsc assigned dsotirho-ucsc Oct 1, 2024

dsotirho-ucsc requested changes Oct 2, 2024

View reviewed changes

dsotirho-ucsc removed their assignment Oct 2, 2024

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch 7 times, most recently from 2395ab7 to 6d3f998 Compare October 17, 2024 07:24

achave11-ucsc requested a review from dsotirho-ucsc October 17, 2024 15:26

achave11-ucsc assigned dsotirho-ucsc Oct 17, 2024

dsotirho-ucsc requested changes Oct 17, 2024

View reviewed changes

dsotirho-ucsc removed their assignment Oct 17, 2024

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch from 0e6add6 to cd97e59 Compare October 18, 2024 20:03

achave11-ucsc requested a review from dsotirho-ucsc October 18, 2024 20:28

achave11-ucsc assigned dsotirho-ucsc Oct 18, 2024

dsotirho-ucsc previously approved these changes Oct 21, 2024

View reviewed changes

dsotirho-ucsc marked this pull request as ready for review October 21, 2024 16:39

dsotirho-ucsc requested a review from hannes-ucsc as a code owner October 21, 2024 16:39

dsotirho-ucsc assigned hannes-ucsc Oct 21, 2024

hannes-ucsc removed their assignment Oct 29, 2024

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch 4 times, most recently from cc35a8b to 730d487 Compare October 31, 2024 18:10

achave11-ucsc requested a review from hannes-ucsc November 1, 2024 17:23

achave11-ucsc assigned hannes-ucsc Nov 1, 2024

hannes-ucsc requested changes Nov 2, 2024

View reviewed changes

hannes-ucsc removed their assignment Nov 2, 2024

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch 3 times, most recently from 2abc349 to c7030a5 Compare November 20, 2024 18:17

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch from c7030a5 to 98b64f4 Compare November 20, 2024 19:00

achave11-ucsc requested a review from dsotirho-ucsc November 20, 2024 19:26

achave11-ucsc assigned dsotirho-ucsc Nov 20, 2024

dsotirho-ucsc requested changes Nov 20, 2024

View reviewed changes

dsotirho-ucsc removed their assignment Nov 20, 2024

achave11-ucsc added 3 commits November 21, 2024 09:29

Refactor AzulChaliceApp request and response logging

7b21626

Tests, Fix: Log request body (#6404)

534c585

Fix: Log request body (#6404)

ecf4d2b

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch from 98b64f4 to 0defdbd Compare November 21, 2024 17:30

github-advanced-security bot found potential problems Nov 21, 2024

View reviewed changes

fixup! Fix: Log request body (#6404)

1c2f71b

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch from 0defdbd to 1c2f71b Compare November 21, 2024 17:36

achave11-ucsc requested a review from dsotirho-ucsc November 21, 2024 18:24

achave11-ucsc assigned dsotirho-ucsc Nov 21, 2024

dsotirho-ucsc approved these changes Nov 22, 2024

View reviewed changes

dsotirho-ucsc assigned hannes-ucsc and unassigned dsotirho-ucsc Nov 22, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix: Log request body (#6404) #6536

Fix: Log request body (#6404) #6536

achave11-ucsc commented Aug 31, 2024 •

edited by dsotirho-ucsc

Loading

codecov bot commented Oct 1, 2024 •

edited

Loading

coveralls commented Oct 1, 2024 •

edited

Loading

dsotirho-ucsc left a comment

dsotirho-ucsc Oct 2, 2024

dsotirho-ucsc Oct 17, 2024

achave11-ucsc Oct 18, 2024

dsotirho-ucsc Oct 17, 2024

achave11-ucsc Oct 18, 2024

hannes-ucsc Oct 21, 2024

dsotirho-ucsc Oct 17, 2024

dsotirho-ucsc left a comment

hannes-ucsc left a comment

hannes-ucsc Nov 2, 2024

hannes-ucsc Nov 2, 2024

hannes-ucsc Nov 2, 2024

achave11-ucsc commented Nov 20, 2024

dsotirho-ucsc Nov 20, 2024

dsotirho-ucsc Nov 20, 2024

achave11-ucsc Nov 21, 2024

dsotirho-ucsc left a comment

	msg = f' (first {str(n := 1024)} characters)'
	n = 1024
	msg = f' (first {str(n)} characters)'

	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)

	len_msg = f' (first {str(n)} characters)'
	len_msg = f' (first {n} characters)'

	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))

Fix: Log request body (#6404) #6536

Are you sure you want to change the base?

Fix: Log request body (#6404) #6536

Conversation

achave11-ucsc commented Aug 31, 2024 • edited by dsotirho-ucsc Loading

Checklist

Author

Author (partiality)

Author (chains)

Author (reindex, API changes)

Author (upgrading deployments)

Author (hotfixes)

Author (before every review)

Peer reviewer (after approval)

System administrator (after approval)

Operator (before pushing merge the commit)

System administrator

Operator (before pushing merge the commit)

Operator (chain shortening)

Operator (after pushing the merge commit)

Operator (reindex)

Operator

Shorthand for review comments

codecov bot commented Oct 1, 2024 • edited Loading

Codecov Report

coveralls commented Oct 1, 2024 • edited Loading

dsotirho-ucsc left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dsotirho-ucsc left a comment

Choose a reason for hiding this comment

hannes-ucsc left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

achave11-ucsc commented Nov 20, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dsotirho-ucsc left a comment

Choose a reason for hiding this comment

achave11-ucsc commented Aug 31, 2024 •

edited by dsotirho-ucsc

Loading

codecov bot commented Oct 1, 2024 •

edited

Loading

coveralls commented Oct 1, 2024 •

edited

Loading