X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/a2c147e469bc4ccc0e788f2e72b2d94aa81ba368..ea6f25f0dde5c750eacea29662c19149c7800134:/sdk/python/arvados/events.py diff --git a/sdk/python/arvados/events.py b/sdk/python/arvados/events.py index 57bf3ae1cb..e53e4980a8 100644 --- a/sdk/python/arvados/events.py +++ b/sdk/python/arvados/events.py @@ -1,9 +1,20 @@ +# Copyright (C) The Arvados Authors. All rights reserved. +# +# SPDX-License-Identifier: Apache-2.0 + +from __future__ import absolute_import +from future import standard_library +standard_library.install_aliases() +from builtins import str +from builtins import object import arvados -import config -import errors +from . import config +from . import errors +from .retry import RetryLoop import logging import json +import _thread import threading import time import os @@ -28,10 +39,7 @@ class _EventClient(WebSocketClient): # ws4py's WebSocketBaseClient.__init__. super(_EventClient, self).__init__(url, ssl_options=ssl_options) - if filters: - self.filters = filters - else: - self.filters = [[]] + self.filters = filters self.on_event = on_event self.last_log_id = last_log_id self._closing_lock = threading.RLock() @@ -40,7 +48,8 @@ class _EventClient(WebSocketClient): self.on_closed = on_closed def opened(self): - self.subscribe(self.filters, self.last_log_id) + for f in self.filters: + self.subscribe(f, self.last_log_id) def closed(self, code, reason=None): self._closed.set() @@ -64,61 +73,79 @@ class _EventClient(WebSocketClient): # wait for ws4py to tell us the connection is closed. self._closed.wait(timeout=timeout) - def subscribe(self, filters, last_log_id=None): - m = {"method": "subscribe", "filters": filters} + 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 - self.filters = filters + 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.subscriptions = {} - self.ec = _EventClient(url, filters, self.on_event, last_log_id, self.on_closed) - - def connect(self): - self.ec.connect() + self.is_closed = threading.Event() + self._setup_event_client() - def close_connection(self): - self.ec.close_connection() + def _setup_event_client(self): + self.ec = _EventClient(self.url, self.filters, self.on_event, + self.last_log_id, self.on_closed) + self.ec.daemon = True + try: + self.ec.connect() + except Exception: + self.ec.close_connection() + raise - def subscribe(self, filters, last_log_id=None): - self.subscriptions[str(filters)] = filters - self.ec.subscribe(filters, last_log_id) + def subscribe(self, f, last_log_id=None): + self.filters.append(f) + self.ec.subscribe(f, last_log_id) - def unsubscribe(self, filters): - del self.subscriptions[str(filters)] - self.ec.unsubscribe(filters) + 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.is_closed.set() self.ec.close(code, reason, timeout) def on_event(self, m): if m.get('id') != None: self.last_log_id = m.get('id') - self.on_event_cb(m) + 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: - self.ec = _EventClient(self.url, self.filters, self.on_event, self.last_log_id, self.on_closed) - while True: - try: - self.ec.connect() - for s in self.subscriptions: - self.ec.subscribe(self.subscriptions[s], self.last_log_id) - break - except: - _logger.warn("Failed to reconnect to websockets on %s. Will retry after 5s." % endpoint) - time.sleep(5) + if not self.is_closed.is_set(): + _logger.warning("Unexpected close. Reconnecting.") + for tries_left in RetryLoop(num_retries=25, backoff_start=.1, max_wait=15): + try: + self._setup_event_client() + _logger.warning("Reconnect successful.") + break + except Exception as e: + _logger.warning("Error '%s' during websocket reconnect.", e) + if tries_left == 0: + _logger.exception("EventClient thread could not contact websocket server.") + self.is_closed.set() + _thread.interrupt_main() + return + + def run_forever(self): + # Have to poll here to let KeyboardInterrupt get raised. + while not self.is_closed.wait(1): + pass class PollClient(threading.Thread): @@ -136,34 +163,101 @@ class PollClient(threading.Thread): self._closing = threading.Event() self._closing_lock = threading.RLock() - def run(self): - self.id = 0 if self.last_log_id != None: - self.id = self.last_log_id + # Caller supplied the last-seen event ID from a previous + # connection. + self._skip_old_events = [["id", ">", str(self.last_log_id)]] else: - 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'] + # We need to do a reverse-order query to find the most + # recent event ID (see "if not self._skip_old_events" + # in run()). + self._skip_old_events = False + def run(self): self.on_event({'status': 200}) 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() + for tries_left in RetryLoop(num_retries=25, backoff_start=.1, max_wait=self.poll_time): + try: + if not self._skip_old_events: + # If the caller didn't provide a known + # recent ID, our first request will ask + # for the single most recent event from + # the last 2 hours (the time restriction + # avoids doing an expensive database + # query, and leaves a big enough margin to + # account for clock skew). If we do find a + # recent event, we remember its ID but + # then discard it (we are supposed to be + # returning new/current events, not old + # ones). + # + # Subsequent requests will get multiple + # events in chronological order, and + # filter on that same cutoff time, or + # (once we see our first matching event) + # the ID of the last-seen event. + # + # Note: self._skip_old_events must not be + # set until the threshold is decided. + # Otherwise, tests will be unreliable. + filter_by_time = [[ + "created_at", ">=", + time.strftime( + "%Y-%m-%dT%H:%M:%SZ", + time.gmtime(time.time()-7200))]] + items = self.api.logs().list( + order="id desc", + limit=1, + filters=f+filter_by_time).execute() + if items["items"]: + self._skip_old_events = [ + ["id", ">", str(items["items"][0]["id"])]] + items = { + "items": [], + "items_available": 0, + } + else: + # No recent events. We can keep using + # the same timestamp threshold until + # we receive our first new event. + self._skip_old_events = filter_by_time + else: + # In this case, either we know the most + # recent matching ID, or we know there + # were no matching events in the 2-hour + # window before subscribing. Either way we + # can safely ask for events in ascending + # order. + items = self.api.logs().list( + order="id asc", + filters=f+self._skip_old_events).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._skip_old_events = [["id", ">", str(i["id"])]] with self._closing_lock: if self._closing.is_set(): return - self.on_event(i) + 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 if not moreitems: self._closing.wait(self.poll_time) @@ -196,12 +290,12 @@ 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, last_log_id=None): @@ -209,20 +303,14 @@ def _subscribe_websocket(api, filters, on_event, last_log_id=None): if not endpoint: raise errors.FeatureNotEnabledError( "Server does not advertise a websocket endpoint") + uri_with_token = "{}?api_token={}".format(endpoint, api.api_token) try: - 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) + except Exception: + _logger.warning("Failed to connect to websockets on %s" % endpoint) raise + else: + return client def subscribe(api, filters, on_event, poll_fallback=15, last_log_id=None): @@ -248,7 +336,7 @@ def subscribe(api, filters, on_event, poll_fallback=15, last_log_id=None): 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) + _logger.warning("Falling back to polling after websocket error: %s" % e) p = PollClient(api, filters, on_event, poll_fallback, last_log_id) p.start() return p