def test_expire_events(self): cache = MemoryCache({ "id1": {"pending_delete": False, "id": "id1", "entry_date": datetime.datetime.fromtimestamp(0)}, "id2": {"pending_delete": False, "id": "id2", "entry_date": datetime.datetime.now()} }, event_ttl=100) cache.expire_events() self.assertEqual(len(cache._cache), 1)
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))
class LogProcessingWorker(Thread): """""" # ---------------------------------------------------------------------- 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(LogProcessingWorker, self).__init__(*args, **kwargs) self.daemon = True self.name = self.__class__.__name__ self._shutdown_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 # ---------------------------------------------------------------------- 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 e: # 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(e) # check for empty queue and report if not self._warn_about_non_empty_queue_on_shutdown() # ---------------------------------------------------------------------- def _reset_flush_counters(self): self._last_event_flush_date = datetime.now() self._non_flushed_event_count = 0 # ---------------------------------------------------------------------- def _setup_logger(self): self._logger = get_logger(self.name) # ---------------------------------------------------------------------- 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 self._flush_queued_events() self._delay_processing() self._expire_events() except (DatabaseLockedError, ProcessingError): if self._shutdown_requested(): return else: 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: self._safe_log( u'debug', u'Database is locked, will try again later (queue length %d)', self._queue.qsize()) raise except Exception as e: self._log_processing_error(e) raise ProcessingError() 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) # ---------------------------------------------------------------------- def _delay_processing(self): self._shutdown_event.wait(QUEUE_CHECK_INTERVAL) # ---------------------------------------------------------------------- def _shutdown_requested(self): return self._shutdown_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 try: queued_events = self._database.get_queued_events() except DatabaseLockedError: self._safe_log( u'debug', u'Database is locked, will try again later (queue length %d)', self._queue.qsize()) return # try again later except Exception as e: # just log the exception and hope we can recover from the error self._safe_log(u'exception', u'Error retrieving queued events: %s', e) return if queued_events: try: events = [event['event_text'] for event in queued_events] self._send_events(events) except Exception as e: self._safe_log(u'exception', u'An error occurred while sending events: %s', e) self._database.requeue_queued_events(queued_events) else: self._delete_queued_events_from_database() self._reset_flush_counters() # ---------------------------------------------------------------------- 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() > QUEUED_EVENTS_FLUSH_INTERVAL # ---------------------------------------------------------------------- def _queued_event_count_reached(self): return self._non_flushed_event_count > QUEUED_EVENTS_FLUSH_COUNT # ---------------------------------------------------------------------- def _send_events(self, events): self._transport.send(events) # ---------------------------------------------------------------------- def _log_general_error(self, exc): self._safe_log(u'exception', u'An unexpected error occurred: %s', 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: log_func = getattr(self._logger, log_level) return 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))