From 63be67af808cde611b608246494840b289304d46 Mon Sep 17 00:00:00 2001 From: Anders Kaseorg Date: Mon, 10 Jul 2023 16:17:30 -0400 Subject: [PATCH] logging_util: Remove dependence on get_current_request. Pass the HttpRequest explicitly through the two webhooks that log to the webhook loggers. get_current_request is now unused, so remove it (in the same commit for test coverage reasons). Signed-off-by: Anders Kaseorg --- zerver/decorator.py | 18 +++--- zerver/lib/logging_util.py | 7 +-- zerver/lib/request.py | 23 ------- zerver/middleware.py | 11 +--- zerver/tests/test_decorators.py | 4 +- zerver/webhooks/bitbucket2/tests.py | 16 +++-- zerver/webhooks/bitbucket2/view.py | 93 ++++++++++++++++------------- zerver/webhooks/github/view.py | 7 ++- zproject/computed_settings.py | 1 - 9 files changed, 85 insertions(+), 95 deletions(-) diff --git a/zerver/decorator.py b/zerver/decorator.py index 2390ed78eb..f23ba66a48 100644 --- a/zerver/decorator.py +++ b/zerver/decorator.py @@ -299,23 +299,25 @@ def access_user_by_api_key( return user_profile -def log_unsupported_webhook_event(summary: str) -> None: +def log_unsupported_webhook_event(request: HttpRequest, summary: str) -> None: # This helper is primarily used by some of our more complicated # webhook integrations (e.g. GitHub) that need to log an unsupported # event based on attributes nested deep within a complicated JSON # payload. In such cases, the error message we want to log may not # really fit what a regular UnsupportedWebhookEventTypeError exception # represents. - webhook_unsupported_events_logger.exception(summary, stack_info=True) + extra = {"request": request} + webhook_unsupported_events_logger.exception(summary, stack_info=True, extra=extra) -def log_exception_to_webhook_logger(err: Exception) -> None: +def log_exception_to_webhook_logger(request: HttpRequest, err: Exception) -> None: + extra = {"request": request} if isinstance(err, AnomalousWebhookPayloadError): - webhook_anomalous_payloads_logger.exception(str(err), stack_info=True) + webhook_anomalous_payloads_logger.exception(str(err), stack_info=True, extra=extra) elif isinstance(err, UnsupportedWebhookEventTypeError): - webhook_unsupported_events_logger.exception(str(err), stack_info=True) + webhook_unsupported_events_logger.exception(str(err), stack_info=True, extra=extra) else: - webhook_logger.exception(str(err), stack_info=True) + webhook_logger.exception(str(err), stack_info=True, extra=extra) def full_webhook_client_name(raw_client_name: Optional[str] = None) -> Optional[str]: @@ -369,7 +371,7 @@ def webhook_view( err.webhook_name = webhook_client_name if isinstance(err, UnsupportedWebhookEventTypeError): capture_exception(err) - log_exception_to_webhook_logger(err) + log_exception_to_webhook_logger(request, err) raise err # Store the event types registered for this webhook as an attribute, which can be access @@ -780,7 +782,7 @@ def authenticated_rest_api_view( err.webhook_name = webhook_client_name if isinstance(err, UnsupportedWebhookEventTypeError): capture_exception(err) - log_exception_to_webhook_logger(err) + log_exception_to_webhook_logger(request, err) raise err return _wrapped_func_arguments diff --git a/zerver/lib/logging_util.py b/zerver/lib/logging_util.py index 1ffb352702..4cc4d1889f 100644 --- a/zerver/lib/logging_util.py +++ b/zerver/lib/logging_util.py @@ -11,6 +11,7 @@ from typing import Optional, Tuple, Union import orjson from django.conf import settings from django.core.cache import cache +from django.http import HttpRequest from django.utils.timezone import now as timezone_now @@ -222,10 +223,8 @@ class ZulipWebhookFormatter(ZulipFormatter): return "\n".join(multiline) def format(self, record: logging.LogRecord) -> str: - from zerver.lib.request import get_current_request - - request = get_current_request() - if not request: + request: Optional[HttpRequest] = getattr(record, "request", None) + if request is None: record.user = None record.client = None record.url = None diff --git a/zerver/lib/request.py b/zerver/lib/request.py index b48343018a..3203b2da99 100644 --- a/zerver/lib/request.py +++ b/zerver/lib/request.py @@ -1,4 +1,3 @@ -import threading from collections import defaultdict from dataclasses import dataclass, field from functools import wraps @@ -490,25 +489,3 @@ def has_request_variables( return return_value return _wrapped_req_func - - -local = threading.local() - - -def get_current_request() -> Optional[HttpRequest]: - """Returns the current HttpRequest object; this should only be used by - logging frameworks, which have no other access to the current - request. All other codepaths should pass through the current - request object, rather than rely on this thread-local global. - - """ - return getattr(local, "request", None) - - -def set_request(req: HttpRequest) -> None: - local.request = req - - -def unset_request() -> None: - if hasattr(local, "request"): - del local.request diff --git a/zerver/middleware.py b/zerver/middleware.py index 23348aae18..7124c893d1 100644 --- a/zerver/middleware.py +++ b/zerver/middleware.py @@ -33,7 +33,7 @@ from zerver.lib.exceptions import ErrorCode, JsonableError, MissingAuthenticatio from zerver.lib.html_to_text import get_content_description from zerver.lib.markdown import get_markdown_requests, get_markdown_time from zerver.lib.rate_limiter import RateLimitResult -from zerver.lib.request import REQ, RequestNotes, has_request_variables, set_request, unset_request +from zerver.lib.request import REQ, RequestNotes, has_request_variables from zerver.lib.response import ( AsynchronousResponse, json_response, @@ -226,15 +226,6 @@ def write_log_line( logger.info("status=%3d, data=%s, uid=%s", status_code, error_data, requester_for_logs) -class RequestContext(MiddlewareMixin): - def __call__(self, request: HttpRequest) -> HttpResponseBase: - set_request(request) - try: - return self.get_response(request) - finally: - unset_request() - - # We take advantage of `has_request_variables` being called multiple times # when processing a request in order to process any `client` parameter that # may have been sent in the request content. diff --git a/zerver/tests/test_decorators.py b/zerver/tests/test_decorators.py index a86078e945..f1e93a8071 100644 --- a/zerver/tests/test_decorators.py +++ b/zerver/tests/test_decorators.py @@ -583,7 +583,9 @@ class DecoratorLoggingTestCase(ZulipTestCase): with self.assertRaisesRegex(UnsupportedWebhookEventTypeError, exception_msg): my_webhook_raises_exception(request) - mock_exception.assert_called_with(exception_msg, stack_info=True) + mock_exception.assert_called_with( + exception_msg, stack_info=True, extra={"request": request} + ) def test_authenticated_rest_api_view_with_non_webhook_view(self) -> None: @authenticated_rest_api_view() diff --git a/zerver/webhooks/bitbucket2/tests.py b/zerver/webhooks/bitbucket2/tests.py index e2ac0387c6..437a511ecc 100644 --- a/zerver/webhooks/bitbucket2/tests.py +++ b/zerver/webhooks/bitbucket2/tests.py @@ -1,7 +1,10 @@ from unittest.mock import MagicMock, patch +from zerver.lib.request import RequestNotes from zerver.lib.test_classes import WebhookTestCase +from zerver.lib.test_helpers import HostRequestMock from zerver.lib.validator import wrap_wild_value +from zerver.models import get_client from zerver.webhooks.bitbucket2.view import get_user_info TOPIC = "Repository name" @@ -429,7 +432,12 @@ class Bitbucket2HookTests(WebhookTestCase): self.assert_json_success(result) def test_get_user_info(self) -> None: - self.assertEqual(get_user_info(wrap_wild_value("request", {})), "Unknown user") + request = HostRequestMock() + request.content_type = "application/json" + request.user = self.test_user + RequestNotes.get_notes(request).client = get_client("test") + + self.assertEqual(get_user_info(request, wrap_wild_value("request", {})), "Unknown user") dct = dict( nickname="alice", @@ -437,10 +445,10 @@ class Bitbucket2HookTests(WebhookTestCase): display_name="Alice Smith", ) - self.assertEqual(get_user_info(wrap_wild_value("request", dct)), "Alice Smith") + self.assertEqual(get_user_info(request, wrap_wild_value("request", dct)), "Alice Smith") del dct["display_name"] - self.assertEqual(get_user_info(wrap_wild_value("request", dct)), "alice") + self.assertEqual(get_user_info(request, wrap_wild_value("request", dct)), "alice") del dct["nickname"] - self.assertEqual(get_user_info(wrap_wild_value("request", dct)), "Unknown user") + self.assertEqual(get_user_info(request, wrap_wild_value("request", dct)), "Unknown user") diff --git a/zerver/webhooks/bitbucket2/view.py b/zerver/webhooks/bitbucket2/view.py index 49cc2efd58..3a706acbb9 100644 --- a/zerver/webhooks/bitbucket2/view.py +++ b/zerver/webhooks/bitbucket2/view.py @@ -94,7 +94,7 @@ def api_bitbucket2_webhook( return json_success(request) subjects = get_push_subjects(payload) - bodies = get_push_bodies(payload) + bodies = get_push_bodies(request, payload) for b, s in zip(bodies, subjects): check_send_webhook_message( @@ -104,6 +104,7 @@ def api_bitbucket2_webhook( subject = get_subject_based_on_type(payload, type) body_function = get_body_based_on_type(type) body = body_function( + request, payload, include_title=user_specified_topic is not None, ) @@ -199,7 +200,7 @@ def get_type(request: HttpRequest, payload: WildValue) -> str: class BodyGetter(Protocol): - def __call__(self, payload: WildValue, include_title: bool) -> str: + def __call__(self, request: HttpRequest, payload: WildValue, include_title: bool) -> str: ... @@ -209,48 +210,48 @@ def get_body_based_on_type( return GET_SINGLE_MESSAGE_BODY_DEPENDING_ON_TYPE_MAPPER[type] -def get_push_bodies(payload: WildValue) -> List[str]: +def get_push_bodies(request: HttpRequest, payload: WildValue) -> List[str]: messages_list = [] for change in payload["push"]["changes"]: potential_tag = (change["new"] or change["old"])["type"].tame(check_string) if potential_tag == "tag": - messages_list.append(get_push_tag_body(payload, change)) + messages_list.append(get_push_tag_body(request, payload, change)) # if change['new'] is None, that means a branch was deleted elif change["new"].value is None: - messages_list.append(get_remove_branch_push_body(payload, change)) + messages_list.append(get_remove_branch_push_body(request, payload, change)) elif change["forced"].tame(check_bool): - messages_list.append(get_force_push_body(payload, change)) + messages_list.append(get_force_push_body(request, payload, change)) else: - messages_list.append(get_normal_push_body(payload, change)) + messages_list.append(get_normal_push_body(request, payload, change)) return messages_list -def get_remove_branch_push_body(payload: WildValue, change: WildValue) -> str: +def get_remove_branch_push_body(request: HttpRequest, payload: WildValue, change: WildValue) -> str: return get_remove_branch_event_message( - get_actor_info(payload), + get_actor_info(request, payload), change["old"]["name"].tame(check_string), ) -def get_force_push_body(payload: WildValue, change: WildValue) -> str: +def get_force_push_body(request: HttpRequest, payload: WildValue, change: WildValue) -> str: return get_force_push_commits_event_message( - get_actor_info(payload), + get_actor_info(request, payload), change["links"]["html"]["href"].tame(check_string), change["new"]["name"].tame(check_string), change["new"]["target"]["hash"].tame(check_string), ) -def get_commit_author_name(commit: WildValue) -> str: +def get_commit_author_name(request: HttpRequest, commit: WildValue) -> str: if "user" in commit["author"]: - return get_user_info(commit["author"]["user"]) + return get_user_info(request, commit["author"]["user"]) return commit["author"]["raw"].tame(check_string).split()[0] -def get_normal_push_body(payload: WildValue, change: WildValue) -> str: +def get_normal_push_body(request: HttpRequest, payload: WildValue, change: WildValue) -> str: commits_data = [ { - "name": get_commit_author_name(commit), + "name": get_commit_author_name(request, commit), "sha": commit["hash"].tame(check_string), "url": commit["links"]["html"]["href"].tame(check_string), "message": commit["message"].tame(check_string), @@ -259,7 +260,7 @@ def get_normal_push_body(payload: WildValue, change: WildValue) -> str: ] return get_push_commits_event_message( - get_actor_info(payload), + get_actor_info(request, payload), change["links"]["html"]["href"].tame(check_string), change["new"]["name"].tame(check_string), commits_data, @@ -267,19 +268,19 @@ def get_normal_push_body(payload: WildValue, change: WildValue) -> str: ) -def get_fork_body(payload: WildValue, include_title: bool) -> str: +def get_fork_body(request: HttpRequest, payload: WildValue, include_title: bool) -> str: return BITBUCKET_FORK_BODY.format( - actor=get_user_info(payload["actor"]), + actor=get_user_info(request, payload["actor"]), fork_name=get_repository_full_name(payload["fork"]), fork_url=get_repository_url(payload["fork"]), ) -def get_commit_comment_body(payload: WildValue, include_title: bool) -> str: +def get_commit_comment_body(request: HttpRequest, payload: WildValue, include_title: bool) -> str: comment = payload["comment"] action = "[commented]({})".format(comment["links"]["html"]["href"].tame(check_string)) return get_commits_comment_action_message( - get_actor_info(payload), + get_actor_info(request, payload), action, comment["commit"]["links"]["html"]["href"].tame(check_string), comment["commit"]["hash"].tame(check_string), @@ -287,7 +288,9 @@ def get_commit_comment_body(payload: WildValue, include_title: bool) -> str: ) -def get_commit_status_changed_body(payload: WildValue, include_title: bool) -> str: +def get_commit_status_changed_body( + request: HttpRequest, payload: WildValue, include_title: bool +) -> str: commit_api_url = payload["commit_status"]["links"]["commit"]["href"].tame(check_string) commit_id = commit_api_url.split("/")[-1] @@ -305,24 +308,26 @@ def get_commit_status_changed_body(payload: WildValue, include_title: bool) -> s ) -def get_issue_commented_body(payload: WildValue, include_title: bool) -> str: +def get_issue_commented_body(request: HttpRequest, payload: WildValue, include_title: bool) -> str: action = "[commented]({}) on".format( payload["comment"]["links"]["html"]["href"].tame(check_string) ) - return get_issue_action_body(payload, action, include_title) + return get_issue_action_body(request, payload, action, include_title) -def get_issue_action_body(payload: WildValue, action: str, include_title: bool) -> str: +def get_issue_action_body( + request: HttpRequest, payload: WildValue, action: str, include_title: bool +) -> str: issue = payload["issue"] assignee = None message = None if action == "created": if issue["assignee"]: - assignee = get_user_info(issue["assignee"]) + assignee = get_user_info(request, issue["assignee"]) message = issue["content"]["raw"].tame(check_string) return get_issue_event_message( - user_name=get_actor_info(payload), + user_name=get_actor_info(request, payload), action=action, url=issue["links"]["html"]["href"].tame(check_string), number=issue["id"].tame(check_int), @@ -332,7 +337,9 @@ def get_issue_action_body(payload: WildValue, action: str, include_title: bool) ) -def get_pull_request_action_body(payload: WildValue, action: str, include_title: bool) -> str: +def get_pull_request_action_body( + request: HttpRequest, payload: WildValue, action: str, include_title: bool +) -> str: pull_request = payload["pullrequest"] target_branch = None base_branch = None @@ -341,7 +348,7 @@ def get_pull_request_action_body(payload: WildValue, action: str, include_title: base_branch = pull_request["destination"]["branch"]["name"].tame(check_string) return get_pull_request_event_message( - user_name=get_actor_info(payload), + user_name=get_actor_info(request, payload), action=action, url=get_pull_request_url(pull_request), number=pull_request["id"].tame(check_int), @@ -352,15 +359,15 @@ def get_pull_request_action_body(payload: WildValue, action: str, include_title: def get_pull_request_created_or_updated_body( - payload: WildValue, action: str, include_title: bool + request: HttpRequest, payload: WildValue, action: str, include_title: bool ) -> str: pull_request = payload["pullrequest"] assignee = None if pull_request["reviewers"]: - assignee = get_user_info(pull_request["reviewers"][0]) + assignee = get_user_info(request, pull_request["reviewers"][0]) return get_pull_request_event_message( - user_name=get_actor_info(payload), + user_name=get_actor_info(request, payload), action=action, url=get_pull_request_url(pull_request), number=pull_request["id"].tame(check_int), @@ -377,16 +384,18 @@ def get_pull_request_created_or_updated_body( def get_pull_request_comment_created_action_body( + request: HttpRequest, payload: WildValue, include_title: bool, ) -> str: action = "[commented]({})".format( payload["comment"]["links"]["html"]["href"].tame(check_string) ) - return get_pull_request_comment_action_body(payload, action, include_title) + return get_pull_request_comment_action_body(request, payload, action, include_title) def get_pull_request_deleted_or_updated_comment_action_body( + request: HttpRequest, payload: WildValue, action: str, include_title: bool, @@ -394,17 +403,18 @@ def get_pull_request_deleted_or_updated_comment_action_body( action = "{} a [comment]({})".format( action, payload["comment"]["links"]["html"]["href"].tame(check_string) ) - return get_pull_request_comment_action_body(payload, action, include_title) + return get_pull_request_comment_action_body(request, payload, action, include_title) def get_pull_request_comment_action_body( + request: HttpRequest, payload: WildValue, action: str, include_title: bool, ) -> str: action += " on" return get_pull_request_event_message( - user_name=get_actor_info(payload), + user_name=get_actor_info(request, payload), action=action, url=payload["pullrequest"]["links"]["html"]["href"].tame(check_string), number=payload["pullrequest"]["id"].tame(check_int), @@ -413,7 +423,7 @@ def get_pull_request_comment_action_body( ) -def get_push_tag_body(payload: WildValue, change: WildValue) -> str: +def get_push_tag_body(request: HttpRequest, payload: WildValue, change: WildValue) -> str: if change.get("new"): tag = change["new"] action = "pushed" @@ -422,7 +432,7 @@ def get_push_tag_body(payload: WildValue, change: WildValue) -> str: action = "removed" return get_push_tag_event_message( - get_actor_info(payload), + get_actor_info(request, payload), tag["name"].tame(check_string), tag_url=tag["links"]["html"]["href"].tame(check_string), action=action, @@ -436,11 +446,11 @@ def append_punctuation(title: str, message: str) -> str: return message -def get_repo_updated_body(payload: WildValue, include_title: bool) -> str: +def get_repo_updated_body(request: HttpRequest, payload: WildValue, include_title: bool) -> str: changes = ["website", "name", "links", "language", "full_name", "description"] body = "" repo_name = payload["repository"]["name"].tame(check_string) - actor = get_actor_info(payload) + actor = get_actor_info(request, payload) for change in changes: new = payload["changes"][change]["new"] @@ -486,7 +496,7 @@ def get_repository_full_name(repository_payload: WildValue) -> str: return repository_payload["full_name"].tame(check_string) -def get_user_info(dct: WildValue) -> str: +def get_user_info(request: HttpRequest, dct: WildValue) -> str: # See https://developer.atlassian.com/cloud/bitbucket/bitbucket-api-changes-gdpr/ # Since GDPR, we don't get username; instead, we either get display_name # or nickname. @@ -499,15 +509,16 @@ def get_user_info(dct: WildValue) -> str: # We call this an unsupported_event, even though we # are technically still sending a message. log_unsupported_webhook_event( + request=request, summary="Could not find display_name/nickname field", ) return "Unknown user" -def get_actor_info(payload: WildValue) -> str: +def get_actor_info(request: HttpRequest, payload: WildValue) -> str: actor = payload["actor"] - return get_user_info(actor) + return get_user_info(request, actor) def get_branch_name_for_push_event(payload: WildValue) -> Optional[str]: diff --git a/zerver/webhooks/github/view.py b/zerver/webhooks/github/view.py index 9c12280c1c..5490352436 100644 --- a/zerver/webhooks/github/view.py +++ b/zerver/webhooks/github/view.py @@ -48,17 +48,17 @@ DISCUSSION_COMMENT_TEMPLATE = "{author} [commented]({comment_url}) on [discussio class Helper: def __init__( self, + request: HttpRequest, payload: WildValue, include_title: bool, ) -> None: + self.request = request self.payload = payload self.include_title = include_title def log_unsupported(self, event: str) -> None: summary = f"The '{event}' event isn't currently supported by the GitHub webhook; ignoring" - log_unsupported_webhook_event( - summary=summary, - ) + log_unsupported_webhook_event(request=self.request, summary=summary) def get_opened_or_update_pull_request_body(helper: Helper) -> str: @@ -836,6 +836,7 @@ def api_github_webhook( body_function = EVENT_FUNCTION_MAPPER[event] helper = Helper( + request=request, payload=payload, include_title=user_specified_topic is not None, ) diff --git a/zproject/computed_settings.py b/zproject/computed_settings.py index 8ffebe12d7..db72f7bed4 100644 --- a/zproject/computed_settings.py +++ b/zproject/computed_settings.py @@ -162,7 +162,6 @@ ALLOWED_HOSTS += REALM_HOSTS.values() MIDDLEWARE = [ "zerver.middleware.TagRequests", "zerver.middleware.SetRemoteAddrFromRealIpHeader", - "zerver.middleware.RequestContext", "django.contrib.sessions.middleware.SessionMiddleware", "django.contrib.auth.middleware.AuthenticationMiddleware", # Important: All middleware before LogRequests should be