paulmataruso/zulip
1
0
Fork 0
mirror of https://github.com/zulip/zulip.git synced 2025-10-24 16:43:57 +00:00
Code Issues Packages Projects Releases Wiki Activity

webhooks: Log unexpected webhook events separately.

Browse Source 
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.
This commit is contained in:
Eeshan Garg
2019-06-06 01:25:09 -02:30
committed by Tim Abbott
parent 4d4b6b8319
commit 8e10ab282a
7 changed files with 135 additions and 21 deletions
Download Patch File Download Diff File Expand all files Collapse all files

3
tools/linter_lib/pyflakes.py
View File

@@ -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",

1
tools/test-backend
View File

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

36
zerver/decorator.py
View File

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

15
zerver/lib/exceptions.py
View File

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

14
zerver/lib/webhooks/common.py
View File

@@ -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']

81
zerver/tests/test_decorators.py
View File

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

6
zproject/settings.py
View File

@@ -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'],