def _finished_processing(self): """Log the completion of this request and update the metrics""" assert self.logcontext is not None usage = self.logcontext.get_resource_usage() if self._processing_finished_time is None: # we completed the request without anything calling processing() self._processing_finished_time = time.time() # the time between receiving the request and the request handler finishing processing_time = self._processing_finished_time - self.start_time # the time between the request handler finishing and the response being sent # to the client (nb may be negative) response_send_time = self.finish_time - self._processing_finished_time user_agent = get_request_user_agent(self, "-") code = str(self.code) if not self.finished: # we didn't send the full response before we gave up (presumably because # the connection dropped) code += "!" log_level = logging.INFO if self._should_log_request() else logging.DEBUG # If this is a request where the target user doesn't match the user who # authenticated (e.g. and admin is puppetting a user) then we log both. requester, authenticated_entity = self.get_authenticated_entity() if authenticated_entity: requester = "{}.{}".format(authenticated_entity, requester) self.site.access_logger.log( log_level, "%s - %s - {%s}" " Processed request: %.3fsec/%.3fsec (%.3fsec, %.3fsec) (%.3fsec/%.3fsec/%d)" ' %sB %s "%s %s %s" "%s" [%d dbevts]', self.getClientIP(), self.site.site_tag, requester, processing_time, response_send_time, usage.ru_utime, usage.ru_stime, usage.db_sched_duration_sec, usage.db_txn_duration_sec, int(usage.db_txn_count), self.sentLength, code, self.get_method(), self.get_redacted_uri(), self.clientproto.decode("ascii", errors="replace"), user_agent, usage.evt_db_fetch_count, ) try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) except Exception as e: logger.warning("Failed to stop metrics: %r", e)
async def handle_submit_username_request(self, request: SynapseRequest, localpart: str, session_id: str) -> None: """Handle a request to the username-picker 'submit' endpoint Will serve an HTTP response to the request. Args: request: HTTP request localpart: localpart requested by the user session_id: ID of the username mapping session, extracted from a cookie """ self._expire_old_sessions() session = self._username_mapping_sessions.get(session_id) if not session: logger.info("Couldn't find session id %s", session_id) raise SynapseError(400, "unknown session") logger.info("[session %s] Registering localpart %s", session_id, localpart) attributes = UserAttributes( localpart=localpart, display_name=session.display_name, emails=session.emails, ) # the following will raise a 400 error if the username has been taken in the # meantime. user_id = await self._register_mapped_user( attributes, session.auth_provider_id, session.remote_user_id, get_request_user_agent(request), request.getClientIP(), ) logger.info("[session %s] Registered userid %s", session_id, user_id) # delete the mapping session and the cookie del self._username_mapping_sessions[session_id] # delete the cookie request.addCookie( USERNAME_MAPPING_SESSION_COOKIE_NAME, b"", expires=b"Thu, 01 Jan 1970 00:00:00 GMT", path=b"/", ) await self._auth_handler.complete_sso_login( user_id, request, session.client_redirect_url, session.extra_login_attributes, )
def render(self, resrc: Resource) -> None: # this is called once a Resource has been found to serve the request; in our # case the Resource in question will normally be a JsonResource. # create a LogContext for this request request_id = self.get_request_id() self.logcontext = LoggingContext( request_id, request=ContextRequest( request_id=request_id, ip_address=self.getClientAddress().host, site_tag=self.synapse_site.site_tag, # The requester is going to be unknown at this point. requester=None, authenticated_entity=None, method=self.get_method(), url=self.get_redacted_uri(), protocol=self.clientproto.decode("ascii", errors="replace"), user_agent=get_request_user_agent(self), ), ) # override the Server header which is set by twisted self.setHeader("Server", self.synapse_site.server_version_string) with PreserveLoggingContext(self.logcontext): # we start the request metrics timer here with an initial stab # at the servlet name. For most requests that name will be # JsonResource (or a subclass), and JsonResource._async_render # will update it once it picks a servlet. servlet_name = resrc.__class__.__name__ self._started_processing(servlet_name) Request.render(self, resrc) # record the arrival of the request *after* # dispatching to the handler, so that the handler # can update the servlet name in the request # metrics requests_counter.labels(self.get_method(), self.request_metrics.name).inc()
async def on_POST(self, request: SynapseRequest, room_id: str, receipt_type: str, event_id: str) -> Tuple[int, JsonDict]: requester = await self.auth.get_user_by_req(request) if receipt_type != ReceiptTypes.READ: raise SynapseError(400, "Receipt type must be 'm.read'") # Do not allow older SchildiChat and Element Android clients (prior to Element/1.[012].x) to send an empty body. user_agent = get_request_user_agent(request) allow_empty_body = False if "Android" in user_agent: if pattern.match(user_agent) or "Riot" in user_agent: allow_empty_body = True body = parse_json_object_from_request(request, allow_empty_body) hidden = body.get(ReadReceiptEventFields.MSC2285_HIDDEN, False) if not isinstance(hidden, bool): raise SynapseError( 400, "Param %s must be a boolean, if given" % ReadReceiptEventFields.MSC2285_HIDDEN, Codes.BAD_JSON, ) await self.presence_handler.bump_presence_active_time(requester.user) await self.receipts_handler.received_client_receipt( room_id, receipt_type, user_id=requester.user.to_string(), event_id=event_id, hidden=hidden, ) return 200, {}
async def get_user_by_req( self, request: SynapseRequest, allow_guest: bool = False, rights: str = "access", allow_expired: bool = False, ) -> Requester: """Get a registered user's ID. Args: request: An HTTP request with an access_token query parameter. allow_guest: If False, will raise an AuthError if the user making the request is a guest. rights: The operation being performed; the access token must allow this allow_expired: If True, allow the request through even if the account is expired, or session token lifetime has ended. Note that /login will deliver access tokens regardless of expiration. Returns: Resolves to the requester Raises: InvalidClientCredentialsError if no user by that token exists or the token is invalid. AuthError if access is denied for the user in the access token """ try: ip_addr = request.getClientIP() user_agent = get_request_user_agent(request) access_token = self.get_access_token_from_request(request) user_id, app_service = await self._get_appservice_user_id(request) if user_id and app_service: if ip_addr and self._track_appservice_user_ips: await self.store.insert_client_ip( user_id=user_id, access_token=access_token, ip=ip_addr, user_agent=user_agent, device_id="dummy-device", # stubbed ) requester = create_requester(user_id, app_service=app_service) request.requester = user_id if user_id in self._force_tracing_for_users: opentracing.set_tag(opentracing.tags.SAMPLING_PRIORITY, 1) opentracing.set_tag("authenticated_entity", user_id) opentracing.set_tag("user_id", user_id) opentracing.set_tag("appservice_id", app_service.id) return requester user_info = await self.get_user_by_access_token( access_token, rights, allow_expired=allow_expired) token_id = user_info.token_id is_guest = user_info.is_guest shadow_banned = user_info.shadow_banned # Deny the request if the user account has expired. if self._account_validity_enabled and not allow_expired: if await self.store.is_account_expired(user_info.user_id, self.clock.time_msec()): raise AuthError(403, "User account has expired", errcode=Codes.EXPIRED_ACCOUNT) device_id = user_info.device_id if access_token and ip_addr: await self.store.insert_client_ip( user_id=user_info.token_owner, access_token=access_token, ip=ip_addr, user_agent=user_agent, device_id=device_id, ) if is_guest and not allow_guest: raise AuthError( 403, "Guest access not allowed", errcode=Codes.GUEST_ACCESS_FORBIDDEN, ) requester = create_requester( user_info.user_id, token_id, is_guest, shadow_banned, device_id, app_service=app_service, authenticated_entity=user_info.token_owner, ) request.requester = requester if user_info.token_owner in self._force_tracing_for_users: opentracing.set_tag(opentracing.tags.SAMPLING_PRIORITY, 1) opentracing.set_tag("authenticated_entity", user_info.token_owner) opentracing.set_tag("user_id", user_info.user_id) if device_id: opentracing.set_tag("device_id", device_id) return requester except KeyError: raise MissingClientTokenError()
async def complete_sso_login_request( self, auth_provider_id: str, remote_user_id: str, request: SynapseRequest, client_redirect_url: str, sso_to_matrix_id_mapper: Callable[[int], Awaitable[UserAttributes]], grandfather_existing_users: Callable[[], Awaitable[Optional[str]]], extra_login_attributes: Optional[JsonDict] = None, ) -> None: """ Given an SSO ID, retrieve the user ID for it and possibly register the user. This first checks if the SSO ID has previously been linked to a matrix ID, if it has that matrix ID is returned regardless of the current mapping logic. If a callable is provided for grandfathering users, it is called and can potentially return a matrix ID to use. If it does, the SSO ID is linked to this matrix ID for subsequent calls. The mapping function is called (potentially multiple times) to generate a localpart for the user. If an unused localpart is generated, the user is registered from the given user-agent and IP address and the SSO ID is linked to this matrix ID for subsequent calls. Finally, we generate a redirect to the supplied redirect uri, with a login token Args: auth_provider_id: A unique identifier for this SSO provider, e.g. "oidc" or "saml". remote_user_id: The unique identifier from the SSO provider. request: The request to respond to client_redirect_url: The redirect URL passed in by the client. sso_to_matrix_id_mapper: A callable to generate the user attributes. The only parameter is an integer which represents the amount of times the returned mxid localpart mapping has failed. It is expected that the mapper can raise two exceptions, which will get passed through to the caller: MappingException if there was a problem mapping the response to the user. RedirectException to redirect to an additional page (e.g. to prompt the user for more information). grandfather_existing_users: A callable which can return an previously existing matrix ID. The SSO ID is then linked to the returned matrix ID. extra_login_attributes: An optional dictionary of extra attributes to be provided to the client in the login response. Raises: MappingException if there was a problem mapping the response to a user. RedirectException: if the mapping provider needs to redirect the user to an additional page. (e.g. to prompt for more information) """ # grab a lock while we try to find a mapping for this user. This seems... # optimistic, especially for implementations that end up redirecting to # interstitial pages. with await self._mapping_lock.queue(auth_provider_id): # first of all, check if we already have a mapping for this user user_id = await self.get_sso_user_by_remote_user_id( auth_provider_id, remote_user_id, ) # Check for grandfathering of users. if not user_id: user_id = await grandfather_existing_users() if user_id: # Future logins should also match this user ID. await self._store.record_user_external_id( auth_provider_id, remote_user_id, user_id) # Otherwise, generate a new user. if not user_id: attributes = await self._call_attribute_mapper( sso_to_matrix_id_mapper) if attributes.localpart is None: # the mapper doesn't return a username. bail out with a redirect to # the username picker. await self._redirect_to_username_picker( auth_provider_id, remote_user_id, attributes, client_redirect_url, extra_login_attributes, ) user_id = await self._register_mapped_user( attributes, auth_provider_id, remote_user_id, get_request_user_agent(request), request.getClientIP(), ) await self._auth_handler.complete_sso_login(user_id, request, client_redirect_url, extra_login_attributes)
async def register_sso_user(self, request: Request, session_id: str) -> None: """Called once we have all the info we need to register a new user. Does so and serves an HTTP response Args: request: HTTP request session_id: ID of the username mapping session, extracted from a cookie """ try: session = self.get_mapping_session(session_id) except SynapseError as e: self.render_error(request, "bad_session", e.msg, code=e.code) return logger.info( "[session %s] Registering localpart %s", session_id, session.chosen_localpart, ) attributes = UserAttributes( localpart=session.chosen_localpart, emails=session.emails_to_use, ) if session.use_display_name: attributes.display_name = session.display_name # the following will raise a 400 error if the username has been taken in the # meantime. user_id = await self._register_mapped_user( attributes, session.auth_provider_id, session.remote_user_id, get_request_user_agent(request), request.getClientIP(), ) logger.info( "[session %s] Registered userid %s with attributes %s", session_id, user_id, attributes, ) # delete the mapping session and the cookie del self._username_mapping_sessions[session_id] # delete the cookie request.addCookie( USERNAME_MAPPING_SESSION_COOKIE_NAME, b"", expires=b"Thu, 01 Jan 1970 00:00:00 GMT", path=b"/", ) auth_result = {} if session.terms_accepted_version: # TODO: make this less awful. auth_result[LoginType.TERMS] = True await self._registration_handler.post_registration_actions( user_id, auth_result, access_token=None) await self._auth_handler.complete_sso_login( user_id, session.auth_provider_id, request, session.client_redirect_url, session.extra_login_attributes, new_user=True, )
async def _wrapped_get_user_by_req( self, request: SynapseRequest, allow_guest: bool, allow_expired: bool, ) -> Requester: """Helper for get_user_by_req Once get_user_by_req has set up the opentracing span, this does the actual work. """ try: ip_addr = request.getClientAddress().host user_agent = get_request_user_agent(request) access_token = self.get_access_token_from_request(request) ( user_id, device_id, app_service, ) = await self._get_appservice_user_id_and_device_id(request) if user_id and app_service: if ip_addr and self._track_appservice_user_ips: await self.store.insert_client_ip( user_id=user_id, access_token=access_token, ip=ip_addr, user_agent=user_agent, device_id="dummy-device" if device_id is None else device_id, # stubbed ) requester = create_requester(user_id, app_service=app_service, device_id=device_id) request.requester = user_id return requester user_info = await self.get_user_by_access_token( access_token, allow_expired=allow_expired) token_id = user_info.token_id is_guest = user_info.is_guest shadow_banned = user_info.shadow_banned # Deny the request if the user account has expired. if not allow_expired: if await self._account_validity_handler.is_user_expired( user_info.user_id): # Raise the error if either an account validity module has determined # the account has expired, or the legacy account validity # implementation is enabled and determined the account has expired raise AuthError( 403, "User account has expired", errcode=Codes.EXPIRED_ACCOUNT, ) device_id = user_info.device_id if access_token and ip_addr: await self.store.insert_client_ip( user_id=user_info.token_owner, access_token=access_token, ip=ip_addr, user_agent=user_agent, device_id=device_id, ) # Track also the puppeted user client IP if enabled and the user is puppeting if (user_info.user_id != user_info.token_owner and self._track_puppeted_user_ips): await self.store.insert_client_ip( user_id=user_info.user_id, access_token=access_token, ip=ip_addr, user_agent=user_agent, device_id=device_id, ) if is_guest and not allow_guest: raise AuthError( 403, "Guest access not allowed", errcode=Codes.GUEST_ACCESS_FORBIDDEN, ) # Mark the token as used. This is used to invalidate old refresh # tokens after some time. if not user_info.token_used and token_id is not None: await self.store.mark_access_token_as_used(token_id) requester = create_requester( user_info.user_id, token_id, is_guest, shadow_banned, device_id, app_service=app_service, authenticated_entity=user_info.token_owner, ) request.requester = requester return requester except KeyError: raise MissingClientTokenError()
def _finished_processing(self) -> None: """Log the completion of this request and update the metrics""" assert self.logcontext is not None assert self.finish_time is not None usage = self.logcontext.get_resource_usage() if self._processing_finished_time is None: # we completed the request without anything calling processing() self._processing_finished_time = time.time() # the time between receiving the request and the request handler finishing processing_time = self._processing_finished_time - self.start_time # the time between the request handler finishing and the response being sent # to the client (nb may be negative) response_send_time = self.finish_time - self._processing_finished_time user_agent = get_request_user_agent(self, "-") # int(self.code) looks redundant, because self.code is already an int. # But self.code might be an HTTPStatus (which inherits from int)---which has # a different string representation. So ensure we really have an integer. code = str(int(self.code)) if not self.finished: # we didn't send the full response before we gave up (presumably because # the connection dropped) code += "!" log_level = logging.INFO if self._should_log_request( ) else logging.DEBUG # If this is a request where the target user doesn't match the user who # authenticated (e.g. and admin is puppetting a user) then we log both. requester, authenticated_entity = self.get_authenticated_entity() if authenticated_entity: requester = f"{authenticated_entity}|{requester}" self.synapse_site.access_logger.log( log_level, "%s - %s - {%s}" " Processed request: %.3fsec/%.3fsec (%.3fsec, %.3fsec) (%.3fsec/%.3fsec/%d)" ' %sB %s "%s %s %s" "%s" [%d dbevts]', self.getClientAddress().host, self.synapse_site.site_tag, requester, processing_time, response_send_time, usage.ru_utime, usage.ru_stime, usage.db_sched_duration_sec, usage.db_txn_duration_sec, int(usage.db_txn_count), self.sentLength, code, self.get_method(), self.get_redacted_uri(), self.clientproto.decode("ascii", errors="replace"), user_agent, usage.evt_db_fetch_count, ) # complete the opentracing span, if any. if self._opentracing_span: self._opentracing_span.finish() try: self.request_metrics.stop(self.finish_time, self.code, self.sentLength) except Exception as e: logger.warning("Failed to stop metrics: %r", e)