def test_redis_cluster_reset(self):
storage = RedisClusterStorage("redis+cluster://localhost:7000")
limiter = FixedWindowRateLimiter(storage)
for i in range(0, 10000):
rate = RateLimitItemPerMinute(i)
limiter.hit(rate)
self.assertEqual(storage.reset(), 10000)
def test_redis_sentinel_reset(self):
storage = RedisSentinelStorage("redis+sentinel://localhost:26379", service_name="localhost-redis-sentinel")
limiter = FixedWindowRateLimiter(storage)
for i in range(0, 10000):
rate = RateLimitItemPerMinute(i)
limiter.hit(rate)
self.assertEqual(storage.reset(), 10000)
def test_redis_cluster_reset(self):
storage = RedisClusterStorage("redis+cluster://localhost:7000")
limiter = FixedWindowRateLimiter(storage)
for i in range(0, 10000):
rate = RateLimitItemPerMinute(i)
limiter.hit(rate)
self.assertEqual(storage.reset(), 10000)
def test_redis_sentinel_reset(self):
storage = RedisSentinelStorage("redis+sentinel://localhost:26379",
service_name="localhost-redis-sentinel")
limiter = FixedWindowRateLimiter(storage)
for i in range(0, 10000):
rate = RateLimitItemPerMinute(i)
limiter.hit(rate)
self.assertEqual(storage.reset(), 10000)
def _setup_logger(self):
self._logger = get_logger(self.name)
# rate limit our own messages to not spam around in case of temporary network errors, etc
rate_limit_setting = constants.ERROR_LOG_RATE_LIMIT
if rate_limit_setting:
self._rate_limit_storage = MemoryStorage()
self._rate_limit_strategy = FixedWindowRateLimiter(self._rate_limit_storage)
self._rate_limit_item = parse_rate_limit(rate_limit_setting)
def test_in_memory(self):
with hiro.Timeline().freeze() as timeline:
limiter = FixedWindowRateLimiter(self.storage)
per_min = RateLimitItemPerMinute(10)
for i in range(0, 10):
self.assertTrue(limiter.hit(per_min))
self.assertFalse(limiter.hit(per_min))
timeline.forward(61)
self.assertTrue(limiter.hit(per_min))
def test_in_memory(self):
with hiro.Timeline().freeze() as timeline:
storage = MemoryStorage()
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerMinute(10)
for i in range(0,10):
self.assertTrue(limiter.hit(per_min))
self.assertFalse(limiter.hit(per_min))
timeline.forward(61)
self.assertTrue(limiter.hit(per_min))
def test_in_memory_reset(self):
storage = MemoryStorage()
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerMinute(10)
for i in range(0,10):
self.assertTrue(limiter.hit(per_min))
self.assertFalse(limiter.hit(per_min))
storage.reset()
for i in range(0,10):
self.assertTrue(limiter.hit(per_min))
self.assertFalse(limiter.hit(per_min))
def test_expiry(self):
with hiro.Timeline().freeze() as timeline:
limiter = FixedWindowRateLimiter(self.storage)
per_min = RateLimitItemPerMinute(10)
for i in range(0, 10):
self.assertTrue(limiter.hit(per_min))
timeline.forward(60)
# touch another key and yield
limiter.hit(RateLimitItemPerSecond(1))
time.sleep(0.1)
self.assertTrue(per_min.key_for() not in self.storage.storage)
def test_in_memory_expiry(self):
with hiro.Timeline().freeze() as timeline:
storage = MemoryStorage()
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerMinute(10)
for i in range(0,10):
self.assertTrue(limiter.hit(per_min))
timeline.forward(60)
# touch another key and yield
limiter.hit(RateLimitItemPerSecond(1))
time.sleep(0.1)
self.assertTrue(per_min.key_for() not in storage.storage)
def test_fixed_window(self):
limiter = FixedWindowRateLimiter(self.storage)
per_second = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_second))
count += 1
self.assertFalse(limiter.hit(per_second))
while time.time() - start <= 1:
time.sleep(0.1)
[self.assertTrue(limiter.hit(per_second)) for _ in range(10)]
def test_memcached(self):
limiter = FixedWindowRateLimiter(self.storage)
per_min = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_min))
count += 1
self.assertFalse(limiter.hit(per_min))
while time.time() - start <= 1:
time.sleep(0.1)
self.assertTrue(limiter.hit(per_min))
def test_fixed_window(self):
storage = MemcachedStorage("memcached://localhost:22122")
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_min))
count += 1
self.assertFalse(limiter.hit(per_min))
while time.time() - start <= 1:
time.sleep(0.1)
self.assertTrue(limiter.hit(per_min))
def test_redis(self):
storage = RedisStorage("redis://localhost:6379")
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_min))
count += 1
self.assertFalse(limiter.hit(per_min))
while time.time() - start <= 1:
time.sleep(0.1)
self.assertTrue(limiter.hit(per_min))
def test_memcached(self):
storage = MemcachedStorage("memcached://localhost:11211")
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_min))
count += 1
self.assertFalse(limiter.hit(per_min))
while time.time() - start <= 1:
time.sleep(0.1)
self.assertTrue(limiter.hit(per_min))
def test_redis_cluster(self):
storage = RedisClusterStorage("redis+cluster://localhost:7000")
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_min))
count += 1
self.assertFalse(limiter.hit(per_min))
while time.time() - start <= 1:
time.sleep(0.1)
self.assertTrue(limiter.hit(per_min))
def test_redis_sentinel(self):
storage = RedisSentinelStorage("redis+sentinel://localhost:26379", service_name="localhost-redis-sentinel")
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_min))
count += 1
self.assertFalse(limiter.hit(per_min))
while time.time() - start <= 1:
time.sleep(0.1)
self.assertTrue(limiter.hit(per_min))
def test_fixed_window_clear(self):
limiter = FixedWindowRateLimiter(self.storage)
per_min = RateLimitItemPerMinute(1)
limiter.hit(per_min)
self.assertFalse(limiter.hit(per_min))
limiter.clear(per_min)
self.assertTrue(limiter.hit(per_min))
def test_redis_sentinel(self):
storage = RedisSentinelStorage("redis+sentinel://localhost:26379",
service_name="localhost-redis-sentinel")
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerSecond(10)
start = time.time()
count = 0
while time.time() - start < 0.5 and count < 10:
self.assertTrue(limiter.hit(per_min))
count += 1
self.assertFalse(limiter.hit(per_min))
while time.time() - start <= 1:
time.sleep(0.1)
self.assertTrue(limiter.hit(per_min))
def test_clear(self):
storage = MemcachedStorage("memcached://localhost:22122")
limiter = FixedWindowRateLimiter(storage)
per_min = RateLimitItemPerMinute(1)
limiter.hit(per_min)
self.assertFalse(limiter.hit(per_min))
limiter.clear(per_min)
self.assertTrue(limiter.hit(per_min))
def test_test_fixed_window(self):
with hiro.Timeline().freeze():
store = MemoryStorage()
limiter = FixedWindowRateLimiter(store)
limit = RateLimitItemPerSecond(2, 1)
self.assertTrue(limiter.hit(limit), store)
self.assertTrue(limiter.test(limit), store)
self.assertTrue(limiter.hit(limit), store)
self.assertFalse(limiter.test(limit), store)
self.assertFalse(limiter.hit(limit), store)
def test_memory_storage_fixed_window(self):
storage = MemoryStorage()
limiter = FixedWindowRateLimiter(storage)
per_second = RateLimitItemPerSecond(100)
[limiter.hit(per_second, uuid4().hex) for _ in range(1000)]
key = uuid4().hex
hits = []
def hit():
if limiter.hit(per_second, key):
hits.append(None)
start = time.time()
threads = [threading.Thread(target=hit) for _ in range(1000)]
[t.start() for t in threads]
[t.join() for t in threads]
self.assertTrue(time.time() - start < 1)
self.assertEqual(len(hits), 100)
def test_reset(self):
limiter = FixedWindowRateLimiter(self.storage)
per_min = RateLimitItemPerMinute(10)
for i in range(0, 10):
self.assertTrue(limiter.hit(per_min))
self.assertFalse(limiter.hit(per_min))
self.storage.reset()
for i in range(0, 10):
self.assertTrue(limiter.hit(per_min))
self.assertFalse(limiter.hit(per_min))
def test_test_fixed_window(self):
with hiro.Timeline().freeze() as timeline:
store = MemoryStorage()
limiter = FixedWindowRateLimiter(store)
limit = RateLimitItemPerSecond(2,1)
self.assertTrue(limiter.hit(limit), store)
self.assertTrue(limiter.test(limit), store)
self.assertTrue(limiter.hit(limit), store)
self.assertFalse(limiter.test(limit), store)
self.assertFalse(limiter.hit(limit), store)
def test_fixed_window(self):
storage = MemoryStorage()
limiter = FixedWindowRateLimiter(storage)
with hiro.Timeline().freeze() as timeline:
start = int(time.time())
limit = RateLimitItemPerSecond(10, 2)
self.assertTrue(all([limiter.hit(limit) for _ in range(0, 10)]))
timeline.forward(1)
self.assertFalse(limiter.hit(limit))
self.assertEqual(limiter.get_window_stats(limit)[1], 0)
self.assertEqual(limiter.get_window_stats(limit)[0], start + 2)
timeline.forward(1)
self.assertEqual(limiter.get_window_stats(limit)[1], 10)
self.assertTrue(limiter.hit(limit))
def test_fixed_window(self):
storage = MemoryStorage()
limiter = FixedWindowRateLimiter(storage)
with hiro.Timeline().freeze() as timeline:
start = int(time.time())
limit = RateLimitItemPerSecond(10, 2)
self.assertTrue(all([limiter.hit(limit) for _ in range(0,10)]))
timeline.forward(1)
self.assertFalse(limiter.hit(limit))
self.assertEqual(limiter.get_window_stats(limit)[1], 0)
self.assertEqual(limiter.get_window_stats(limit)[0], start + 2)
timeline.forward(1)
self.assertEqual(limiter.get_window_stats(limit)[1], 10)
self.assertTrue(limiter.hit(limit))
def test_reset(self):
limiter = FixedWindowRateLimiter(self.storage)
for i in range(0, 10):
rate = RateLimitItemPerMinute(i)
limiter.hit(rate)
self.assertEqual(self.storage.reset(), 10)
class LogProcessingWorker(Thread): # pylint: disable=too-many-instance-attributes
""""""
# ----------------------------------------------------------------------
def __init__(self, *args, **kwargs):
self._host = kwargs.pop('host')
self._port = kwargs.pop('port')
self._transport = kwargs.pop('transport')
self._ssl_enable = kwargs.pop('ssl_enable')
self._ssl_verify = kwargs.pop('ssl_verify')
self._keyfile = kwargs.pop('keyfile')
self._certfile = kwargs.pop('certfile')
self._ca_certs = kwargs.pop('ca_certs')
self._database_path = kwargs.pop('database_path')
self._memory_cache = kwargs.pop('cache')
self._event_ttl = kwargs.pop('event_ttl')
super().__init__(*args, **kwargs)
self.daemon = True
self.name = self.__class__.__name__
self._shutdown_event = Event()
self._flush_event = Event()
self._queue = Queue()
self._event = None
self._database = None
self._last_event_flush_date = None
self._non_flushed_event_count = None
self._logger = None
self._rate_limit_storage = None
self._rate_limit_strategy = None
self._rate_limit_item = None
# ----------------------------------------------------------------------
def enqueue_event(self, event):
# called from other threads
self._queue.put(event)
# ----------------------------------------------------------------------
def shutdown(self):
# called from other threads
self._shutdown_event.set()
# ----------------------------------------------------------------------
def run(self):
self._reset_flush_counters()
self._setup_logger()
self._setup_database()
try:
self._fetch_events()
except Exception as exc:
# we really should not get anything here, and if, the worker thread is dying
# too early resulting in undefined application behaviour
self._log_general_error(exc)
# check for empty queue and report if not
self._warn_about_non_empty_queue_on_shutdown()
# ----------------------------------------------------------------------
def force_flush_queued_events(self):
self._flush_event.set()
# ----------------------------------------------------------------------
def _reset_flush_counters(self):
self._last_event_flush_date = datetime.now()
self._non_flushed_event_count = 0
# ----------------------------------------------------------------------
def _clear_flush_event(self):
self._flush_event.clear()
# ----------------------------------------------------------------------
def _setup_logger(self):
self._logger = get_logger(self.name)
# rate limit our own messages to not spam around in case of temporary network errors, etc
rate_limit_setting = constants.ERROR_LOG_RATE_LIMIT
if rate_limit_setting:
self._rate_limit_storage = MemoryStorage()
self._rate_limit_strategy = FixedWindowRateLimiter(
self._rate_limit_storage)
self._rate_limit_item = parse_rate_limit(rate_limit_setting)
# ----------------------------------------------------------------------
def _setup_database(self):
if self._database_path:
self._database = DatabaseCache(path=self._database_path,
event_ttl=self._event_ttl)
else:
self._database = MemoryCache(cache=self._memory_cache,
event_ttl=self._event_ttl)
# ----------------------------------------------------------------------
def _fetch_events(self):
while True:
try:
self._fetch_event()
self._process_event()
except Empty:
# Flush queued (in database) events after internally queued events has been
# processed, i.e. the queue is empty.
if self._shutdown_requested():
self._flush_queued_events(force=True)
return
force_flush = self._flush_requested()
self._flush_queued_events(force=force_flush)
self._delay_processing()
self._expire_events()
except (DatabaseLockedError, ProcessingError):
if self._shutdown_requested():
return
self._requeue_event()
self._delay_processing()
# ----------------------------------------------------------------------
def _fetch_event(self):
self._event = self._queue.get(block=False)
# ----------------------------------------------------------------------
def _process_event(self):
try:
self._write_event_to_database()
except DatabaseLockedError as exc:
self._safe_log(
u'debug',
u'Database is locked, will try again later (queue length %d)',
self._queue.qsize(),
exc=exc)
raise
except Exception as exc:
self._log_processing_error(exc)
raise ProcessingError from exc
else:
self._event = None
# ----------------------------------------------------------------------
def _expire_events(self):
try:
self._database.expire_events()
except DatabaseLockedError:
# Nothing to handle, if it fails, we will either successfully publish
# these messages next time or we will delete them on the next pass.
pass
# ----------------------------------------------------------------------
def _log_processing_error(self, exception):
self._safe_log(u'exception',
u'Log processing error (queue size: %3s): %s',
self._queue.qsize(),
exception,
exc=exception)
# ----------------------------------------------------------------------
def _delay_processing(self):
self._shutdown_event.wait(constants.QUEUE_CHECK_INTERVAL)
# ----------------------------------------------------------------------
def _shutdown_requested(self):
return self._shutdown_event.is_set()
# ----------------------------------------------------------------------
def _flush_requested(self):
return self._flush_event.is_set()
# ----------------------------------------------------------------------
def _requeue_event(self):
self._queue.put(self._event)
# ----------------------------------------------------------------------
def _write_event_to_database(self):
self._database.add_event(self._event)
self._non_flushed_event_count += 1
# ----------------------------------------------------------------------
def _flush_queued_events(self, force=False):
# check if necessary and abort if not
if not force and not self._queued_event_interval_reached() and \
not self._queued_event_count_reached():
return
self._clear_flush_event()
while True:
queued_events = self._fetch_queued_events_for_flush()
if not queued_events:
break
try:
events = [event['event_text'] for event in queued_events]
self._send_events(events)
# exception types for which we do not want a stack trace
except (ConnectionError, TimeoutError, socket_gaierror) as exc:
self._safe_log(u'error',
u'An error occurred while sending events: %s',
exc)
self._database.requeue_queued_events(queued_events)
break
except Exception as exc:
self._safe_log(u'exception',
u'An error occurred while sending events: %s',
exc,
exc=exc)
self._database.requeue_queued_events(queued_events)
break
else:
self._delete_queued_events_from_database()
self._reset_flush_counters()
# ----------------------------------------------------------------------
def _fetch_queued_events_for_flush(self):
try:
return self._database.get_queued_events()
except DatabaseLockedError as exc:
self._safe_log(
u'debug',
u'Database is locked, will try again later (queue length %d)',
self._queue.qsize(),
exc=exc)
except Exception as exc:
# just log the exception and hope we can recover from the error
self._safe_log(u'exception',
u'Error retrieving queued events: %s',
exc,
exc=exc)
# ----------------------------------------------------------------------
def _delete_queued_events_from_database(self):
try:
self._database.delete_queued_events()
except DatabaseLockedError:
pass # nothing to handle, if it fails, we delete those events in a later run
# ----------------------------------------------------------------------
def _queued_event_interval_reached(self):
delta = datetime.now() - self._last_event_flush_date
return delta.total_seconds() > constants.QUEUED_EVENTS_FLUSH_INTERVAL
# ----------------------------------------------------------------------
def _queued_event_count_reached(self):
return self._non_flushed_event_count > constants.QUEUED_EVENTS_FLUSH_COUNT
# ----------------------------------------------------------------------
def _send_events(self, events):
use_logging = not self._shutdown_requested()
self._transport.send(events, use_logging=use_logging)
# ----------------------------------------------------------------------
def _log_general_error(self, exc):
self._safe_log(u'exception',
u'An unexpected error occurred: %s',
exc,
exc=exc)
# ----------------------------------------------------------------------
def _safe_log(self, log_level, message, *args, **kwargs):
# we cannot log via the logging subsystem any longer once it has been set to shutdown
if self._shutdown_requested():
safe_log_via_print(log_level, message, *args, **kwargs)
else:
rate_limit_allowed = self._rate_limit_check(kwargs)
if rate_limit_allowed <= 0:
return # skip further logging due to rate limiting
if rate_limit_allowed == 1:
# extend the message to indicate future rate limiting
message = \
u'{} (rate limiting effective, ' \
'further equal messages will be limited)'.format(message)
self._safe_log_impl(log_level, message, *args, **kwargs)
# ----------------------------------------------------------------------
def _rate_limit_check(self, kwargs):
exc = kwargs.pop('exc', None)
if self._rate_limit_strategy is not None and exc is not None:
key = self._factor_rate_limit_key(exc)
# query curent counter for the caller
_, remaining = self._rate_limit_strategy.get_window_stats(
self._rate_limit_item, key)
# increase the rate limit counter for the key
self._rate_limit_strategy.hit(self._rate_limit_item, key)
return remaining
return 2 # any value greater than 1 means allowed
# ----------------------------------------------------------------------
def _factor_rate_limit_key(self, exc): # pylint: disable=no-self-use
module_name = getattr(exc, '__module__', '__no_module__')
class_name = exc.__class__.__name__
key_items = [module_name, class_name]
if hasattr(exc, 'errno') and isinstance(exc.errno, int):
# in case of socket.error, include the errno as rate limiting key
key_items.append(str(exc.errno))
return '.'.join(key_items)
# ----------------------------------------------------------------------
def _safe_log_impl(self, log_level, message, *args, **kwargs):
log_func = getattr(self._logger, log_level)
log_func(message, *args, **kwargs)
# ----------------------------------------------------------------------
def _warn_about_non_empty_queue_on_shutdown(self):
queue_size = self._queue.qsize()
if queue_size:
self._safe_log(
'warn',
u'Non-empty queue while shutting down ({} events pending). '
u'This indicates a previous error.'.format(queue_size),
extra=dict(queue_size=queue_size))
