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.56098% with 2 lines in your changes missing coverage. Please review.

Project coverage is 85.36%. Comparing base (24aaa42) to head (730d487).

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

Additional details and impacted files

@@             Coverage Diff             @@
##           develop    #6536      +/-   ##
===========================================
+ Coverage    85.35%   85.36%   +0.01%     
===========================================
  Files          155      155              
  Lines        20779    20794      +15     
===========================================
+ Hits         17735    17751      +16     
+ Misses        3044     3043       -1

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

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

coverage: 85.397% (+0.03%) from 85.368%
when pulling 730d487 on issues/achave11-ucsc/6404-log-req-body
into 24aaa42 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 · 2024-10-23T16:42:38Z

src/azul/chalice.py

                     context['httpMethod'],
                     context['path'],
                     json.dumps(request_info, cls=self._LogJSONEncoder))

+            body = self.current_request.json_body
+            if not body:


Isn't this conflating None and the empty string? And for responses, don't we log the fact that the body is absent?

Isn't this conflating None and the empty string?

My bad, it skipped me, ty.

And for responses, don't we log the fact that the body is absent?

Yeah, the http_body_log_message gracefully handles that aspect:

azul/src/azul/logging.py

Lines 168 to 175 in ccc785f

def http_body_log_message(body_type: str,

body: bytes | bytearray | str | None,

*,

verbatim: bool = False,

) -> str:

if body is None:

return f'… without {body_type} body'

elif isinstance(body, (bytes, bytearray, str)):

I've renamed the msg variable to body_len_msg, with the intent of making the purpose of the variable more evident.

hannes-ucsc · 2024-10-23T16:45:29Z

test/service/test_app_logging.py

+                                'Returning 200 response with headers {"Access-Control-Allow-Origin": '
+                                '"*", "Access-Control-Allow-Headers": '
+                                '"Authorization,Content-Type,X-Amz-Date,X-Amz-Security-Token,X-Api-Key", '
+                                f'"Content-Security-Policy": "default-src {sq("self")}", '
+                                '"Referrer-Policy": "strict-origin-when-cross-origin", '
+                                '"Strict-Transport-Security": "max-age=63072000; includeSubDomains; preload", '
+                                '"X-Content-Type-Options": "nosniff", '
+                                '"X-Frame-Options": "DENY", '
+                                '"X-XSS-Protection": "1; mode=block", '
+                                '"Cache-Control": "no-store"}. '
+                                'See next line for the first 1024 characters of the body.\n'
+                                '{"pagination": {"count": 1, "total": 1, "size": 10, "next": null, "previous":'
+                                ' null, "pages": 1, "sort": "projectTitle", "order": "asc"}, "termFacets": '
+                                '{"organ": {"terms": [{"term": "pancreas", "count": 1}], "total": 1, "type": '
+                                '"terms"}, "sampleEntityType": {"terms": [{"term": "specimens", "count": 1}], '
+                                '"total": 1, "type": "terms"}, "dataUseRestriction": {"terms": [{"term": null, '
+                                '"count": 1}], "total": 1, "type": "terms"}, "project": {"terms": [{"term": '
+                                '"Single of human pancreas", "count": 1, "projectId": '
+                                '["e8642221-4c2c-4fd7-b926-a68bce363c88"]}], "total": 1, "type": "terms"}, '
+                                '"sampleDisease": {"terms": [{"term": "normal", "count": 1}], "total": 1, "type": '
+                                '"terms"}, "nucleicAcidSource": {"terms": [{"term": "single cell", "count": 1}], '
+                                '"total": 1, "type": "terms"}, "assayType": {"terms": [{"term": null, "count": 1}], '
+                                '"total": 0, "type": "terms"}, "instrumentManufacturerModel": {"terms": [{"term": '
+                                '"Illumina NextSeq 500", "count": 1}], "total": 1, "type": "terms"}, "institution": '
+                                '{"terms": [{"term": "Farmers Tru',


Please find a way to make this less ugly. For example, you could specify headers and body as JSON literals and use json.dumps() to convert them to a string, and taking only the first 1024 charterers of the body.

hannes-ucsc · 2024-10-23T16:45:42Z

test/service/test_app_logging.py

-                            '{"up": true}'
-                        )
-                    ])
+                    if reques_body:


Suggested change

if reques_body:

if request_body:

hannes-ucsc · 2024-10-23T16:48:16Z

test/service/test_app_logging.py

+                    with self.subTest(level=level,
+                                      authenticated=authenticated,
+                                      request_body=reques_body,
+                                      azul_debug=azul_debug):


Suggested change

with self.subTest(level=level,

authenticated=authenticated,

request_body=reques_body,

azul_debug=azul_debug):

with self.subTest(authenticated=authenticated,

request_body=reques_body,

azul_debug=azul_debug):

because level is derived from azul_debug you don't need to label the subtest with it.

src/azul/chalice.py

src/azul/logging.py

hannes-ucsc · 2024-10-29T16:48:35Z

src/azul/chalice.py

+            log.info('%s%s',
+                     http_body_log_message('request', body, verbatim=True), body_len_msg)


Suggested change

log.info('%s%s',

http_body_log_message('request', body, verbatim=True), body_len_msg)

log.info(http_body_log_message('request', body, verbatim=True) + body_len_msg))

hannes-ucsc · 2024-10-29T16:51:00Z

test/service/test_app_logging.py

+                                    },
+                                    'termFacets': {
+                                        'organ': {
+                                            'terms': [{


What's your convention about hugging brackets and braces? Hugging them breaks our wrap-all-or-nothing convention so if you already break it, you might as well put each inner-most dict literals on one line.

Or, don't hug.

hannes-ucsc · 2024-10-29T16:51:33Z

test/service/test_app_logging.py

+                                '"X-XSS-Protection": "1; mode=block", '
+                                '"Cache-Control": "no-store"}. '
+                                'See next line for the first 1024 characters of the body.\n'
+                                + json_head(1024, {


As I pointed out before, you shouldn't use the code under test to compute an assertion about the output of said code.

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

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

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch from b939169 to 10b6f76 Compare October 22, 2024 18:06

achave11-ucsc requested a review from hannes-ucsc October 22, 2024 19:07

achave11-ucsc assigned hannes-ucsc Oct 22, 2024

hannes-ucsc requested changes Oct 23, 2024

View reviewed changes

hannes-ucsc added 2 reviews [process] Lead requested changes twice and removed 1 review [process] Lead requested changes once labels Oct 23, 2024

hannes-ucsc removed their assignment Oct 23, 2024

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch from 3969986 to 437f818 Compare October 24, 2024 23:13

github-advanced-security bot found potential problems Oct 24, 2024

View reviewed changes

src/azul/chalice.py Fixed Show fixed Hide fixed

src/azul/logging.py Fixed Show fixed Hide fixed

achave11-ucsc requested a review from hannes-ucsc October 25, 2024 00:32

achave11-ucsc assigned hannes-ucsc and unassigned hannes-ucsc Oct 25, 2024

achave11-ucsc requested review from hannes-ucsc and removed request for hannes-ucsc October 25, 2024 00:33

achave11-ucsc assigned hannes-ucsc Oct 25, 2024

hannes-ucsc requested changes Oct 29, 2024

View reviewed changes

hannes-ucsc added 3 reviews [process] Lead requested changes thrice and removed 2 reviews [process] Lead requested changes twice labels Oct 29, 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 added 2 commits November 13, 2024 10:44

Updates to TestServiceAppLogging for simplifying subsequent additions

e4bd1b6

Tests, Fix: Log request body (#6404)

c7b4f79

achave11-ucsc force-pushed the issues/achave11-ucsc/6404-log-req-body branch from 730d487 to e4bd1b6 Compare November 13, 2024 18:45

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 Oct 23, 2024

achave11-ucsc Oct 24, 2024

hannes-ucsc Oct 23, 2024

hannes-ucsc Oct 23, 2024

hannes-ucsc Oct 23, 2024

hannes-ucsc Oct 29, 2024

hannes-ucsc Oct 29, 2024

hannes-ucsc Oct 29, 2024

hannes-ucsc left a comment

hannes-ucsc Nov 2, 2024

hannes-ucsc Nov 2, 2024

hannes-ucsc Nov 2, 2024

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

	def http_body_log_message(body_type: str,
	body: bytes \| bytearray \| str \| None,
	*,
	verbatim: bool = False,
	) -> str:
	if body is None:
	return f'… without {body_type} body'
	elif isinstance(body, (bytes, bytearray, str)):

		log.info('%s%s',
		http_body_log_message('request', body, verbatim=True), body_len_msg)

	log.info('%s%s',
	http_body_log_message('request', body, verbatim=True), body_len_msg)
	log.info(http_body_log_message('request', body, verbatim=True) + body_len_msg))

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

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

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

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 Aug 31, 2024 •

edited by dsotirho-ucsc

Loading

codecov bot commented Oct 1, 2024 •

edited

Loading

coveralls commented Oct 1, 2024 •

edited

Loading