From 8e10ab282a00a2f8e32b3f5607f147e6d27e2bc5 Mon Sep 17 00:00:00 2001 From: Eeshan Garg Date: Thu, 6 Jun 2019 01:25:09 -0230 Subject: [PATCH] webhooks: Log unexpected webhook events separately. This change serves to declutter webhook-errors.log, which is filled with too many UnexpectedWebhookEventType exceptions. Keeping UnexpectedWebhookEventType in zerver/lib/webhooks/common.py led to a cyclic import when we tried to import the exception in zerver/decorators.py, so this commit also moves this exception to another appropriate module. Note that our webhooks still import this exception via zerver/lib/webhooks/common.py. --- tools/linter_lib/pyflakes.py | 3 ++ tools/test-backend | 1 - zerver/decorator.py | 36 ++++++++++++--- zerver/lib/exceptions.py | 15 +++++- zerver/lib/webhooks/common.py | 14 +----- zerver/tests/test_decorators.py | 81 +++++++++++++++++++++++++++++++++ zproject/settings.py | 6 +++ 7 files changed, 135 insertions(+), 21 deletions(-) diff --git a/tools/linter_lib/pyflakes.py b/tools/linter_lib/pyflakes.py index 96476e5531..7f93a463b7 100644 --- a/tools/linter_lib/pyflakes.py +++ b/tools/linter_lib/pyflakes.py @@ -13,6 +13,9 @@ def check_pyflakes(files, options): suppress_patterns = [ (b"scripts/lib/pythonrc.py", b"imported but unused"), (b'', b"'scripts.lib.setup_path_on_import' imported but unused"), + # Intentionally imported by zerver/lib/webhooks/common.py + (b'', b"'zerver.lib.exceptions.UnexpectedWebhookEventType' imported but unused"), + # Our ipython startup pythonrc file intentionally imports * (b"scripts/lib/pythonrc.py", diff --git a/tools/test-backend b/tools/test-backend index d60592ca17..6d1072c695 100755 --- a/tools/test-backend +++ b/tools/test-backend @@ -67,7 +67,6 @@ not_yet_fully_covered = {path for target in [ 'zerver/lib/i18n.py', 'zerver/lib/email_notifications.py', 'zerver/lib/send_email.py', - 'zerver/lib/webhooks/common.py', 'zerver/lib/url_preview/preview.py', 'zerver/worker/queue_processors.py', # Bugdown sub-libs should have full coverage too; a lot are really close diff --git a/zerver/decorator.py b/zerver/decorator.py index 37ac2e02af..30ac1e657e 100644 --- a/zerver/decorator.py +++ b/zerver/decorator.py @@ -18,6 +18,7 @@ from django.utils.decorators import available_attrs from django.utils.timezone import now as timezone_now from django.conf import settings +from zerver.lib.exceptions import UnexpectedWebhookEventType from zerver.lib.queue import queue_json_publish from zerver.lib.subdomains import get_subdomain, user_matches_subdomain from zerver.lib.timestamp import datetime_to_timestamp, timestamp_to_datetime @@ -55,6 +56,10 @@ ReturnT = TypeVar('ReturnT') webhook_logger = logging.getLogger("zulip.zerver.webhooks") log_to_file(webhook_logger, settings.API_KEY_ONLY_WEBHOOK_LOG_PATH) +webhook_unexpected_events_logger = logging.getLogger("zulip.zerver.lib.webhooks.common") +log_to_file(webhook_unexpected_events_logger, + settings.WEBHOOK_UNEXPECTED_EVENTS_LOG_PATH) + class _RespondAsynchronously: pass @@ -275,8 +280,11 @@ def access_user_by_api_key(request: HttpRequest, api_key: str, email: Optional[s return user_profile -def log_exception_to_webhook_logger(request: HttpRequest, user_profile: UserProfile, - request_body: Optional[str]=None) -> None: +def log_exception_to_webhook_logger( + request: HttpRequest, user_profile: UserProfile, + request_body: Optional[str]=None, + unexpected_event: Optional[bool]=False +) -> None: if request_body is not None: payload = request_body else: @@ -320,7 +328,11 @@ body: custom_headers=header_message, ) message = message.strip(' ') - webhook_logger.exception(message) + + if unexpected_event: + webhook_unexpected_events_logger.exception(message) + else: + webhook_logger.exception(message) def full_webhook_client_name(raw_client_name: Optional[str]=None) -> Optional[str]: if raw_client_name is None: @@ -356,7 +368,11 @@ def api_key_only_webhook_view( from zerver.lib.webhooks.common import notify_bot_owner_about_invalid_json notify_bot_owner_about_invalid_json(user_profile, webhook_client_name) else: - log_exception_to_webhook_logger(request, user_profile) + kwargs = {'request': request, 'user_profile': user_profile} + if isinstance(err, UnexpectedWebhookEventType): + kwargs['unexpected_event'] = True + + log_exception_to_webhook_logger(**kwargs) raise err return _wrapped_func_arguments @@ -583,8 +599,16 @@ def authenticated_rest_api_view(*, webhook_client_name: Optional[str]=None, if is_webhook or webhook_client_name is not None: request_body = request.POST.get('payload') if request_body is not None: - log_exception_to_webhook_logger(request, profile, - request_body=request_body) + kwargs = { + 'request_body': request_body, + 'request': request, + 'user_profile': profile, + } + if isinstance(err, UnexpectedWebhookEventType): + kwargs['unexpected_event'] = True + + log_exception_to_webhook_logger(**kwargs) + raise err return _wrapped_func_arguments return _wrapped_view_func diff --git a/zerver/lib/exceptions.py b/zerver/lib/exceptions.py index 5a5e086c09..cca51ae30c 100644 --- a/zerver/lib/exceptions.py +++ b/zerver/lib/exceptions.py @@ -1,10 +1,11 @@ from enum import Enum -from typing import Any, Dict, List, Type +from typing import Any, Dict, List, Type, Optional from mypy_extensions import NoReturn from django.core.exceptions import PermissionDenied from django.utils.translation import ugettext as _ + class AbstractEnum(Enum): '''An enumeration whose members are used strictly for their names.''' @@ -200,3 +201,15 @@ class InvalidAPIKeyError(JsonableError): @staticmethod def msg_format() -> str: return _("Invalid API key") + +class UnexpectedWebhookEventType(JsonableError): + code = ErrorCode.UNEXPECTED_WEBHOOK_EVENT_TYPE + data_fields = ['webhook_name', 'event_type'] + + def __init__(self, webhook_name: str, event_type: Optional[str]) -> None: + self.webhook_name = webhook_name + self.event_type = event_type + + @staticmethod + def msg_format() -> str: + return _("The '{event_type}' event isn't currently supported by the {webhook_name} webhook") diff --git a/zerver/lib/webhooks/common.py b/zerver/lib/webhooks/common.py index 17aeff8a68..c337f6d11d 100644 --- a/zerver/lib/webhooks/common.py +++ b/zerver/lib/webhooks/common.py @@ -8,7 +8,7 @@ from typing import Optional, Dict, Union, Any, Callable from zerver.lib.actions import check_send_stream_message, \ check_send_private_message, send_rate_limited_pm_notification_to_bot_owner from zerver.lib.exceptions import StreamDoesNotExistError, JsonableError, \ - ErrorCode + ErrorCode, UnexpectedWebhookEventType from zerver.lib.request import REQ, has_request_variables from zerver.lib.send_email import FromAddress from zerver.models import UserProfile @@ -39,18 +39,6 @@ def notify_bot_owner_about_invalid_json(user_profile: UserProfile, INVALID_JSON_MESSAGE.format(webhook_name=webhook_client_name).strip() ) -class UnexpectedWebhookEventType(JsonableError): - code = ErrorCode.UNEXPECTED_WEBHOOK_EVENT_TYPE - data_fields = ['webhook_name', 'event_type'] - - def __init__(self, webhook_name: str, event_type: Optional[str]) -> None: - self.webhook_name = webhook_name - self.event_type = event_type - - @staticmethod - def msg_format() -> str: - return _("The '{event_type}' event isn't currently supported by the {webhook_name} webhook") - class MissingHTTPEventHeader(JsonableError): code = ErrorCode.MISSING_HTTP_EVENT_HEADER data_fields = ['header'] diff --git a/zerver/tests/test_decorators.py b/zerver/tests/test_decorators.py index 26a52077f4..df70f7f053 100644 --- a/zerver/tests/test_decorators.py +++ b/zerver/tests/test_decorators.py @@ -28,6 +28,7 @@ from zerver.lib.user_agent import parse_user_agent from zerver.lib.request import \ REQ, has_request_variables, RequestVariableMissingError, \ RequestVariableConversionError, RequestConfusingParmsError +from zerver.lib.webhooks.common import UnexpectedWebhookEventType from zerver.decorator import ( api_key_only_webhook_view, authenticated_json_view, @@ -277,6 +278,11 @@ class DecoratorTestCase(TestCase): def my_webhook_raises_exception(request: HttpRequest, user_profile: UserProfile) -> None: raise Exception("raised by webhook function") + @api_key_only_webhook_view('ClientName') + def my_webhook_raises_exception_unexpected_event( + request: HttpRequest, user_profile: UserProfile) -> None: + raise UnexpectedWebhookEventType("helloworld", "test_event") + webhook_bot_email = 'webhook-bot@zulip.com' webhook_bot_realm = get_realm('zulip') webhook_bot = get_user(webhook_bot_email, webhook_bot_realm) @@ -348,6 +354,37 @@ custom_http_headers: {custom_headers} body: +{body} + """ + message = message.strip(' ') + mock_exception.assert_called_with(message.format( + email=webhook_bot_email, + realm=webhook_bot_realm.string_id, + client_name=webhook_client_name, + path_info=request.META.get('PATH_INFO'), + content_type=request.content_type, + custom_headers="HTTP_X_CUSTOM_HEADER: custom_value\n", + body=request.body, + )) + + # Test when an unexpected webhook event occurs + with mock.patch('zerver.decorator.webhook_unexpected_events_logger.exception') as mock_exception: + exception_msg = "The 'test_event' event isn't currently supported by the helloworld webhook" + with self.assertRaisesRegex(UnexpectedWebhookEventType, exception_msg): + request.body = "invalidjson" + request.content_type = 'application/json' + request.META['HTTP_X_CUSTOM_HEADER'] = 'custom_value' + my_webhook_raises_exception_unexpected_event(request) # type: ignore # mypy doesn't seem to apply the decorator + + message = """ +user: {email} ({realm}) +client: {client_name} +URL: {path_info} +content_type: {content_type} +custom_http_headers: +{custom_headers} +body: + {body} """ message = message.strip(' ') @@ -490,6 +527,50 @@ custom_http_headers: {custom_headers} body: +{body} + """ + message = message.strip(' ') + mock_exception.assert_called_with(message.format( + email=webhook_bot_email, + realm=webhook_bot_realm.string_id, + client_name='ZulipClientNameWebhook', + path_info=request.META.get('PATH_INFO'), + content_type=request.content_type, + custom_headers=None, + body=request.body, + )) + + def test_authenticated_rest_api_view_logging_unexpected_event(self) -> None: + @authenticated_rest_api_view(webhook_client_name="ClientName") + def my_webhook_raises_exception(request: HttpRequest, user_profile: UserProfile) -> None: + raise UnexpectedWebhookEventType("helloworld", "test_event") + + webhook_bot_email = 'webhook-bot@zulip.com' + webhook_bot_realm = get_realm('zulip') + + request = HostRequestMock() + request.META['HTTP_AUTHORIZATION'] = self.encode_credentials(webhook_bot_email) + request.method = 'POST' + request.host = "zulip.testserver" + + request.body = '{}' + request.POST['payload'] = '{}' + request.content_type = 'text/plain' + + with mock.patch('zerver.decorator.webhook_unexpected_events_logger.exception') as mock_exception: + exception_msg = "The 'test_event' event isn't currently supported by the helloworld webhook" + with self.assertRaisesRegex(UnexpectedWebhookEventType, exception_msg): + my_webhook_raises_exception(request) # type: ignore # mypy doesn't seem to apply the decorator + + message = """ +user: {email} ({realm}) +client: {client_name} +URL: {path_info} +content_type: {content_type} +custom_http_headers: +{custom_headers} +body: + {body} """ message = message.strip(' ') diff --git a/zproject/settings.py b/zproject/settings.py index bf39a26f4d..8d162fd762 100644 --- a/zproject/settings.py +++ b/zproject/settings.py @@ -1027,6 +1027,7 @@ ZULIP_PATHS = [ ("ANALYTICS_LOG_PATH", "/var/log/zulip/analytics.log"), ("ANALYTICS_LOCK_DIR", "/home/zulip/deployments/analytics-lock-dir"), ("API_KEY_ONLY_WEBHOOK_LOG_PATH", "/var/log/zulip/webhooks_errors.log"), + ("WEBHOOK_UNEXPECTED_EVENTS_LOG_PATH", "/var/log/zulip/webhooks_unexpected_events.log"), ("SOFT_DEACTIVATION_LOG_PATH", "/var/log/zulip/soft_deactivation.log"), ("TRACEMALLOC_DUMP_DIR", "/var/log/zulip/tracemalloc"), ("SCHEDULED_MESSAGE_DELIVERER_LOG_PATH", @@ -1258,6 +1259,11 @@ LOGGING = { 'handlers': ['file', 'errors_file'], 'propagate': False, }, + 'zulip.zerver.lib.webhooks.common': { + 'level': 'DEBUG', + 'handlers': ['file', 'errors_file'], + 'propagate': False, + }, 'zulip.zerver.webhooks': { 'level': 'DEBUG', 'handlers': ['file', 'errors_file'],