2015-02-27 10:41:52 -05:00
|
|
|
#
|
2023-11-21 15:29:58 -05:00
|
|
|
# This file is licensed under the Affero General Public License (AGPL) version 3.
|
|
|
|
#
|
2024-01-23 06:26:48 -05:00
|
|
|
# Copyright 2015, 2016 OpenMarket Ltd
|
2023-11-21 15:29:58 -05:00
|
|
|
# Copyright (C) 2023 New Vector, Ltd
|
|
|
|
#
|
|
|
|
# This program is free software: you can redistribute it and/or modify
|
|
|
|
# it under the terms of the GNU Affero General Public License as
|
|
|
|
# published by the Free Software Foundation, either version 3 of the
|
|
|
|
# License, or (at your option) any later version.
|
|
|
|
#
|
|
|
|
# See the GNU Affero General Public License for more details:
|
|
|
|
# <https://www.gnu.org/licenses/agpl-3.0.html>.
|
|
|
|
#
|
|
|
|
# Originally licensed under the Apache License, Version 2.0:
|
|
|
|
# <http://www.apache.org/licenses/LICENSE-2.0>.
|
|
|
|
#
|
|
|
|
# [This file includes modifications made by New Vector Limited]
|
2015-02-27 10:41:52 -05:00
|
|
|
#
|
|
|
|
#
|
|
|
|
|
2018-07-09 02:09:20 -04:00
|
|
|
import collections
|
|
|
|
import contextlib
|
|
|
|
import logging
|
2022-08-30 07:08:29 -04:00
|
|
|
import threading
|
2021-09-10 12:03:18 -04:00
|
|
|
import typing
|
2022-08-30 07:08:29 -04:00
|
|
|
from typing import (
|
|
|
|
Any,
|
|
|
|
Callable,
|
2023-08-15 08:11:20 -04:00
|
|
|
ContextManager,
|
2022-08-30 07:08:29 -04:00
|
|
|
DefaultDict,
|
|
|
|
Dict,
|
|
|
|
Iterator,
|
|
|
|
List,
|
|
|
|
Mapping,
|
2023-05-19 06:17:12 -04:00
|
|
|
MutableSet,
|
2022-08-30 07:08:29 -04:00
|
|
|
Optional,
|
|
|
|
Set,
|
|
|
|
Tuple,
|
|
|
|
)
|
2023-05-19 06:17:12 -04:00
|
|
|
from weakref import WeakSet
|
2018-07-09 02:09:20 -04:00
|
|
|
|
2022-08-17 17:10:07 -04:00
|
|
|
from prometheus_client.core import Counter
|
|
|
|
|
2015-02-27 10:41:52 -05:00
|
|
|
from twisted.internet import defer
|
|
|
|
|
|
|
|
from synapse.api.errors import LimitExceededError
|
2022-08-03 05:40:20 -04:00
|
|
|
from synapse.config.ratelimiting import FederationRatelimitSettings
|
2019-07-03 10:07:04 -04:00
|
|
|
from synapse.logging.context import (
|
2018-05-03 06:16:36 -04:00
|
|
|
PreserveLoggingContext,
|
2018-07-09 02:09:20 -04:00
|
|
|
make_deferred_yieldable,
|
|
|
|
run_in_background,
|
2018-05-03 06:16:36 -04:00
|
|
|
)
|
2022-08-15 14:41:23 -04:00
|
|
|
from synapse.logging.opentracing import start_active_span
|
2022-08-18 11:05:07 -04:00
|
|
|
from synapse.metrics import Histogram, LaterGauge
|
2021-09-10 12:03:18 -04:00
|
|
|
from synapse.util import Clock
|
|
|
|
|
|
|
|
if typing.TYPE_CHECKING:
|
|
|
|
from contextlib import _GeneratorContextManager
|
2015-02-27 10:41:52 -05:00
|
|
|
|
|
|
|
logger = logging.getLogger(__name__)
|
|
|
|
|
|
|
|
|
2022-08-17 17:10:07 -04:00
|
|
|
# Track how much the ratelimiter is affecting requests
|
2022-08-30 07:08:29 -04:00
|
|
|
rate_limit_sleep_counter = Counter(
|
|
|
|
"synapse_rate_limit_sleep",
|
|
|
|
"Number of requests slept by the rate limiter",
|
|
|
|
["rate_limiter_name"],
|
|
|
|
)
|
|
|
|
rate_limit_reject_counter = Counter(
|
|
|
|
"synapse_rate_limit_reject",
|
|
|
|
"Number of requests rejected by the rate limiter",
|
|
|
|
["rate_limiter_name"],
|
|
|
|
)
|
2022-08-17 05:38:05 -04:00
|
|
|
queue_wait_timer = Histogram(
|
|
|
|
"synapse_rate_limit_queue_wait_time_seconds",
|
2022-08-30 07:08:29 -04:00
|
|
|
"Amount of time spent waiting for the rate limiter to let our request through.",
|
|
|
|
["rate_limiter_name"],
|
2022-08-17 05:38:05 -04:00
|
|
|
buckets=(
|
|
|
|
0.005,
|
|
|
|
0.01,
|
|
|
|
0.025,
|
|
|
|
0.05,
|
|
|
|
0.1,
|
|
|
|
0.25,
|
|
|
|
0.5,
|
|
|
|
0.75,
|
|
|
|
1.0,
|
|
|
|
2.5,
|
|
|
|
5.0,
|
|
|
|
10.0,
|
|
|
|
20.0,
|
|
|
|
"+Inf",
|
|
|
|
),
|
|
|
|
)
|
|
|
|
|
|
|
|
|
2023-05-19 06:17:12 -04:00
|
|
|
# This must be a `WeakSet`, otherwise we indirectly hold on to entire `HomeServer`s
|
|
|
|
# during trial test runs and leak a lot of memory.
|
|
|
|
_rate_limiter_instances: MutableSet["FederationRateLimiter"] = WeakSet()
|
2022-08-30 07:08:29 -04:00
|
|
|
# Protects the _rate_limiter_instances set from concurrent access
|
|
|
|
_rate_limiter_instances_lock = threading.Lock()
|
|
|
|
|
|
|
|
|
|
|
|
def _get_counts_from_rate_limiter_instance(
|
|
|
|
count_func: Callable[["FederationRateLimiter"], int]
|
|
|
|
) -> Mapping[Tuple[str, ...], int]:
|
|
|
|
"""Returns a count of something (slept/rejected hosts) by (metrics_name)"""
|
|
|
|
# Cast to a list to prevent it changing while the Prometheus
|
|
|
|
# thread is collecting metrics
|
|
|
|
with _rate_limiter_instances_lock:
|
|
|
|
rate_limiter_instances = list(_rate_limiter_instances)
|
|
|
|
|
|
|
|
# Map from (metrics_name,) -> int, the number of something like slept hosts
|
|
|
|
# or rejected hosts. The key type is Tuple[str], but we leave the length
|
|
|
|
# unspecified for compatability with LaterGauge's annotations.
|
|
|
|
counts: Dict[Tuple[str, ...], int] = {}
|
|
|
|
for rate_limiter_instance in rate_limiter_instances:
|
|
|
|
# Only track metrics if they provided a `metrics_name` to
|
|
|
|
# differentiate this instance of the rate limiter.
|
|
|
|
if rate_limiter_instance.metrics_name:
|
|
|
|
key = (rate_limiter_instance.metrics_name,)
|
|
|
|
counts[key] = count_func(rate_limiter_instance)
|
|
|
|
|
|
|
|
return counts
|
|
|
|
|
|
|
|
|
|
|
|
# We track the number of affected hosts per time-period so we can
|
|
|
|
# differentiate one really noisy homeserver from a general
|
|
|
|
# ratelimit tuning problem across the federation.
|
|
|
|
LaterGauge(
|
|
|
|
"synapse_rate_limit_sleep_affected_hosts",
|
|
|
|
"Number of hosts that had requests put to sleep",
|
|
|
|
["rate_limiter_name"],
|
|
|
|
lambda: _get_counts_from_rate_limiter_instance(
|
|
|
|
lambda rate_limiter_instance: sum(
|
|
|
|
ratelimiter.should_sleep()
|
|
|
|
for ratelimiter in rate_limiter_instance.ratelimiters.values()
|
|
|
|
)
|
|
|
|
),
|
|
|
|
)
|
|
|
|
LaterGauge(
|
|
|
|
"synapse_rate_limit_reject_affected_hosts",
|
|
|
|
"Number of hosts that had requests rejected",
|
|
|
|
["rate_limiter_name"],
|
|
|
|
lambda: _get_counts_from_rate_limiter_instance(
|
|
|
|
lambda rate_limiter_instance: sum(
|
|
|
|
ratelimiter.should_reject()
|
|
|
|
for ratelimiter in rate_limiter_instance.ratelimiters.values()
|
|
|
|
)
|
|
|
|
),
|
|
|
|
)
|
|
|
|
|
|
|
|
|
2020-09-04 06:54:56 -04:00
|
|
|
class FederationRateLimiter:
|
2022-08-30 07:08:29 -04:00
|
|
|
"""Used to rate limit request per-host."""
|
|
|
|
|
|
|
|
def __init__(
|
|
|
|
self,
|
|
|
|
clock: Clock,
|
|
|
|
config: FederationRatelimitSettings,
|
|
|
|
metrics_name: Optional[str] = None,
|
|
|
|
):
|
|
|
|
"""
|
|
|
|
Args:
|
|
|
|
clock
|
|
|
|
config
|
|
|
|
metrics_name: The name of the rate limiter so we can differentiate it
|
|
|
|
from the rest in the metrics. If `None`, we don't track metrics
|
|
|
|
for this rate limiter.
|
|
|
|
|
|
|
|
"""
|
|
|
|
self.metrics_name = metrics_name
|
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def new_limiter() -> "_PerHostRatelimiter":
|
2022-08-30 07:08:29 -04:00
|
|
|
return _PerHostRatelimiter(
|
2023-01-16 08:16:19 -05:00
|
|
|
clock=clock, config=config, metrics_name=metrics_name
|
2022-08-30 07:08:29 -04:00
|
|
|
)
|
2019-07-05 06:10:19 -04:00
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
self.ratelimiters: DefaultDict[
|
|
|
|
str, "_PerHostRatelimiter"
|
|
|
|
] = collections.defaultdict(new_limiter)
|
2015-02-27 10:41:52 -05:00
|
|
|
|
2022-08-30 07:08:29 -04:00
|
|
|
with _rate_limiter_instances_lock:
|
|
|
|
_rate_limiter_instances.add(self)
|
2022-08-18 11:05:07 -04:00
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def ratelimit(self, host: str) -> "_GeneratorContextManager[defer.Deferred[None]]":
|
2020-06-05 05:47:20 -04:00
|
|
|
"""Used to ratelimit an incoming request from a given host
|
2015-02-27 10:41:52 -05:00
|
|
|
|
|
|
|
Example usage:
|
|
|
|
|
|
|
|
with rate_limiter.ratelimit(origin) as wait_deferred:
|
|
|
|
yield wait_deferred
|
|
|
|
# Handle request ...
|
|
|
|
|
|
|
|
Args:
|
2022-11-16 10:25:24 -05:00
|
|
|
host: Origin of incoming request.
|
2015-02-27 10:41:52 -05:00
|
|
|
|
|
|
|
Returns:
|
2019-07-05 06:10:19 -04:00
|
|
|
context manager which returns a deferred.
|
2015-02-27 10:41:52 -05:00
|
|
|
"""
|
2022-08-17 17:10:07 -04:00
|
|
|
return self.ratelimiters[host].ratelimit(host)
|
2015-02-27 10:41:52 -05:00
|
|
|
|
|
|
|
|
2020-09-04 06:54:56 -04:00
|
|
|
class _PerHostRatelimiter:
|
2022-08-30 07:08:29 -04:00
|
|
|
def __init__(
|
|
|
|
self,
|
|
|
|
clock: Clock,
|
|
|
|
config: FederationRatelimitSettings,
|
|
|
|
metrics_name: Optional[str] = None,
|
|
|
|
):
|
2019-05-15 13:06:04 -04:00
|
|
|
"""
|
|
|
|
Args:
|
2021-09-10 12:03:18 -04:00
|
|
|
clock
|
|
|
|
config
|
2022-08-30 07:08:29 -04:00
|
|
|
metrics_name: The name of the rate limiter so we can differentiate it
|
|
|
|
from the rest in the metrics. If `None`, we don't track metrics
|
|
|
|
for this rate limiter.
|
|
|
|
from the rest in the metrics
|
2019-05-15 13:06:04 -04:00
|
|
|
"""
|
2015-02-27 10:41:52 -05:00
|
|
|
self.clock = clock
|
2022-08-30 07:08:29 -04:00
|
|
|
self.metrics_name = metrics_name
|
2015-02-27 10:41:52 -05:00
|
|
|
|
2019-05-15 13:06:04 -04:00
|
|
|
self.window_size = config.window_size
|
|
|
|
self.sleep_limit = config.sleep_limit
|
|
|
|
self.sleep_sec = config.sleep_delay / 1000.0
|
|
|
|
self.reject_limit = config.reject_limit
|
|
|
|
self.concurrent_requests = config.concurrent
|
2015-02-27 10:41:52 -05:00
|
|
|
|
2018-07-13 11:19:40 -04:00
|
|
|
# request_id objects for requests which have been slept
|
2021-09-10 12:03:18 -04:00
|
|
|
self.sleeping_requests: Set[object] = set()
|
2018-07-13 11:19:40 -04:00
|
|
|
|
|
|
|
# map from request_id object to Deferred for requests which are ready
|
|
|
|
# for processing but have been queued
|
2021-09-10 12:03:18 -04:00
|
|
|
self.ready_request_queue: collections.OrderedDict[
|
|
|
|
object, defer.Deferred[None]
|
|
|
|
] = collections.OrderedDict()
|
2018-07-13 11:19:40 -04:00
|
|
|
|
|
|
|
# request id objects for requests which are in progress
|
2021-09-10 12:03:18 -04:00
|
|
|
self.current_processing: Set[object] = set()
|
2018-07-13 11:19:40 -04:00
|
|
|
|
|
|
|
# times at which we have recently (within the last window_size ms)
|
|
|
|
# received requests.
|
2021-09-10 12:03:18 -04:00
|
|
|
self.request_times: List[int] = []
|
2015-02-27 10:41:52 -05:00
|
|
|
|
2015-03-02 08:32:44 -05:00
|
|
|
@contextlib.contextmanager
|
2022-08-17 17:10:07 -04:00
|
|
|
def ratelimit(self, host: str) -> "Iterator[defer.Deferred[None]]":
|
2015-03-02 08:32:44 -05:00
|
|
|
# `contextlib.contextmanager` takes a generator and turns it into a
|
|
|
|
# context manager. The generator should only yield once with a value
|
|
|
|
# to be returned by manager.
|
|
|
|
# Exceptions will be reraised at the yield.
|
2015-02-27 10:41:52 -05:00
|
|
|
|
2022-08-17 17:10:07 -04:00
|
|
|
self.host = host
|
|
|
|
|
2015-03-02 08:32:44 -05:00
|
|
|
request_id = object()
|
2022-08-18 11:26:26 -04:00
|
|
|
# Ideally we'd use `Deferred.fromCoroutine()` here, to save on redundant
|
|
|
|
# type-checking, but we'd need Twisted >= 21.2.
|
|
|
|
ret = defer.ensureDeferred(self._on_enter_with_tracing(request_id))
|
2015-03-02 08:32:44 -05:00
|
|
|
try:
|
|
|
|
yield ret
|
|
|
|
finally:
|
|
|
|
self._on_exit(request_id)
|
2015-02-27 10:41:52 -05:00
|
|
|
|
2022-08-18 11:05:07 -04:00
|
|
|
def should_reject(self) -> bool:
|
|
|
|
"""
|
|
|
|
Whether to reject the request if we already have too many queued up
|
|
|
|
(either sleeping or in the ready queue).
|
|
|
|
"""
|
|
|
|
queue_size = len(self.ready_request_queue) + len(self.sleeping_requests)
|
|
|
|
return queue_size > self.reject_limit
|
|
|
|
|
|
|
|
def should_sleep(self) -> bool:
|
|
|
|
"""
|
|
|
|
Whether to sleep the request if we already have too many requests coming
|
|
|
|
through within the window.
|
|
|
|
"""
|
|
|
|
return len(self.request_times) > self.sleep_limit
|
|
|
|
|
2022-08-18 11:26:26 -04:00
|
|
|
async def _on_enter_with_tracing(self, request_id: object) -> None:
|
2022-08-30 07:08:29 -04:00
|
|
|
maybe_metrics_cm: ContextManager = contextlib.nullcontext()
|
|
|
|
if self.metrics_name:
|
|
|
|
maybe_metrics_cm = queue_wait_timer.labels(self.metrics_name).time()
|
|
|
|
with start_active_span("ratelimit wait"), maybe_metrics_cm:
|
2022-08-18 11:26:26 -04:00
|
|
|
await self._on_enter(request_id)
|
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def _on_enter(self, request_id: object) -> "defer.Deferred[None]":
|
2015-02-27 10:41:52 -05:00
|
|
|
time_now = self.clock.time_msec()
|
2018-07-13 11:19:40 -04:00
|
|
|
|
|
|
|
# remove any entries from request_times which aren't within the window
|
2015-02-27 10:41:52 -05:00
|
|
|
self.request_times[:] = [
|
2019-06-20 05:32:02 -04:00
|
|
|
r for r in self.request_times if time_now - r < self.window_size
|
2015-02-27 10:41:52 -05:00
|
|
|
]
|
|
|
|
|
2018-07-13 11:19:40 -04:00
|
|
|
# reject the request if we already have too many queued up (either
|
|
|
|
# sleeping or in the ready queue).
|
2022-08-18 11:05:07 -04:00
|
|
|
if self.should_reject():
|
2022-08-17 17:10:07 -04:00
|
|
|
logger.debug("Ratelimiter(%s): rejecting request", self.host)
|
2022-08-30 07:08:29 -04:00
|
|
|
if self.metrics_name:
|
|
|
|
rate_limit_reject_counter.labels(self.metrics_name).inc()
|
2015-02-27 10:41:52 -05:00
|
|
|
raise LimitExceededError(
|
2023-08-29 19:39:39 -04:00
|
|
|
limiter_name="rc_federation",
|
|
|
|
retry_after_ms=int(self.window_size / self.sleep_limit),
|
2015-02-27 10:41:52 -05:00
|
|
|
)
|
|
|
|
|
|
|
|
self.request_times.append(time_now)
|
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def queue_request() -> "defer.Deferred[None]":
|
2019-07-05 06:10:19 -04:00
|
|
|
if len(self.current_processing) >= self.concurrent_requests:
|
2021-09-10 12:03:18 -04:00
|
|
|
queue_defer: defer.Deferred[None] = defer.Deferred()
|
2015-02-27 10:41:52 -05:00
|
|
|
self.ready_request_queue[request_id] = queue_defer
|
2018-07-13 11:19:40 -04:00
|
|
|
logger.info(
|
2022-08-17 17:10:07 -04:00
|
|
|
"Ratelimiter(%s): queueing request (queue now %i items)",
|
|
|
|
self.host,
|
2018-07-13 11:19:40 -04:00
|
|
|
len(self.ready_request_queue),
|
|
|
|
)
|
|
|
|
|
2015-02-27 10:41:52 -05:00
|
|
|
return queue_defer
|
|
|
|
else:
|
|
|
|
return defer.succeed(None)
|
|
|
|
|
|
|
|
logger.debug(
|
2022-08-17 17:10:07 -04:00
|
|
|
"Ratelimit(%s) [%s]: len(self.request_times)=%d",
|
|
|
|
self.host,
|
2019-06-20 05:32:02 -04:00
|
|
|
id(request_id),
|
|
|
|
len(self.request_times),
|
2015-02-27 10:41:52 -05:00
|
|
|
)
|
|
|
|
|
2022-08-18 11:05:07 -04:00
|
|
|
if self.should_sleep():
|
2022-08-17 17:10:07 -04:00
|
|
|
logger.debug(
|
|
|
|
"Ratelimiter(%s) [%s]: sleeping request for %f sec",
|
|
|
|
self.host,
|
|
|
|
id(request_id),
|
|
|
|
self.sleep_sec,
|
|
|
|
)
|
2022-08-30 07:08:29 -04:00
|
|
|
if self.metrics_name:
|
|
|
|
rate_limit_sleep_counter.labels(self.metrics_name).inc()
|
2018-07-13 11:19:40 -04:00
|
|
|
ret_defer = run_in_background(self.clock.sleep, self.sleep_sec)
|
2015-02-27 10:41:52 -05:00
|
|
|
|
|
|
|
self.sleeping_requests.add(request_id)
|
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def on_wait_finished(_: Any) -> "defer.Deferred[None]":
|
2022-08-17 17:10:07 -04:00
|
|
|
logger.debug(
|
|
|
|
"Ratelimit(%s) [%s]: Finished sleeping", self.host, id(request_id)
|
|
|
|
)
|
2015-02-27 10:41:52 -05:00
|
|
|
self.sleeping_requests.discard(request_id)
|
|
|
|
queue_defer = queue_request()
|
|
|
|
return queue_defer
|
|
|
|
|
|
|
|
ret_defer.addBoth(on_wait_finished)
|
|
|
|
else:
|
|
|
|
ret_defer = queue_request()
|
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def on_start(r: object) -> object:
|
2022-08-17 17:10:07 -04:00
|
|
|
logger.debug(
|
|
|
|
"Ratelimit(%s) [%s]: Processing req", self.host, id(request_id)
|
|
|
|
)
|
2015-02-27 10:41:52 -05:00
|
|
|
self.current_processing.add(request_id)
|
|
|
|
return r
|
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def on_err(r: object) -> object:
|
2018-05-03 06:16:36 -04:00
|
|
|
# XXX: why is this necessary? this is called before we start
|
|
|
|
# processing the request so why would the request be in
|
|
|
|
# current_processing?
|
2015-02-27 10:41:52 -05:00
|
|
|
self.current_processing.discard(request_id)
|
|
|
|
return r
|
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def on_both(r: object) -> object:
|
2015-02-27 10:41:52 -05:00
|
|
|
# Ensure that we've properly cleaned up.
|
|
|
|
self.sleeping_requests.discard(request_id)
|
|
|
|
self.ready_request_queue.pop(request_id, None)
|
|
|
|
return r
|
|
|
|
|
|
|
|
ret_defer.addCallbacks(on_start, on_err)
|
|
|
|
ret_defer.addBoth(on_both)
|
2018-05-03 06:16:36 -04:00
|
|
|
return make_deferred_yieldable(ret_defer)
|
2015-02-27 10:41:52 -05:00
|
|
|
|
2021-09-10 12:03:18 -04:00
|
|
|
def _on_exit(self, request_id: object) -> None:
|
2022-08-17 17:10:07 -04:00
|
|
|
logger.debug("Ratelimit(%s) [%s]: Processed req", self.host, id(request_id))
|
2018-05-03 06:16:36 -04:00
|
|
|
|
2023-01-12 19:16:21 -05:00
|
|
|
# When requests complete synchronously, we will recursively start the next
|
|
|
|
# request in the queue. To avoid stack exhaustion, we defer starting the next
|
|
|
|
# request until the next reactor tick.
|
|
|
|
|
|
|
|
def start_next_request() -> None:
|
|
|
|
# We only remove the completed request from the list when we're about to
|
|
|
|
# start the next one, otherwise we can allow extra requests through.
|
|
|
|
self.current_processing.discard(request_id)
|
|
|
|
try:
|
|
|
|
# start processing the next item on the queue.
|
|
|
|
_, deferred = self.ready_request_queue.popitem(last=False)
|
|
|
|
|
|
|
|
with PreserveLoggingContext():
|
|
|
|
deferred.callback(None)
|
|
|
|
except KeyError:
|
|
|
|
pass
|
|
|
|
|
2023-01-16 08:16:19 -05:00
|
|
|
self.clock.call_later(0.0, start_next_request)
|