From c53f9d561e95cd8c0996effcb89b09011a17be8b Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Wed, 13 Apr 2016 11:11:46 +0100 Subject: [PATCH 1/2] Don't auto log failed auth checks --- synapse/api/auth.py | 98 ++++++++++++++++------------------ synapse/handlers/_base.py | 6 ++- synapse/handlers/federation.py | 34 +++++++++--- 3 files changed, 76 insertions(+), 62 deletions(-) diff --git a/synapse/api/auth.py b/synapse/api/auth.py index 4f9c3c9db..12f753e7c 100644 --- a/synapse/api/auth.py +++ b/synapse/api/auth.py @@ -68,72 +68,64 @@ class Auth(object): """ self.check_size_limits(event) - try: - if not hasattr(event, "room_id"): - raise AuthError(500, "Event has no room_id: %s" % event) - if auth_events is None: - # Oh, we don't know what the state of the room was, so we - # are trusting that this is allowed (at least for now) - logger.warn("Trusting event: %s", event.event_id) - return True + if not hasattr(event, "room_id"): + raise AuthError(500, "Event has no room_id: %s" % event) + if auth_events is None: + # Oh, we don't know what the state of the room was, so we + # are trusting that this is allowed (at least for now) + logger.warn("Trusting event: %s", event.event_id) + return True - if event.type == EventTypes.Create: - # FIXME - return True + if event.type == EventTypes.Create: + # FIXME + return True - creation_event = auth_events.get((EventTypes.Create, ""), None) + creation_event = auth_events.get((EventTypes.Create, ""), None) - if not creation_event: - raise SynapseError( + if not creation_event: + raise SynapseError( + 403, + "Room %r does not exist" % (event.room_id,) + ) + + creating_domain = RoomID.from_string(event.room_id).domain + originating_domain = UserID.from_string(event.sender).domain + if creating_domain != originating_domain: + if not self.can_federate(event, auth_events): + raise AuthError( 403, - "Room %r does not exist" % (event.room_id,) + "This room has been marked as unfederatable." ) - creating_domain = RoomID.from_string(event.room_id).domain - originating_domain = UserID.from_string(event.sender).domain - if creating_domain != originating_domain: - if not self.can_federate(event, auth_events): - raise AuthError( - 403, - "This room has been marked as unfederatable." - ) + # FIXME: Temp hack + if event.type == EventTypes.Aliases: + return True - # FIXME: Temp hack - if event.type == EventTypes.Aliases: - return True + logger.debug( + "Auth events: %s", + [a.event_id for a in auth_events.values()] + ) - logger.debug( - "Auth events: %s", - [a.event_id for a in auth_events.values()] + if event.type == EventTypes.Member: + allowed = self.is_membership_change_allowed( + event, auth_events ) + if allowed: + logger.debug("Allowing! %s", event) + else: + logger.debug("Denying! %s", event) + return allowed - if event.type == EventTypes.Member: - allowed = self.is_membership_change_allowed( - event, auth_events - ) - if allowed: - logger.debug("Allowing! %s", event) - else: - logger.debug("Denying! %s", event) - return allowed + self.check_event_sender_in_room(event, auth_events) + self._can_send_event(event, auth_events) - self.check_event_sender_in_room(event, auth_events) - self._can_send_event(event, auth_events) + if event.type == EventTypes.PowerLevels: + self._check_power_levels(event, auth_events) - if event.type == EventTypes.PowerLevels: - self._check_power_levels(event, auth_events) + if event.type == EventTypes.Redaction: + self.check_redaction(event, auth_events) - if event.type == EventTypes.Redaction: - self.check_redaction(event, auth_events) - - logger.debug("Allowing! %s", event) - except AuthError as e: - logger.info( - "Event auth check failed on event %s with msg: %s", - event, e.msg - ) - logger.info("Denying! %s", event) - raise + logger.debug("Allowing! %s", event) def check_size_limits(self, event): def too_big(field): diff --git a/synapse/handlers/_base.py b/synapse/handlers/_base.py index aaf6b1b83..13a675b20 100644 --- a/synapse/handlers/_base.py +++ b/synapse/handlers/_base.py @@ -316,7 +316,11 @@ class BaseHandler(object): if ratelimit: self.ratelimit(requester) - self.auth.check(event, auth_events=context.current_state) + try: + self.auth.check(event, auth_events=context.current_state) + except AuthError as err: + logger.warn("Denying new event %r because %s", event, err) + raise err yield self.maybe_kick_guest_users(event, context.current_state.values()) diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py index 5ac55e10f..d95e0b23b 100644 --- a/synapse/handlers/federation.py +++ b/synapse/handlers/federation.py @@ -681,9 +681,13 @@ class FederationHandler(BaseHandler): "state_key": user_id, }) - event, context = yield self._create_new_client_event( - builder=builder, - ) + try: + event, context = yield self._create_new_client_event( + builder=builder, + ) + except AuthError as e: + logger.warn("Failed to create join %r because %s", event, e) + raise e self.auth.check(event, auth_events=context.current_state) @@ -915,7 +919,11 @@ class FederationHandler(BaseHandler): builder=builder, ) - self.auth.check(event, auth_events=context.current_state) + try: + self.auth.check(event, auth_events=context.current_state) + except AuthError as e: + logger.warn("Failed to create new leave %r because %s", event, e) + raise e defer.returnValue(event) @@ -1512,8 +1520,9 @@ class FederationHandler(BaseHandler): try: self.auth.check(event, auth_events=auth_events) - except AuthError: - raise + except AuthError as e: + logger.warn("Failed auth resolution for %r because %s", event, e) + raise e @defer.inlineCallbacks def construct_auth_difference(self, local_auth, remote_auth): @@ -1689,7 +1698,12 @@ class FederationHandler(BaseHandler): event_dict, event, context ) - self.auth.check(event, context.current_state) + try: + self.auth.check(event, context.current_state) + except AuthError as e: + logger.warn("Denying new third party invite %r because %s", event, e) + raise e + yield self._check_signature(event, auth_events=context.current_state) member_handler = self.hs.get_handlers().room_member_handler yield member_handler.send_membership_event(None, event, context) @@ -1714,7 +1728,11 @@ class FederationHandler(BaseHandler): event_dict, event, context ) - self.auth.check(event, auth_events=context.current_state) + try: + self.auth.check(event, auth_events=context.current_state) + except AuthError as e: + logger.warn("Denying third party invite %r because %s", event, e) + raise e yield self._check_signature(event, auth_events=context.current_state) returned_invite = yield self.send_invite(origin, event) From 0f2ca8cde1b731bc4eafc074d11829cab95aa1aa Mon Sep 17 00:00:00 2001 From: Erik Johnston Date: Wed, 13 Apr 2016 11:15:59 +0100 Subject: [PATCH 2/2] Measure Auth.check --- synapse/api/auth.py | 95 +++++++++++++++++++++++---------------------- 1 file changed, 49 insertions(+), 46 deletions(-) diff --git a/synapse/api/auth.py b/synapse/api/auth.py index 12f753e7c..9e912fdfb 100644 --- a/synapse/api/auth.py +++ b/synapse/api/auth.py @@ -25,6 +25,7 @@ from synapse.api.errors import AuthError, Codes, SynapseError, EventSizeError from synapse.types import Requester, RoomID, UserID, EventID from synapse.util.logutils import log_function from synapse.util.logcontext import preserve_context_over_fn +from synapse.util.metrics import Measure from unpaddedbase64 import decode_base64 import logging @@ -44,6 +45,7 @@ class Auth(object): def __init__(self, hs): self.hs = hs + self.clock = hs.get_clock() self.store = hs.get_datastore() self.state = hs.get_state_handler() self.TOKEN_NOT_FOUND_HTTP_STATUS = 401 @@ -66,66 +68,67 @@ class Auth(object): Returns: True if the auth checks pass. """ - self.check_size_limits(event) + with Measure(self.clock, "auth.check"): + self.check_size_limits(event) - if not hasattr(event, "room_id"): - raise AuthError(500, "Event has no room_id: %s" % event) - if auth_events is None: - # Oh, we don't know what the state of the room was, so we - # are trusting that this is allowed (at least for now) - logger.warn("Trusting event: %s", event.event_id) - return True + if not hasattr(event, "room_id"): + raise AuthError(500, "Event has no room_id: %s" % event) + if auth_events is None: + # Oh, we don't know what the state of the room was, so we + # are trusting that this is allowed (at least for now) + logger.warn("Trusting event: %s", event.event_id) + return True - if event.type == EventTypes.Create: - # FIXME - return True + if event.type == EventTypes.Create: + # FIXME + return True - creation_event = auth_events.get((EventTypes.Create, ""), None) + creation_event = auth_events.get((EventTypes.Create, ""), None) - if not creation_event: - raise SynapseError( - 403, - "Room %r does not exist" % (event.room_id,) - ) - - creating_domain = RoomID.from_string(event.room_id).domain - originating_domain = UserID.from_string(event.sender).domain - if creating_domain != originating_domain: - if not self.can_federate(event, auth_events): - raise AuthError( + if not creation_event: + raise SynapseError( 403, - "This room has been marked as unfederatable." + "Room %r does not exist" % (event.room_id,) ) - # FIXME: Temp hack - if event.type == EventTypes.Aliases: - return True + creating_domain = RoomID.from_string(event.room_id).domain + originating_domain = UserID.from_string(event.sender).domain + if creating_domain != originating_domain: + if not self.can_federate(event, auth_events): + raise AuthError( + 403, + "This room has been marked as unfederatable." + ) - logger.debug( - "Auth events: %s", - [a.event_id for a in auth_events.values()] - ) + # FIXME: Temp hack + if event.type == EventTypes.Aliases: + return True - if event.type == EventTypes.Member: - allowed = self.is_membership_change_allowed( - event, auth_events + logger.debug( + "Auth events: %s", + [a.event_id for a in auth_events.values()] ) - if allowed: - logger.debug("Allowing! %s", event) - else: - logger.debug("Denying! %s", event) - return allowed - self.check_event_sender_in_room(event, auth_events) - self._can_send_event(event, auth_events) + if event.type == EventTypes.Member: + allowed = self.is_membership_change_allowed( + event, auth_events + ) + if allowed: + logger.debug("Allowing! %s", event) + else: + logger.debug("Denying! %s", event) + return allowed - if event.type == EventTypes.PowerLevels: - self._check_power_levels(event, auth_events) + self.check_event_sender_in_room(event, auth_events) + self._can_send_event(event, auth_events) - if event.type == EventTypes.Redaction: - self.check_redaction(event, auth_events) + if event.type == EventTypes.PowerLevels: + self._check_power_levels(event, auth_events) - logger.debug("Allowing! %s", event) + if event.type == EventTypes.Redaction: + self.check_redaction(event, auth_events) + + logger.debug("Allowing! %s", event) def check_size_limits(self, event): def too_big(field):