async def receive_result(self, rpc_message: RpcMessage, return_path: str,
options: dict) -> ResultMessage:
logger.debug(
L("Awaiting Redis result for RPC message: {}", Bold(rpc_message)))
redis_key = self._parse_return_path(return_path)
with await self.connection_manager() as redis:
start_time = time.time()
result = None
while not result:
# Sometimes blpop() will return None in the case of timeout or
# cancellation. We therefore perform this step with a loop to catch
# this. A more elegant solution is welcome.
result = await redis.blpop(redis_key, timeout=self.rpc_timeout)
_, serialized = result
result_message = self.deserializer(serialized)
logger.debug(
L(
"⬅ Received Redis result in {} for RPC message {}: {}",
human_time(time.time() - start_time),
rpc_message,
Bold(result_message.result),
))
return result_message
async def call_rpc(self, rpc_message: RpcMessage, options: dict,
bus_client: "BusClient"):
queue_key = f"{rpc_message.api_name}:rpc_queue"
expiry_key = f"rpc_expiry_key:{rpc_message.id}"
logger.debug(
LBullets(
L("Enqueuing message {} in Redis list {}", Bold(rpc_message),
Bold(queue_key)),
items=dict(**rpc_message.get_metadata(),
kwargs=rpc_message.get_kwargs()),
))
start_time = time.time()
for try_number in range(3, 0, -1):
last_try = try_number == 1
try:
await self._call_rpc(rpc_message, queue_key, expiry_key)
return
except (PipelineError, ConnectionClosedError,
ConnectionResetError):
if not last_try:
await asyncio.sleep(self.rpc_retry_delay)
else:
raise
logger.debug(
L(
"Enqueued message {} in Redis in {} stream {}",
Bold(rpc_message),
human_time(time.time() - start_time),
Bold(queue_key),
))
async def _call_rpc_local(self, api_name: str, name: str, kwargs: dict = frozendict()):
api = self.api_registry.get(api_name)
validate_event_or_rpc_name(api_name, "rpc", name)
start_time = time.time()
try:
method = getattr(api, name)
if self.config.api(api_name).cast_values:
kwargs = cast_to_signature(kwargs, method)
result = await run_user_provided_callable(method, args=[], kwargs=kwargs)
except (asyncio.CancelledError, SuddenDeathException):
raise
except Exception as e:
logging.exception(e)
logger.warning(
L(
"⚡ Error while executing {}.{}. Took {}",
Bold(api_name),
Bold(name),
human_time(time.time() - start_time),
)
)
raise
else:
logger.info(
L(
"⚡ Executed {}.{} in {}",
Bold(api_name),
Bold(name),
human_time(time.time() - start_time),
)
)
return result
async def send_event(self, event_message: EventMessage, options: dict):
"""Publish an event"""
stream = self._get_stream_names(
listen_for=[(event_message.api_name, event_message.event_name)])[0]
logger.debug(
LBullets(
L(
"Enqueuing event message {} in Redis stream {}",
Bold(event_message),
Bold(stream),
),
items=dict(**event_message.get_metadata(),
kwargs=event_message.get_kwargs()),
))
# Performance: I suspect getting a connection from the connection manager each time is causing
# performance issues. Need to confirm.
with await self.connection_manager() as redis:
start_time = time.time()
await redis.xadd(
stream=stream,
fields=self.serializer(event_message),
max_len=self.max_stream_length or None,
exact_len=False,
)
logger.debug(
L(
"Enqueued event message {} in Redis in {} stream {}",
Bold(event_message.canonical_name),
human_time(time.time() - start_time),
Bold(stream),
))
async def call_rpc_local(self,
api_name: str,
name: str,
kwargs: dict = frozendict()):
api = registry.get(api_name)
self._validate_name(api_name, "rpc", name)
start_time = time.time()
try:
method = getattr(api, name)
if self.config.api(api_name).cast_values:
kwargs = cast_to_signature(kwargs, method)
result = method(**kwargs)
result = await await_if_necessary(result)
except (CancelledError, SuddenDeathException):
raise
except Exception as e:
logger.warning(
L(
"⚡ Error while executing {}.{}. Took {}",
Bold(api_name),
Bold(name),
human_time(time.time() - start_time),
))
return e
else:
logger.info(
L(
"⚡ Executed {}.{} in {}",
Bold(api_name),
Bold(name),
human_time(time.time() - start_time),
))
return result
async def receive_result(self, rpc_message: RpcMessage, return_path: str,
options: dict,
bus_client: "BusClient") -> ResultMessage:
"""Await a result from the processing worker"""
logger.debug(
L("Awaiting Redis result for RPC message: {}", Bold(rpc_message)))
redis_key = self._parse_return_path(return_path)
with await self.connection_manager() as redis:
start_time = time.time()
result = None
while not result:
# Sometimes blpop() will return None in the case of timeout or
# cancellation. We therefore perform this step with a loop to catch
# this. A more elegant solution is welcome.
# TODO: RPC & result Transports should not be applying a timeout, leave
# this to the client which coordinates between the two
result = await redis.blpop(redis_key, timeout=self.rpc_timeout)
_, serialized = result
result_message = self.deserializer(serialized)
logger.debug(
L(
"⬅ Received Redis result in {} for RPC message {}: {}",
human_time(time.time() - start_time),
rpc_message,
Bold(result_message.result),
))
return result_message
async def send_result(
self,
rpc_message: RpcMessage,
result_message: ResultMessage,
return_path: str,
bus_client: "BusClient",
):
"""Send the result back to the caller"""
logger.debug(
L(
"Sending result {} into Redis using return path {}",
Bold(result_message),
Bold(return_path),
))
redis_key = self._parse_return_path(return_path)
with await self.connection_manager() as redis:
start_time = time.time()
p = redis.pipeline()
p.lpush(redis_key, self.serializer(result_message))
p.expire(redis_key, timeout=self.result_ttl)
await p.execute()
logger.debug(
L(
"➡ Sent result {} into Redis in {} using return path {}",
Bold(result_message),
human_time(time.time() - start_time),
Bold(return_path),
))
async def setup_async(self, plugins: dict = None):
"""Setup lightbus and get it ready to consume events and/or RPCs
You should call this manually if you are calling `consume_rpcs()`
directly. This you be handled for you if you are
calling `run_forever()`.
"""
logger.info(
LBullets(
"Lightbus is setting up",
items={
"service_name (set with -s or LIGHTBUS_SERVICE_NAME)": Bold(
self.config.service_name
),
"process_name (with with -p or LIGHTBUS_PROCESS_NAME)": Bold(
self.config.process_name
),
},
)
)
# Log the transport information
rpc_transport = self.transport_registry.get_rpc_transport("default", default=None)
result_transport = self.transport_registry.get_result_transport("default", default=None)
event_transport = self.transport_registry.get_event_transport("default", default=None)
log_transport_information(
rpc_transport, result_transport, event_transport, self.schema.schema_transport, logger
)
# Log the plugins we have
if plugins is None:
logger.debug("Auto-loading any installed Lightbus plugins...")
self.plugin_registry.autoload_plugins(self.config)
else:
logger.debug("Loading explicitly specified Lightbus plugins....")
self.plugin_registry.set_plugins(plugins)
if self.plugin_registry._plugins:
logger.info(
LBullets(
"Loaded the following plugins ({})".format(len(self.plugin_registry._plugins)),
items=self.plugin_registry._plugins,
)
)
else:
logger.info("No plugins loaded")
# Load schema
logger.debug("Loading schema...")
await self.schema.load_from_bus()
logger.info(
LBullets(
"Loaded the following remote schemas ({})".format(len(self.schema.remote_schemas)),
items=self.schema.remote_schemas.keys(),
)
)
for transport in self.transport_registry.get_all_transports():
await transport.open()
async def call_rpc(self, rpc_message: RpcMessage, options: dict):
queue_key = f"{rpc_message.api_name}:rpc_queue"
expiry_key = f"rpc_expiry_key:{rpc_message.id}"
logger.debug(
LBullets(
L("Enqueuing message {} in Redis stream {}", Bold(rpc_message),
Bold(queue_key)),
items=dict(**rpc_message.get_metadata(),
kwargs=rpc_message.get_kwargs()),
))
with await self.connection_manager() as redis:
start_time = time.time()
print("setting " + expiry_key)
p = redis.pipeline()
p.rpush(key=queue_key, value=self.serializer(rpc_message))
p.set(expiry_key, 1)
p.expire(expiry_key, timeout=self.rpc_timeout)
await p.execute()
logger.debug(
L(
"Enqueued message {} in Redis in {} stream {}",
Bold(rpc_message),
human_time(time.time() - start_time),
Bold(queue_key),
))
async def consume_rpcs(self, apis: Sequence[Api]) -> Sequence[RpcMessage]:
# Get the name of each stream
streams = ['{}:stream'.format(api.meta.name) for api in apis]
# Get where we last left off in each stream
latest_ids = [self._latest_ids.get(stream, '$') for stream in streams]
logger.debug(LBullets(
'Consuming RPCs from', items=[
'{} ({})'.format(s, self._latest_ids.get(s, '$')) for s in streams
]
))
pool = await self.get_redis_pool()
with await pool as redis:
# TODO: Count/timeout configurable
stream_messages = await redis.xread(streams, latest_ids=latest_ids, count=10)
rpc_messages = []
for stream, message_id, fields in stream_messages:
stream = decode(stream, 'utf8')
message_id = decode(message_id, 'utf8')
decoded_fields = decode_message_fields(fields)
# See comment on events transport re updating message_id
self._latest_ids[stream] = message_id
rpc_messages.append(
RpcMessage.from_dict(decoded_fields)
)
logger.debug(LBullets(
L("⬅ Received message {} on stream {}", Bold(message_id), Bold(stream)),
items=decoded_fields
))
return rpc_messages
async def _on_message(self, event_message: EventMessage,
listener: Callable, options: dict,
on_error: OnError):
# TODO: Check events match those requested
logger.info(
L("📩 Received event {}.{} with ID {}".format(
Bold(event_message.api_name), Bold(event_message.event_name),
event_message.id)))
validate_incoming(self.config, self.schema, event_message)
await self.hook_registry.execute("before_event_execution",
event_message=event_message)
if self.config.api(event_message.api_name).cast_values:
parameters = cast_to_signature(parameters=event_message.kwargs,
callable=listener)
else:
parameters = event_message.kwargs
# Call the listener.
# Pass the event message as a positional argument,
# thereby allowing listeners to have flexibility in the argument names.
# (And therefore allowing listeners to use the `event` parameter themselves)
if on_error == OnError.SHUTDOWN:
# Run the callback in the queue_exception_checker(). This will
# put any errors into Lightbus' error queue, and therefore
# cause a shutdown
await queue_exception_checker(
run_user_provided_callable(listener,
args=[event_message],
kwargs=parameters),
self.error_queue,
help=
(f"An error occurred while {listener} was handling an event. Lightbus will now"
" shutdown. If you wish to continue you can use the on_error parameter when"
" setting up your event. For example:\n\n bus.my_api.my_event.listen(fn,"
" listener_name='example', on_error=lightbus.OnError.ACKNOWLEDGE_AND_LOG)"
),
)
elif on_error == on_error.ACKNOWLEDGE_AND_LOG:
try:
await listener(event_message, **parameters)
except asyncio.CancelledError:
raise
except Exception as e:
# Log here. Acknowledgement will follow in below
logger.exception(e)
# Acknowledge the successfully processed message
await self.producer.send(
AcknowledgeEventCommand(message=event_message,
options=options)).wait()
await self.hook_registry.execute("after_event_execution",
event_message=event_message)
async def receive_result(self, rpc_message: RpcMessage,
return_path: asyncio.Future,
options: dict) -> ResultMessage:
logger.info(
L("⌛️ Awaiting result for RPC message: {}", Bold(rpc_message)))
result = await return_path
logger.info(
L("⬅ Received result for RPC message {}: {}", rpc_message,
Bold(result)))
return result
async def fire_event(self,
api_name,
name,
kwargs: dict = None,
options: dict = None):
kwargs = kwargs or {}
try:
api = registry.get(api_name)
except UnknownApi:
raise UnknownApi(
"Lightbus tried to fire the event {api_name}.{name}, but could not find API {api_name} in the "
"registry. An API being in the registry implies you are an authority on that API. Therefore, "
"Lightbus requires the API to be in the registry as it is a bad idea to fire "
"events on behalf of remote APIs. However, this could also be caused by a typo in the "
"API name or event name, or be because the API class has not been "
"imported. ".format(**locals()))
self._validate_name(api_name, "event", name)
try:
event = api.get_event(name)
except EventNotFound:
raise EventNotFound(
"Lightbus tried to fire the event {api_name}.{name}, but the API {api_name} does not "
"seem to contain an event named {name}. You may need to define the event, you "
"may also be using the incorrect API. Also check for typos.".
format(**locals()))
if set(kwargs.keys()) != _parameter_names(event.parameters):
raise InvalidEventArguments(
"Invalid event arguments supplied when firing event. Attempted to fire event with "
"{} arguments: {}. Event expected {}: {}".format(
len(kwargs),
sorted(kwargs.keys()),
len(event.parameters),
sorted(_parameter_names(event.parameters)),
))
kwargs = deform_to_bus(kwargs)
event_message = EventMessage(api_name=api.meta.name,
event_name=name,
kwargs=kwargs)
self._validate(event_message, "outgoing")
event_transport = self.transport_registry.get_event_transport(api_name)
await self._plugin_hook("before_event_sent",
event_message=event_message)
logger.info(
L("📤 Sending event {}.{}".format(Bold(api_name), Bold(name))))
await event_transport.send_event(event_message, options=options)
await self._plugin_hook("after_event_sent",
event_message=event_message)
def run_forever(self, *, loop=None, consume_rpcs=True, consume_events=True, plugins=None):
logger.info(LBullets(
"Lightbus getting ready to run. Brokers in use",
items={
"RPC transport": L(
'{}.{}',
self.rpc_transport.__module__, Bold(self.rpc_transport.__class__.__name__)
),
"Result transport": L(
'{}.{}', self.result_transport.__module__,
Bold(self.result_transport.__class__.__name__)
),
"Event transport": L(
'{}.{}', self.event_transport.__module__,
Bold(self.event_transport.__class__.__name__)
),
}
))
self.setup(plugins=plugins)
registry.add(LightbusStateApi())
registry.add(LightbusMetricsApi())
if consume_rpcs:
if registry.public():
logger.info(LBullets(
"APIs in registry ({})".format(len(registry.all())),
items=registry.all()
))
else:
if consume_events:
logger.warning(
"No APIs have been registered, lightbus may still receive events "
"but Lightbus will not handle any incoming RPCs"
)
else:
logger.error(
"No APIs have been registered, yet Lightbus has been configured to only "
"handle RPCs. There is therefore nothing for lightbus to do. Exiting."
)
return
block(handle_aio_exceptions(
plugin_hook('before_server_start', bus_client=self, loop=loop)
), timeout=5)
loop = loop or asyncio.get_event_loop()
self._run_forever(loop, consume_rpcs, consume_events)
loop.run_until_complete(handle_aio_exceptions(
plugin_hook('after_server_stopped', bus_client=self, loop=loop)
))
async def call_rpc_local(self, api_name: str, name: str, kwargs: dict):
api = registry.get(api_name)
start_time = time.time()
try:
result = await api.call(name, kwargs)
except (CancelledError, SuddenDeathException):
raise
except Exception as e:
logger.warning(L("⚡ Error while executing {}.{}. Took {}", Bold(api_name), Bold(name), human_time(time.time() - start_time)))
return e
else:
logger.info(L("⚡ Executed {}.{} in {}", Bold(api_name), Bold(name), human_time(time.time() - start_time)))
return result
async def fire_event(self, api_name, name, kwargs: dict = None, options: dict = None):
kwargs = kwargs or {}
try:
api = self.api_registry.get(api_name)
except UnknownApi:
raise UnknownApi(
"Lightbus tried to fire the event {api_name}.{name}, but no API named {api_name} was found in the "
"registry. An API being in the registry implies you are an authority on that API. Therefore, "
"Lightbus requires the API to be in the registry as it is a bad idea to fire "
"events on behalf of remote APIs. However, this could also be caused by a typo in the "
"API name or event name, or be because the API class has not been "
"registered using bus.client.register_api(). ".format(**locals())
)
validate_event_or_rpc_name(api_name, "event", name)
try:
event = api.get_event(name)
except EventNotFound:
raise EventNotFound(
"Lightbus tried to fire the event {api_name}.{name}, but the API {api_name} does not "
"seem to contain an event named {name}. You may need to define the event, you "
"may also be using the incorrect API. Also check for typos.".format(**locals())
)
parameter_names = {p.name if isinstance(p, Parameter) else p for p in event.parameters}
if set(kwargs.keys()) != parameter_names:
raise InvalidEventArguments(
"Invalid event arguments supplied when firing event. Attempted to fire event with "
"{} arguments: {}. Event expected {}: {}".format(
len(kwargs),
sorted(kwargs.keys()),
len(event.parameters),
sorted(parameter_names),
)
)
kwargs = deform_to_bus(kwargs)
event_message = EventMessage(
api_name=api.meta.name, event_name=name, kwargs=kwargs, version=api.meta.version
)
validate_outgoing(self.config, self.schema, event_message)
await self.hook_registry.execute("before_event_sent", event_message=event_message)
logger.info(L("📤 Sending event {}.{}".format(Bold(api_name), Bold(name))))
await self.producer.send(SendEventCommand(message=event_message, options=options)).wait()
await self.hook_registry.execute("after_event_sent", event_message=event_message)
def autodiscover(directory='.'):
logger.debug("Attempting to autodiscover bus.py file")
bus_path = discover_bus_py(directory)
if not bus_path:
return None
logger.debug(L("Found bus.py file at: {}", Bold(bus_path)))
bus_module_name = prepare_exec_for_file(bus_path)
logger.debug(L("Going to import {}", Bold(bus_module_name)))
spec = importlib.util.spec_from_file_location(bus_module_name, str(bus_path))
bus_module = importlib.util.module_from_spec(spec)
spec.loader.exec_module(bus_module)
logger.info(L("No initial import was specified. Using autodiscovered module '{}'", Bold(bus_module_name)))
return bus_module
async def call_rpc_remote(self, api_name: str, name: str, kwargs: dict, options: dict):
rpc_message = RpcMessage(api_name=api_name, procedure_name=name, kwargs=kwargs)
return_path = self.result_transport.get_return_path(rpc_message)
rpc_message.return_path = return_path
options = options or {}
timeout = options.get('timeout', 5)
logger.info("➡ Calling remote RPC ".format(rpc_message))
start_time = time.time()
# TODO: It is possible that the RPC will be called before we start waiting for the response. This is bad.
future = asyncio.gather(
self.receive_result(rpc_message, return_path, options=options),
self.rpc_transport.call_rpc(rpc_message, options=options),
)
await plugin_hook('before_rpc_call', rpc_message=rpc_message, bus_client=self)
try:
result_message, _ = await asyncio.wait_for(future, timeout=timeout)
except asyncio.TimeoutError:
future.cancel()
# TODO: Include description of possible causes and how to increase the timeout.
# TODO: Remove RPC from queue. Perhaps add a RpcBackend.cancel() method. Optional,
# as not all backends will support it. No point processing calls which have timed out.
raise LightbusTimeout('Timeout when calling RPC {} after {} seconds'.format(
rpc_message.canonical_name, timeout
)) from None
await plugin_hook('after_rpc_call', rpc_message=rpc_message, result_message=result_message, bus_client=self)
if not result_message.error:
logger.info(L("⚡ Remote call of {} completed in {}", Bold(rpc_message.canonical_name), human_time(time.time() - start_time)))
else:
logger.warning(
L("⚡ Server error during remote call of {}. Took {}: {}",
Bold(rpc_message.canonical_name),
human_time(time.time() - start_time),
result_message.result,
),
)
raise LightbusServerError('Error while calling {}: {}\nRemote stack trace:\n{}'.format(
rpc_message.canonical_name,
result_message.result,
result_message.trace,
))
return result_message.result
async def receive_result(self, rpc_message: RpcMessage, return_path: str, options: dict) -> ResultMessage:
logger.info(L("⌛ Awaiting Redis result for RPC message: {}", Bold(rpc_message)))
redis_key = self._parse_return_path(return_path)
pool = await self.get_redis_pool()
with await pool as redis:
start_time = time.time()
# TODO: Make timeout configurable
_, result = await redis.blpop(redis_key, timeout=5)
result_dictionary = redis_decode(result)
logger.info(L(
"⬅ Received Redis result in {} for RPC message {}: {}",
human_time(time.time() - start_time), rpc_message, Bold(result)
))
return ResultMessage.from_dict(result_dictionary)
async def send_result(
self,
rpc_message: RpcMessage,
result_message: ResultMessage,
return_path: asyncio.Future,
bus_client: "BusClient",
):
logger.info(L("⚡️ Directly sending RPC result: {}", Bold(result_message)))
return_path.set_result(result_message)
async def call_rpc(self, rpc_message: RpcMessage, options: dict):
stream = '{}:stream'.format(rpc_message.api_name)
logger.debug(
LBullets(
L("Enqueuing message {} in Redis stream {}", Bold(rpc_message), Bold(stream)),
items=rpc_message.to_dict()
)
)
pool = await self.get_redis_pool()
with await pool as redis:
start_time = time.time()
# TODO: MAXLEN
await redis.xadd(stream=stream, fields=encode_message_fields(rpc_message.to_dict()))
logger.info(L(
"Enqueued message {} in Redis in {} stream {}",
Bold(rpc_message), human_time(time.time() - start_time), Bold(stream)
))
async def send_event(self, event_message: EventMessage, options: dict):
"""Publish an event"""
stream = '{}.{}:stream'.format(event_message.api_name, event_message.event_name)
logger.debug(
LBullets(
L("Enqueuing event message {} in Redis stream {}", Bold(event_message), Bold(stream)),
items=event_message.to_dict()
)
)
pool = await self.get_redis_pool()
with await pool as redis:
start_time = time.time()
# TODO: MAXLEN
await redis.xadd(stream=stream, fields=encode_message_fields(event_message.to_dict()))
logger.info(L(
"Enqueued event message {} in Redis in {} stream {}",
Bold(event_message), human_time(time.time() - start_time), Bold(stream)
))
async def send_result(self, rpc_message: RpcMessage, result_message: ResultMessage, return_path: str):
logger.debug(L(
"Sending result {} into Redis using return path {}",
Bold(result_message), Bold(return_path)
))
redis_key = self._parse_return_path(return_path)
pool = await self.get_redis_pool()
with await pool as redis:
start_time = time.time()
p = redis.pipeline()
p.lpush(redis_key, redis_encode(result_message.to_dict()))
# TODO: Make result expiry configurable
p.expire(redis_key, timeout=60)
await p.execute()
logger.debug(L(
"➡ Sent result {} into Redis in {} using return path {}",
Bold(result_message), human_time(time.time() - start_time), Bold(return_path)
))
def log_welcome_message(
logger: Logger,
transport_registry: TransportRegistry,
schema: "Schema",
plugin_registry: PluginRegistry,
config: Config,
):
"""Show the worker-startup welcome message
"""
logger.info(
LBullets(
"Lightbus is setting up",
items={
"service_name (set with -s or LIGHTBUS_SERVICE_NAME)":
Bold(config.service_name),
"process_name (with with -p or LIGHTBUS_PROCESS_NAME)":
Bold(config.process_name),
},
))
# Log the transport information
rpc_transport = transport_registry.get_rpc_transport("default",
default=None)
result_transport = transport_registry.get_result_transport("default",
default=None)
event_transport = transport_registry.get_event_transport("default",
default=None)
log_transport_information(rpc_transport, result_transport, event_transport,
schema.schema_transport, logger)
if plugin_registry._plugins:
logger.info(
LBullets(
"Loaded the following plugins ({})".format(
len(plugin_registry._plugins)),
items=plugin_registry._plugins,
))
else:
logger.info("No plugins loaded")
async def call_rpc(self, rpc_message: RpcMessage, options: dict):
"""Emit a call to a remote procedure
This only sends the request, it does not await any result (see RedisResultTransport)
"""
queue_key = f"{rpc_message.api_name}:rpc_queue"
expiry_key = f"rpc_expiry_key:{rpc_message.id}"
logger.debug(
LBullets(
L("Enqueuing message {} in Redis list {}", Bold(rpc_message),
Bold(queue_key)),
items=dict(**rpc_message.get_metadata(),
kwargs=rpc_message.get_kwargs()),
))
start_time = time.time()
for try_number in range(3, 0, -1):
last_try = try_number == 1
try:
await self._call_rpc(rpc_message, queue_key, expiry_key)
break
except (PipelineError, ConnectionClosedError,
ConnectionResetError) as e:
if not last_try:
logger.debug(
f"Retrying sending of message. Will retry {try_number} more times. "
f"Error was {type(e).__name__}: {e}")
await asyncio.sleep(self.rpc_retry_delay)
else:
raise
logger.debug(
L(
"Enqueued message {} in Redis in {} stream {}",
Bold(rpc_message),
human_time(time.time() - start_time),
Bold(queue_key),
))
async def _reclaim_lost_messages(self, stream_names: List[str],
consumer_group: str,
expected_events: set):
"""Reclaim messages that other consumers in the group failed to acknowledge"""
with await self.connection_manager() as redis:
for stream in stream_names:
old_messages = await redis.xpending(
stream,
consumer_group,
"-",
"+",
count=self.reclaim_batch_size)
timeout = self.acknowledgement_timeout * 1000
for (
message_id,
consumer_name,
ms_since_last_delivery,
num_deliveries,
) in old_messages:
message_id = decode(message_id, "utf8")
consumer_name = decode(consumer_name, "utf8")
if ms_since_last_delivery > timeout:
logger.info(
L(
"Found timed out event {} in stream {}. Abandoned by {}. Attempting to reclaim...",
Bold(message_id),
Bold(stream),
Bold(consumer_name),
))
result = await redis.xclaim(stream, consumer_group,
self.consumer_name,
int(timeout), message_id)
for claimed_message_id, fields in result:
claimed_message_id = decode(claimed_message_id, "utf8")
event_message = self._fields_to_message(
fields,
expected_events,
native_id=claimed_message_id)
if not event_message:
# noop message, or message an event we don't care about
continue
logger.debug(
LBullets(
L(
"⬅ Reclaimed timed out event {} on stream {}. Abandoned by {}.",
Bold(message_id),
Bold(stream),
Bold(consumer_name),
),
items=dict(
**event_message.get_metadata(),
kwargs=event_message.get_kwargs(),
),
))
yield event_message, stream
async def _consume_rpcs(self, apis: Sequence[Api]) -> Sequence[RpcMessage]:
# Get the name of each list queue
queue_keys = ["{}:rpc_queue".format(api.meta.name) for api in apis]
logger.debug(
LBullets(
"Consuming RPCs from",
items=[
"{} ({})".format(s, self._latest_ids.get(s, "$"))
for s in queue_keys
],
))
with await self.connection_manager() as redis:
try:
try:
stream, data = await redis.blpop(*queue_keys)
except RuntimeError:
# For some reason aio-redis likes to eat the CancelledError and
# turn it into a Runtime error:
# https://github.com/aio-libs/aioredis/blob/9f5964/aioredis/connection.py#L184
raise asyncio.CancelledError(
"aio-redis task was cancelled and decided it should be a RuntimeError"
)
except asyncio.CancelledError:
# We need to manually close the connection here otherwise the aioredis
# pool will emit warnings saying that this connection still has pending
# commands (i.e. the above blocking pop)
redis.close()
raise
stream = decode(stream, "utf8")
rpc_message = self.deserializer(data)
expiry_key = f"rpc_expiry_key:{rpc_message.id}"
key_deleted = await redis.delete(expiry_key)
if not key_deleted:
return []
logger.debug(
LBullets(
L("⬅ Received RPC message on stream {}", Bold(stream)),
items=dict(**rpc_message.get_metadata(),
kwargs=rpc_message.get_kwargs()),
))
return [rpc_message]
def _register_listener(self, events: List[Tuple[str, str]]):
"""A context manager to help keep track of what the bus is listening for"""
logger.info(
LBullets(f"Registering listener for",
items=[Bold(f"{a}.{e}") for a, e in events]))
for api_name, event_name in events:
key = (api_name, event_name)
self._listeners.setdefault(key, 0)
self._listeners[key] += 1
yield
for api_name, event_name in events:
key = (api_name, event_name)
self._listeners[key] -= 1
if not self._listeners[key]:
self._listeners.pop(key)
async def start_listening_for(self, api_name, event_name, options: dict):
stream_name = '{}.{}:stream'.format(api_name, event_name)
options = options or {}
since = options.get('since')
if stream_name in self._streams:
if since:
# We could probably handle this by starting up a new Redis connection
# just for this listener. Let's see if this is needed.
logger.warning(
'Cannot start listening on {}.{} as it is already being listened for. '
'You also specified a "since" value, so be warned you are probably not '
'going to be getting the history of messages you expect. Consider '
'calling stop_listening_for() first.'.format(api_name, event_name)
)
else:
logger.debug('Already listening on event stream {}. Doing nothing.'.format(stream_name))
else:
if not since:
latest_id = '$'
elif hasattr(since, 'timestamp'): # datetime
# Create message ID: "<milliseconds-timestamp>-<sequence-number>"
latest_id = '{}-0'.format(round(since.timestamp() * 1000))
else:
latest_id = since
logger.info(L(
'Will to listen on event stream {} {}',
Bold(stream_name),
'starting now' if self._task else 'once event consumption begins',
))
self._streams[stream_name] = latest_id
if self._task:
logger.debug('Existing consumer task running, cancelling')
self._reload = True
self._task.cancel()
async def fetch_events(self) -> Tuple[Sequence[EventMessage], Any]:
pool = await self.get_redis_pool()
with await pool as redis:
if not self._streams:
logger.debug('Event backend has been given no events to consume. Event backend will sleep.')
self._task = asyncio.ensure_future(asyncio.sleep(3600 * 24 * 365))
else:
logger.info(LBullets(
'Consuming events from', items={
'{} ({})'.format(*v) for v in self._streams.items()
}
))
# TODO: Count/timeout
self._task = asyncio.ensure_future(
redis.xread(
streams=list(self._streams.keys()),
latest_ids=list(self._streams.values()),
count=10, # TODO: Make configurable, add timeout too
)
)
try:
stream_messages = await self._task or []
except asyncio.CancelledError as e:
if self._reload:
# Streams to listen on have changed.
# Bail out and let this method get called again,
# at which point we'll pickup the new streams.
logger.debug('Event transport reloading.')
stream_messages = []
self._reload = False
else:
raise
event_messages = []
latest_ids = {}
for stream, message_id, fields in stream_messages:
stream = decode(stream, 'utf8')
message_id = decode(message_id, 'utf8')
decoded_fields = decode_message_fields(fields)
# Keep track of which event ID we are up to. We will store these
# in consumption_complete(), once we know the events have definitely
# been consumed.
latest_ids[stream] = message_id
# Unfortunately, these is an edge-case when BOTH:
# 1. We are consuming events from 'now' (i.e. event ID '$'), the default
# 2. There is an unhandled error when processing the FIRST batch of events
# In which case, the next iteration would start again from '$', in which
# case we would loose events. Therefore 'subtract one' from the message ID
# and store that immediately. Subtracting one is imprecise, as there is a SLIM
# chance we could grab another event in the process. However, if events are
# being consumed from 'now' then the developer presumably doesn't care about
# a high level of precision.
if self._streams[stream] == '$':
self._streams[stream] = redis_stream_id_subtract_one(message_id)
event_messages.append(
EventMessage.from_dict(decoded_fields)
)
logger.debug(LBullets(
L("⬅ Received event {} on stream {}", Bold(message_id), Bold(stream)),
items=decoded_fields
))
return event_messages, latest_ids
