X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/c4fa80c6ed2445e1e384455944eb6c4108906cad..5e991889ca6c18cdd901b98b5083c4cee7d260c9:/sdk/python/arvados/events.py diff --git a/sdk/python/arvados/events.py b/sdk/python/arvados/events.py index 09f2a871a9..d88897f123 100644 --- a/sdk/python/arvados/events.py +++ b/sdk/python/arvados/events.py @@ -1,9 +1,11 @@ import arvados import config import errors +from retry import RetryLoop import logging import json +import thread import threading import time import os @@ -13,13 +15,10 @@ from ws4py.client.threadedclient import WebSocketClient _logger = logging.getLogger('arvados.events') -class EventClient(WebSocketClient): - def __init__(self, url, filters, on_event): - # Prefer system's CA certificates (if available) - ssl_options = {} - certs_path = '/etc/ssl/certs/ca-certificates.crt' - if os.path.exists(certs_path): - ssl_options['ca_certs'] = certs_path + +class _EventClient(WebSocketClient): + def __init__(self, url, filters, on_event, last_log_id, on_closed): + ssl_options = {'ca_certs': arvados.util.ca_certs_path()} if config.flag_is_true('ARVADOS_API_HOST_INSECURE'): ssl_options['cert_reqs'] = ssl.CERT_NONE else: @@ -29,34 +28,110 @@ class EventClient(WebSocketClient): # IPv4 addresses (common with "localhost"), only one of them # will be attempted -- and it might not be the right one. See # ws4py's WebSocketBaseClient.__init__. - super(EventClient, self).__init__(url, ssl_options=ssl_options) + super(_EventClient, self).__init__(url, ssl_options=ssl_options) + self.filters = filters self.on_event = on_event + self.last_log_id = last_log_id + self._closing_lock = threading.RLock() + self._closing = False + self._closed = threading.Event() + self.on_closed = on_closed def opened(self): - self.subscribe(self.filters) + for f in self.filters: + self.subscribe(f, self.last_log_id) + + def closed(self, code, reason=None): + self._closed.set() + self.on_closed() def received_message(self, m): - self.on_event(json.loads(str(m))) + with self._closing_lock: + if not self._closing: + self.on_event(json.loads(str(m))) - def close_connection(self): - try: - self.sock.shutdown(socket.SHUT_RDWR) - self.sock.close() - except: - pass + def close(self, code=1000, reason='', timeout=0): + """Close event client and optionally wait for it to finish. - def subscribe(self, filters, last_log_id=None): - m = {"method": "subscribe", "filters": filters} + :timeout: is the number of seconds to wait for ws4py to + indicate that the connection has closed. + """ + super(_EventClient, self).close(code, reason) + with self._closing_lock: + # make sure we don't process any more messages. + self._closing = True + # wait for ws4py to tell us the connection is closed. + self._closed.wait(timeout=timeout) + + def subscribe(self, f, last_log_id=None): + m = {"method": "subscribe", "filters": f} if last_log_id is not None: m["last_log_id"] = last_log_id self.send(json.dumps(m)) - def unsubscribe(self, filters): - self.send(json.dumps({"method": "unsubscribe", "filters": filters})) + def unsubscribe(self, f): + self.send(json.dumps({"method": "unsubscribe", "filters": f})) + + +class EventClient(object): + def __init__(self, url, filters, on_event_cb, last_log_id): + self.url = url + if filters: + self.filters = [filters] + else: + self.filters = [[]] + self.on_event_cb = on_event_cb + self.last_log_id = last_log_id + self.is_closed = False + self.ec = _EventClient(url, self.filters, self.on_event, last_log_id, self.on_closed) + + def connect(self): + self.ec.connect() + + def close_connection(self): + self.ec.close_connection() + + def subscribe(self, f, last_log_id=None): + self.filters.append(f) + self.ec.subscribe(f, last_log_id) + + def unsubscribe(self, f): + del self.filters[self.filters.index(f)] + self.ec.unsubscribe(f) + + def close(self, code=1000, reason='', timeout=0): + self.is_closed = True + self.ec.close(code, reason, timeout) + + def on_event(self, m): + if m.get('id') != None: + self.last_log_id = m.get('id') + try: + self.on_event_cb(m) + except Exception as e: + _logger.exception("Unexpected exception from event callback.") + thread.interrupt_main() + + def on_closed(self): + if self.is_closed == False: + _logger.warn("Unexpected close. Reconnecting.") + for tries_left in RetryLoop(num_retries=25, backoff_start=.1, max_wait=15): + try: + self.ec = _EventClient(self.url, self.filters, self.on_event, self.last_log_id, self.on_closed) + self.ec.connect() + break + except Exception as e: + _logger.warn("Error '%s' during websocket reconnect.", e) + if tries_left == 0: + _logger.exception("EventClient thread could not contact websocket server.") + self.is_closed = True + thread.interrupt_main() + return + class PollClient(threading.Thread): - def __init__(self, api, filters, on_event, poll_time): + def __init__(self, api, filters, on_event, poll_time, last_log_id): super(PollClient, self).__init__() self.api = api if filters: @@ -66,38 +141,95 @@ class PollClient(threading.Thread): self.on_event = on_event self.poll_time = poll_time self.daemon = True - self.stop = threading.Event() + self.last_log_id = last_log_id + self._closing = threading.Event() + self._closing_lock = threading.RLock() def run(self): self.id = 0 - for f in self.filters: - items = self.api.logs().list(limit=1, order="id desc", filters=f).execute()['items'] - if items: - if items[0]['id'] > self.id: - self.id = items[0]['id'] + if self.last_log_id != None: + self.id = self.last_log_id + else: + for f in self.filters: + for tries_left in RetryLoop(num_retries=25, backoff_start=.1, max_wait=self.poll_time): + try: + items = self.api.logs().list(limit=1, order="id desc", filters=f).execute()['items'] + break + except errors.ApiError as error: + pass + else: + tries_left = 0 + break + if tries_left == 0: + _logger.exception("PollClient thread could not contact API server.") + with self._closing_lock: + self._closing.set() + thread.interrupt_main() + return + if items: + if items[0]['id'] > self.id: + self.id = items[0]['id'] self.on_event({'status': 200}) - while not self.stop.isSet(): + while not self._closing.is_set(): max_id = self.id + moreitems = False for f in self.filters: - items = self.api.logs().list(order="id asc", filters=f+[["id", ">", str(self.id)]]).execute()['items'] - for i in items: + for tries_left in RetryLoop(num_retries=25, backoff_start=.1, max_wait=self.poll_time): + try: + items = self.api.logs().list(order="id asc", filters=f+[["id", ">", str(self.id)]]).execute() + break + except errors.ApiError as error: + pass + else: + tries_left = 0 + break + if tries_left == 0: + _logger.exception("PollClient thread could not contact API server.") + with self._closing_lock: + self._closing.set() + thread.interrupt_main() + return + for i in items["items"]: if i['id'] > max_id: max_id = i['id'] - self.on_event(i) + with self._closing_lock: + if self._closing.is_set(): + return + try: + self.on_event(i) + except Exception as e: + _logger.exception("Unexpected exception from event callback.") + thread.interrupt_main() + if items["items_available"] > len(items["items"]): + moreitems = True self.id = max_id - self.stop.wait(self.poll_time) + if not moreitems: + self._closing.wait(self.poll_time) def run_forever(self): # Have to poll here, otherwise KeyboardInterrupt will never get processed. - while not self.stop.is_set(): - self.stop.wait(1) + while not self._closing.is_set(): + self._closing.wait(1) - def close(self): - self.stop.set() + def close(self, code=None, reason=None, timeout=0): + """Close poll client and optionally wait for it to finish. + + If an :on_event: handler is running in a different thread, + first wait (indefinitely) for it to return. + + After closing, wait up to :timeout: seconds for the thread to + finish the poll request in progress (if any). + + :code: and :reason: are ignored. They are present for + interface compatibility with EventClient. + """ + + with self._closing_lock: + self._closing.set() try: - self.join() + self.join(timeout=timeout) except RuntimeError: # "join() raises a RuntimeError if an attempt is made to join the # current thread as that would cause a deadlock. It is also an @@ -105,31 +237,36 @@ class PollClient(threading.Thread): # to do so raises the same exception." pass - def subscribe(self, filters): + def subscribe(self, f): self.on_event({'status': 200}) - self.filters.append(filters) + self.filters.append(f) - def unsubscribe(self, filters): - del self.filters[self.filters.index(filters)] + def unsubscribe(self, f): + del self.filters[self.filters.index(f)] -def _subscribe_websocket(api, filters, on_event): +def _subscribe_websocket(api, filters, on_event, last_log_id=None): endpoint = api._rootDesc.get('websocketUrl', None) if not endpoint: raise errors.FeatureNotEnabledError( "Server does not advertise a websocket endpoint") - uri_with_token = "{}?api_token={}".format(endpoint, api.api_token) - client = EventClient(uri_with_token, filters, on_event) - ok = False try: - client.connect() - ok = True - return client - finally: - if not ok: - client.close_connection() - -def subscribe(api, filters, on_event, poll_fallback=15): + uri_with_token = "{}?api_token={}".format(endpoint, api.api_token) + client = EventClient(uri_with_token, filters, on_event, last_log_id) + ok = False + try: + client.connect() + ok = True + return client + finally: + if not ok: + client.close_connection() + except: + _logger.warn("Failed to connect to websockets on %s" % endpoint) + raise + + +def subscribe(api, filters, on_event, poll_fallback=15, last_log_id=None): """ :api: a client object retrieved from arvados.api(). The caller should not use this client object for anything else after calling subscribe(). @@ -139,15 +276,20 @@ def subscribe(api, filters, on_event, poll_fallback=15): The callback when a message is received. :poll_fallback: If websockets are not available, fall back to polling every N seconds. If poll_fallback=False, this will return None if websockets are not available. + :last_log_id: + Log rows that are newer than the log id """ if not poll_fallback: - return _subscribe_websocket(api, filters, on_event) + return _subscribe_websocket(api, filters, on_event, last_log_id) try: - return _subscribe_websocket(api, filters, on_event) + if not config.flag_is_true('ARVADOS_DISABLE_WEBSOCKETS'): + return _subscribe_websocket(api, filters, on_event, last_log_id) + else: + _logger.info("Using polling because ARVADOS_DISABLE_WEBSOCKETS is true") except Exception as e: _logger.warn("Falling back to polling after websocket error: %s" % e) - p = PollClient(api, filters, on_event, poll_fallback) + p = PollClient(api, filters, on_event, poll_fallback, last_log_id) p.start() return p