diff --git a/CHANGELOG.md b/CHANGELOG.md index 36e35c17e..3a05a826c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,102 +3,49 @@ ## [v3.7.1.dev0] ### Added - -- [API] Added `lithops.concurrent.futures`, a `concurrent.futures`-compatible executor interface backed by Lithops. -- [Monitoring] Added Redis, AWS SQS, GCP Pub/Sub and Azure Queue Storage monitoring backends. -- [Core] Added `clean_jobs` to `wait()`, to keep the temporary data until the results are read. -- [AWS Batch] Added the `instance_types` config option for EC2/SPOT compute environments. -- [Multiprocessing] Added `timeout` to `acquire()`, and `_getvalue()`, `_callmethod()` and `copy_proxy()` to the manager proxies. -- [Multiprocessing] Added `ThreadPool`, the standard error classes and the module-level helpers (`freeze_support()`, `get_logger()`, `log_to_stderr()`). -- [Telemetry] Added `lithops.telemetry`, which turns the call statuses the monitor reads into 29 Prometheus or OpenTelemetry metrics. -- [Tests] Added a unit test suite for all non-backend modules. - -### Changed - -- [Core] `wait()` now returns two empty lists instead of `None` for empty input and reuses a single thread pool across polls, and `get_result()` deletes the temporary data once the results are in, not during the wait. -- [Core] Stopping an executor now waits for the invocations already in flight instead of returning while its invoker threads still run. -- [Monitoring] Reorganised job monitoring as pluggable backends: the message backends now delete their queue on cleanup instead of on every `stop()`, so a later `map()` can reuse it, and the storage backend lists only the prefixes of the jobs it still watches. -- [Monitoring] Status lines (Pending/Running/Done) are now logged every 30s instead of on every activation. -- [Multiprocessing] Manager proxies now follow the standard library API more closely, and `Manager()` returns a started manager instead of the class itself. -- [Multiprocessing] Shared objects now refresh their expiry when read, not only when written, and connection polling backs off from 1ms instead of waiting a fixed 100ms. -- [Multiprocessing] `imap()` and `imap_unordered()` now default to the configured chunksize. -- [Localhost] A job that ended cleanly is no longer killed on cleanup, so its runner log is kept. -- [Standalone] `docker login` now reads the password from stdin and quotes its arguments. -- [Storage] `CloudFileProxy.walk()` now yields nothing for a missing path, like `os.walk`, and `cloud_open()` raises `ValueError` on an unsupported mode. -- [Worker] Replaced the `multiprocessing` Manager queue of the worker pool with a POSIX pipe, and a failed task or job process now logs its output instead of only its return code. -- [CLI] `job list`, `worker list`, `image delete` and `image list` now reject unknown flags. -- [Joblib] `lithops_args` is now applied to the pool that runs the batches, and the shared-argument upload and download pools are capped at 32 threads. - -### Fixed - -- [Core] Fixed a repeated submission reusing the first serialization of a callable, freezing its captured state and the dependencies of the first runtime it ran on. -- [Core] Fixed executor IDs repeating in a process whose environment is reset between executors. -- [Core] Fixed `wait()` watching futures of another executor with a monitor that never sees them, leaving behind the monitors it started, and raising `TypeError` from `signal.alarm()` on a fractional timeout. -- [Core] Fixed `result()` returning `None` instead of re-raising when the call had already failed. -- [Core] Fixed module inspection crashing on a function whose `__module__` is `None`, and `SerializeIndependent` appending `lithops` to the preinstalled module list on every job. -- [Core] Fixed a hand-built `FuturesList` raising `AttributeError` instead of creating its executor, and pickling one detaching it from the executor it has. -- [Core] Fixed `find_free_port()` setting `SO_REUSEADDR` after the bind. -- [Core] Fixed `chunksize=0` and `execution_timeout=0` falling back to the config value. -- [Core] Fixed a second Ctrl+C after a failed call turning into `Error in sys.excepthook`, and logging at interpreter shutdown raising on an already closed stream. -- [Core] Fixed the function package carrying `.pytest_cache` directories and stale zips, a failed build leaving a partial zip behind, and `runtime_include_function` leaving the process in the build directory when the build failed. -- [Chaining] Fixed a plain list, tuple or slice of futures not being recognised as a chain, leaving its consumed results in `get_result()`, and `extra_args` failing every activation instead of raising at submit time. -- [Concurrent] Fixed `shutdown()` returning before a submission already in progress had been registered. -- [Job] Fixed a glob pattern in the object name raising `TypeError` instead of listing the objects, and a `head_object()` without `content-length` raising a bare `KeyError`. -- [Job] Fixed the last byte of an object being left out of its partitions, and folder markers being counted as objects, returning empty partitions. -- [Monitoring] Fixed a lost status message or an unread stored status turning into a bogus timeout, hanging `wait()` for ever, or one storage error being enough to declare a timeout. -- [Monitoring] Fixed a nested executor publishing statuses to a queue nobody declares, and failed RabbitMQ publishes being dropped with nothing in the log. -- [Redis] Fixed `put_object()` rejecting file-like objects, which made `upload_file()` always fail, and `head_object()` reporting every key as missing on Redis 7 and up, where the `DEBUG OBJECT` command it relied on is disabled. -- [Redis] Fixed `list_objects()` returning the object bodies instead of their keys and sizes and not skipping keys whose value is gone, `head_bucket()` returning a bool instead of the bucket metadata, and `delete_objects()` raising on an empty list. -- [Redis] Fixed the `bytes=L-` form of the `Range` argument raising `ValueError` and `bytes=-N` returning a single byte instead of the last N, and a ranged read of a missing key returning an empty result instead of raising. -- [Redis] `list_keys()` now walks the key space one pipelined round trip per level instead of one per directory, which cost a round trip per activation when listing a job. -- [Infinispan] Fixed `list_objects()` failing for the whole bucket when one of its objects was empty, since an empty object was reported as a missing key, and reading every value one after the other, at one round trip per key. -- [Infinispan] Fixed the `bytes=L-` and `bytes=-N` forms of the `Range` argument raising `ValueError`. -- [Infinispan] Fixed `head_bucket()` raising `NotImplementedError`, and `put_object()` ignoring a failed request. -- [Infinispan] Fixed the documented `mech` config key being ignored, so `mech: BASIC` silently authenticated with DIGEST. -- [Multiprocessing] Fixed `error_callback` never being called by `apply_async()`, `map_async()` and `starmap_async()`. -- [Multiprocessing] Fixed a full bounded `Queue` silently discarding what was put on it, which now waits and raises `Full`, and `Queue.empty()` always saying True over a pynng connection. -- [Multiprocessing] Fixed shared list writes being dropped or misplaced through slices, `remove()`, `index()`, `pop()` and `del`, and a slice of a shared array returning one element too many. -- [Multiprocessing] Fixed manager proxies not raising the `KeyError`, `ValueError` and `IndexError` the standard library raises. -- [Multiprocessing] Fixed concurrent updates to a shared object overwriting each other, and a shared object being deleted while on its way to a worker. -- [Multiprocessing] Fixed `Condition.wait()` never reporting a notify, keeping a recursively acquired lock so nobody could notify it, and not giving the lock back after a Redis error. -- [Multiprocessing] Fixed over-releasing a lock or bounded semaphore passing silently, and a re-entrant `RLock` giving back a token it never took. -- [Multiprocessing] Fixed `Value()` and `Array()` ignoring their `lock` argument. -- [Multiprocessing] Fixed `lithops.multiprocessing.context` being shadowed by a context instance, which broke every `mp.context.`. -- [Multiprocessing] Fixed closing one connection closing the Redis client the whole process shares. -- [Multiprocessing] Fixed a closed `Pool` leaving the monitor and invoker threads of its executor running, and the remote log feed keeping the interpreter alive at exit. -- [Multiprocessing] Fixed `AsyncResult.get()` raising the builtin `TimeoutError` instead of `multiprocessing.TimeoutError`. -- [Multiprocessing] Fixed `current_process()` in a worker creating an executor and a Redis client just to read a name, and `set_parameter()` rewriting the defaults it falls back to. -- [Localhost] Fixed the v2 job manager spinning a full core: on a job cleared mid-task that left a latch closed, and while an invocation was queueing. -- [Localhost] Fixed a partial `clear()` tearing down the consumers, tasks and latches of other jobs. -- [Localhost] Fixed a task starting after `stop()`, leaving a process nobody kills, and two concurrent `invoke()` calls clearing each other's in-progress flag. -- [Localhost] Fixed the v2 container being removed while other jobs were still running in it. -- [Localhost] Fixed v1 and v2 sharing one runner file, so a job could run under the other version's runner, and the runner exiting with success on an unknown command or a crash. -- [Localhost] Fixed a container image whose name starts with `python`, such as `python:3.12`, being run as a local interpreter. -- [Standalone] Fixed a dict race that killed the budget keeper and left the VM running. -- [Standalone] Fixed a file descriptor leak of the runner log, one per task. -- [Standalone] Fixed the worker `/stop` endpoint iterating the process map while it changed, and `cancel_job_process()` raising on an emptied queue or a job with no queue. -- [Standalone] Fixed the master dropping the errors of its parallel worker and job requests, and a failed consume-mode worker setup script passing unnoticed. -- [Standalone] Fixed the SSH client keeping a client that failed to connect, and rejecting every private key that is not RSA. -- [Standalone] Fixed a reuse-mode worker blocking for ever on a stale queue connection instead of taking the next job. -- [Standalone] Fixed the worker service running a `python:*` container image with the local interpreter. -- [Storage] Fixed `delete_cloudobjects()` deleting the keys of one bucket from another when the objects spanned several, and deleting part of the list before rejecting a foreign object. -- [Storage] Fixed `CloudFileProxy.listdir()` returning nothing for its default argument. -- [Worker] Fixed the remote invoker returning before its invocations in flight were done. -- [Worker] Fixed the function process being aborted on macOS from the second call on, by setting Apple's fork-safety flag, and one killed by the OOM killer, or by any signal, being reported as a missing result. -- [Worker] Fixed the non-Unix worker pool sharing one task object across its calls, mixing up their ids, data and logs, by spawning a process per worker. -- [Azure] Fixed the `az` CLI calls deadlocking when a command filled the stderr pipe. -- [Azure Containers] Fixed a deploy racing a provisioning operation already in progress, and a container app left in `Failed` state never being recreated. -- [CLI] Fixed `job list` and `worker list` crashing when there was nothing to list. -- [CLI] Fixed `lithops clean` deleting the local temp directory of the jobs running at the same time on the same machine. -- [Cleaner] Fixed two cleaners racing for the pid file, and the cleaner skipping the requests it was started for. -- [Cleaner] Fixed the cleaner reading a request another process was still writing, and looping forever on one it could not read or classify. -- [Joblib] Fixed the backend being unused with joblib 1.4+, which renamed `apply_async` to `submit`. -- [Joblib] Fixed shared arguments going to the default storage instead of the configured one, a `KeyError` on those over 32KB from a check-then-read on the disk cache, and a race losing one of two proxied in the same call. -- [Joblib] Fixed `lithops[joblib]` missing `redis`, needed to import the backend. -- [IBM] Fixed the COS token manager raising if `ibm_botocore` hides the private expiry attribute. +- [API] `lithops.concurrent.futures`, a stdlib-compatible executor backed by Lithops. +- [Monitoring] Redis, AWS SQS, GCP Pub/Sub and Azure Queue Storage backends. +- [Core] `clean_jobs` on `wait()`, to keep temporary data until results are read. +- [AWS Batch] `instance_types` for EC2/SPOT compute environments. +- [Multiprocessing] `ThreadPool`, stdlib helpers, proxy methods, `acquire(timeout)` and `Condition.notify(n)`. +- [Telemetry] Prometheus and OpenTelemetry metrics from call statuses. +- [Tests] Unit test suite for all non-backend modules. + +### Changed +- [Core] `wait()` returns `[], []` for empty input, reuses one thread pool, and only ends the jobs it waited on. +- [Core] `get_result()` cleans after the results are in; stopping an executor waits for in-flight invocations. +- [Core] A list or tuple of futures as `iterdata` or `call_async()` data is now a chain. +- [Monitoring] Pluggable backends; queues live until cleanup (RabbitMQ expires after 24h); status lines every 30s. +- [Monitoring] The job monitor stays up across `map()`/`wait()` of the same executor, so the next job is not delayed by joining and replacing it. +- [Multiprocessing] Closer stdlib API: started `Manager()`, default `imap` chunksize, expiry refresh on read. +- [Worker] POSIX pipe instead of a Manager queue; `SystemExit`/`KeyboardInterrupt` reported as the function's exception. +- [Localhost] A clean job is no longer killed on cleanup, so its runner log is kept. +- [Standalone] `docker login` reads the password from stdin and quotes its arguments. +- [Storage] `CloudFileProxy.walk()` matches `os.walk` on a missing path; `cloud_open()` rejects an unsupported mode. +- [CLI] `job list`, `worker list`, `image delete` and `image list` reject unknown flags. +- [Joblib] `lithops_args` applied to the batch pool; upload/download pools capped at 32 threads. + +### Fixed +- [Core] Serialization, executor IDs, `FuturesList`, module inspection, `chunksize=0`, packaging, ports, and Ctrl+C/`sys.exit()`. +- [Core] `wait()`/`clean()`/`get_result()` no longer drop unread results, other jobs' calls, or FaaS concurrency after a failure. +- [Chaining] Lists, tuples and slices of futures recognised as a chain; `extra_args` fails at submit time. +- [Concurrent] `shutdown()` waits for an in-progress submit. +- [Job] Object listing, partitions, and `head_object()` without `content-length`. +- [Monitoring] Lost statuses, token leaks, races, nested-executor queues, oversized messages, and remote-invoker cleanup. +- [Redis] `put_object`, `head_object`, `list_objects`/`list_keys`, `delete_objects`, and `Range` reads. +- [Infinispan] `list_objects`, `Range`, `head_bucket`, `put_object`, and the `mech` config key. +- [Multiprocessing] Pool `get()`/`ready()`/`join()`/callbacks, queues, locks, lists, refcounts, and proxy errors. +- [Localhost] Job-manager races, container lifetime, runner files, and `python:*` images taken as interpreters. +- [Standalone] Budget keeper, log FD leak, `/stop`, SSH, reuse-mode queue, and `python:*` images. +- [Storage] `delete_cloudobjects()` across buckets; `CloudFileProxy.listdir()` default. +- [Worker] Remote invoker shutdown, unpickleable exceptions, timeout/OOM reports, macOS fork-safety, and the non-Unix pool. +- [Azure] `az` CLI deadlock; container-app deploy races. +- [CLI] Empty `job`/`worker` lists; `lithops clean` deleting other jobs' local temp. +- [Cleaner] Pid-file races and unreadable requests. +- [Joblib] joblib 1.4+ `submit`, shared-argument storage/cache, and the missing `redis` extra. +- [IBM] COS token manager with `ibm_botocore`. ### Removed - - [Storage] Removed the `infinispan_hotrod` storage backend. ## [v3.7.0] diff --git a/lithops/executors.py b/lithops/executors.py index b0d33d932..73a0393f9 100644 --- a/lithops/executors.py +++ b/lithops/executors.py @@ -103,6 +103,15 @@ def _missing_plotting_extra(method_name: str) -> ModuleNotFoundError: ) +def _output_settled(future) -> bool: + """ + Whether nothing is left to read from storage for this call: its result + was downloaded or it produced none, it failed, or it handed back + futures of its own + """ + return future.done or future.futures + + def _group_futures_by_job( futures: List[Any] ) -> List[Tuple[str, str, List[Any], List[Any]]]: @@ -449,7 +458,21 @@ def _cleanup_jobs(self, futures, exception=None, force=False): self.compute_handler.clear(present_jobs) else: self.compute_handler.clear(present_jobs, exception=exception) - self.clean(clean_cloudobjects=False, force=force) + self.clean(fs=futures, clean_cloudobjects=False, force=force) + + def _release_finished_from_monitor(self, futures): + """ + Drops futures that have already reported back, so the monitor does + not keep listing their prefixes. The thread stays up: the next + map() of this executor adds to it instead of joining a stopped + one and spawning another + """ + finished = [ + f for f in futures + if getattr(f, 'ready', False) or f.success or f.done + ] + if finished: + self.job_monitor.remove(finished) def _stop_monitor_if_idle(self, extra_fs=None): """ @@ -764,17 +787,25 @@ def wait( futures_from_executor_wait=not fs, ) - self._stop_monitor_if_idle(futures) + self._release_finished_from_monitor(futures) if do_clean and return_when == ALL_COMPLETED: self._cleanup_jobs(futures) except (KeyboardInterrupt, Exception) as e: - self.invoker.stop(wait=True) + if isinstance(e, KeyboardInterrupt): + self.invoker.stop(wait=True) + else: + # Only the jobs waited on end here. Another job of this + # executor may still have calls queued for a free worker + self.invoker.discard_pending( + {f.job_key for f in futures}, + {f.job_id for f in futures}, + ) self.job_monitor.remove(futures) for future in futures: future._set_exception() self._stop_monitor_if_idle(futures) - if self.data_cleaner: + if do_clean: self._cleanup_jobs(futures, exception=e, force=True) raise @@ -808,7 +839,7 @@ def get_result( :return: The result of the future/s """ pending_to_read = ( - len(fs) if fs + len(self._as_future_list(fs)) if fs else sum(1 for f in self.futures if not f._read and not f.futures) ) @@ -961,11 +992,26 @@ def clean( }) futures = self._as_future_list(fs or self.futures) - present_jobs = { - create_job_key(f.executor_id, f.job_id) - for f in futures - if (f.executor_id.count('-') == 1 and f.done) or force - } + if force or on_exit: + # On exit nothing will read the leftover results, so a job + # that still has one unread call would otherwise stay forever + present_jobs = { + create_job_key(f.executor_id, f.job_id) for f in futures + } + else: + # A job's data is one prefix, so it goes only once no call of + # the job, including the ones not passed here, still has a + # result to read from it + unread_jobs = { + create_job_key(f.executor_id, f.job_id) + for f in list(self.futures) + list(futures) + if not _output_settled(f) + } + present_jobs = { + create_job_key(f.executor_id, f.job_id) + for f in futures + if f.executor_id.count('-') == 1 and f.done + } - unread_jobs jobs_to_clean = present_jobs - self.cleaned_jobs if jobs_to_clean: diff --git a/lithops/future.py b/lithops/future.py index 4cd6261a6..a564a152e 100644 --- a/lithops/future.py +++ b/lithops/future.py @@ -277,6 +277,14 @@ def _raise_call_exception(self, throw_except): except Exception: pass fn_exc.args = (fn_exc.args[1],) + # tblib rebuilds a SystemExit from its args and leaves code at + # None, which would end the client with status 0 whatever the + # function passed to sys.exit() + if isinstance(fn_exc, SystemExit) and fn_exc.code is None \ + and fn_exc.args: + fn_exc.code = ( + fn_exc.args[0] if len(fn_exc.args) == 1 else fn_exc.args + ) else: fn_exctype = Exception fn_exc = Exception(self._exception['exc_value']) @@ -452,7 +460,7 @@ def status( if 'new_futures' in self._call_status and not self._new_futures: self._resolve_new_futures() - elif self._call_status['func_result_size'] == 0: + elif self._call_status.get('func_result_size', 0) == 0: self._produce_output = False if 'result' in self._call_status: diff --git a/lithops/invokers.py b/lithops/invokers.py index c7ef97d1c..6732cf107 100644 --- a/lithops/invokers.py +++ b/lithops/invokers.py @@ -309,6 +309,13 @@ def stop(self, wait: bool = False): """ pass + def discard_pending(self, job_keys, job_ids=None): + """ + Drops the calls of the given jobs not invoked yet. Only an invoker + that queues calls has any + """ + pass + class BatchInvoker(Invoker): """ @@ -540,6 +547,45 @@ def _invoke_job_remote(self, job): return raise Exception('Unable to spawn remote invoker') + def _empty_token_bucket(self): + while True: + try: + self.job_monitor.token_bucket_q.get(block=False) + except queue.Empty: + return + + def discard_pending(self, job_keys, job_ids=None): + """ + Drops the calls of the given jobs that are still waiting for a + worker, leaving the queued calls of every other job in place. + + The monitor also stops tracking those jobs, so their workers will + not hand tokens back. When no other job is still queued, the count + of running workers is forgotten; otherwise a later map() of the + same executor stays capped by workers that never free + """ + kept = [] + while True: + try: + item = self.pending_calls_q.get(block=False) + except queue.Empty: + break + job, _ = item + if job is None or job.job_key not in job_keys: + kept.append(item) + other_jobs = False + for item in kept: + job, _ = item + if job is not None: + other_jobs = True + self.pending_calls_q.put(item) + if other_jobs: + return + self._empty_token_bucket() + self.running_workers = 0 + if job_ids and self.job_monitor is not None: + self.job_monitor.close_jobs(job_ids) + def _drain_token_bucket(self): """ Takes back the tokens left over by previous jobs, one per worker that @@ -595,6 +641,10 @@ def _invoke_job(self, job): prefix = log_prefix(job.executor_id, job.job_id) if not self.should_run: + # Tokens a monitor handed back after the stop belong to workers + # this restart no longer counts, and would each invoke one more + # worker than max_workers allows + self._empty_token_bucket() self.running_workers = 0 self.should_run = True self._start_async_invokers() diff --git a/lithops/localhost/config.py b/lithops/localhost/config.py index 22422a08d..3cae0ef0c 100644 --- a/lithops/localhost/config.py +++ b/lithops/localhost/config.py @@ -30,12 +30,10 @@ LOCALHOST_EXECUTION_TIMEOUT = 3600 _WINDOWS_PATH = re.compile(r'^(?:[A-Za-z]:[\\/]|\\\\)') -# Interpreters like python, python3, python3.12, python.exe — not docker tags -# such as python:3.12. -_PYTHON_INTERPRETER = re.compile( - r'^python(\d+(\.\d+)*)?(\.exe)?$', - re.IGNORECASE, -) +# Interpreters like python3.12, python3.13t, python3-intel64 or pythonw.exe. +# Docker tags and repositories such as python:3.12 or registry/python always +# carry a ':' or a '/', which an interpreter name never does. +_PYTHON_INTERPRETER = re.compile(r'^python[^:/\\]*$', re.IGNORECASE) class LocalhostEnvironment(Enum): @@ -53,7 +51,10 @@ def get_environment(runtime_name: str) -> LocalhostEnvironment: if ( runtime_name.startswith('/') or _WINDOWS_PATH.match(runtime_name) is not None - or _PYTHON_INTERPRETER.match(basename) is not None + or ( + '/' not in runtime_name + and _PYTHON_INTERPRETER.match(basename) is not None + ) ): return LocalhostEnvironment.DEFAULT return LocalhostEnvironment.CONTAINER diff --git a/lithops/monitoring/backends/aws_sqs/status.py b/lithops/monitoring/backends/aws_sqs/status.py index 4adfe845a..dcef8abb8 100644 --- a/lithops/monitoring/backends/aws_sqs/status.py +++ b/lithops/monitoring/backends/aws_sqs/status.py @@ -12,15 +12,11 @@ # limitations under the License. # -import logging from functools import cached_property from lithops.monitoring.backends.aws_sqs import aws_sqs as sqs_backend -from lithops.monitoring.monitor import is_named_error from lithops.monitoring.status import MessageCallStatus -logger = logging.getLogger(__name__) - class SqsCallStatus(MessageCallStatus): """ @@ -29,6 +25,7 @@ class SqsCallStatus(MessageCallStatus): """ service_name = 'SQS' + MAX_MESSAGE_SIZE = 256 * 1024 def __init__(self, job, internal_storage): super().__init__(job, internal_storage) @@ -51,23 +48,14 @@ def _queue_url(self, name): """ The URL of a queue by name, looked up once per call. - The monitor of the executor created the queue before any worker was - invoked, so this normally just resolves it; it is created here only - when it is really not there, which is what a status published to an - executor further up the chain can run into + The monitor that reads the queue created it before any worker was + invoked. One that is not there belongs to a reader that is gone, and + creating it again would leave a queue nobody deletes """ url = self._urls.get(name) if url: return url - try: - url = self.client.get_queue_url(QueueName=name)['QueueUrl'] - except Exception as exc: - if not is_named_error( - exc, 'QueueDoesNotExist', 'NonExistentQueue' - ): - raise - logger.debug(f'The SQS queue {name} is not there; creating it') - url = self.client.create_queue(QueueName=name)['QueueUrl'] + url = self.client.get_queue_url(QueueName=name)['QueueUrl'] self._urls[name] = url return url @@ -75,9 +63,8 @@ def close(self) -> None: self._urls.clear() super().close() - def _publish(self, payload: str) -> None: - for name in self._targets(): - self.client.send_message( - QueueUrl=self._queue_url(name), - MessageBody=payload, - ) + def _publish_to(self, target: str, payload: str) -> None: + self.client.send_message( + QueueUrl=self._queue_url(target), + MessageBody=payload, + ) diff --git a/lithops/monitoring/backends/azure_queue/status.py b/lithops/monitoring/backends/azure_queue/status.py index 84c3b482d..9e5e6b4da 100644 --- a/lithops/monitoring/backends/azure_queue/status.py +++ b/lithops/monitoring/backends/azure_queue/status.py @@ -27,6 +27,11 @@ class AzureQueueCallStatus(MessageCallStatus): """ service_name = 'Azure Queue' + #: The service takes 64 KiB per message, measured once the SDK has + #: encoded it: XML-escaped text by default, base64 when the queue client + #: is configured so, which is 4/3 of the text. Three quarters of the + #: limit fits either way + MAX_MESSAGE_SIZE = 48 * 1024 def __init__(self, job, internal_storage): super().__init__(job, internal_storage) @@ -47,9 +52,6 @@ def service(self): ), ) - def _targets(self): - return [azure_queue_name(name) for name in super()._targets()] - def _queue(self, name): name = azure_queue_name(name) client = self._queues.get(name) @@ -71,6 +73,5 @@ def close(self) -> None: self._queues.clear() super().close() - def _publish(self, payload: str) -> None: - for name in self._targets(): - self._queue(name).send_message(payload) + def _publish_to(self, target: str, payload: str) -> None: + self._queue(target).send_message(payload) diff --git a/lithops/monitoring/backends/gcp_pubsub/status.py b/lithops/monitoring/backends/gcp_pubsub/status.py index 8baa153ce..e88bbba25 100644 --- a/lithops/monitoring/backends/gcp_pubsub/status.py +++ b/lithops/monitoring/backends/gcp_pubsub/status.py @@ -12,16 +12,12 @@ # limitations under the License. # -import logging from functools import cached_property from lithops.monitoring.backends.gcp_pubsub import gcp_pubsub as pubsub_backend from lithops.monitoring.backends.gcp_pubsub.gcp_pubsub import _topic_path -from lithops.monitoring.monitor import is_named_error from lithops.monitoring.status import MessageCallStatus -logger = logging.getLogger(__name__) - class GcpPubsubCallStatus(MessageCallStatus): """ @@ -30,13 +26,13 @@ class GcpPubsubCallStatus(MessageCallStatus): """ service_name = 'Pub/Sub' + MAX_MESSAGE_SIZE = 10 * 1000 * 1000 def __init__(self, job, internal_storage): super().__init__(job, internal_storage) self.project = ( self.config.get('gcp_pubsub') or {} ).get('project_name') - self._topics = set() @cached_property def publisher(self): @@ -54,38 +50,11 @@ def build(): return self.obtain_client('publisher', build) - def _ensure_topic(self, name): - """ - The path of a topic, created if it is not there. - - The monitor of the executor created the topic before any worker was - invoked, so AlreadyExists is the normal answer here; anything else - is a real failure and is left for _send() to retry and report - """ - path = _topic_path(self.project, name) - if path in self._topics: - return path - try: - self.publisher.create_topic(name=path) - except Exception as exc: - if not is_named_error(exc, 'AlreadyExists', 'PermissionDenied'): - raise - if is_named_error(exc, 'PermissionDenied'): - # A worker that may publish but not create topics is fine, - # as long as the topic is already there - logger.debug( - f'Not allowed to create the Pub/Sub topic {name}; ' - 'assuming it exists' - ) - self._topics.add(path) - return path - - def close(self) -> None: - self._topics.clear() - super().close() - - def _publish(self, payload: str) -> None: - data = payload.encode('utf-8') - for name in self._targets(): - future = self.publisher.publish(self._ensure_topic(name), data) - future.result(timeout=10) + def _publish_to(self, target: str, payload: str) -> None: + # The monitor that reads the topic created it before any worker was + # invoked. One that is not there belongs to a reader that is gone, + # and the NotFound is what tells the caller so + future = self.publisher.publish( + _topic_path(self.project, target), payload.encode('utf-8') + ) + future.result(timeout=10) diff --git a/lithops/monitoring/backends/rabbitmq/rabbitmq.py b/lithops/monitoring/backends/rabbitmq/rabbitmq.py index a3b0a083e..ba07678a0 100644 --- a/lithops/monitoring/backends/rabbitmq/rabbitmq.py +++ b/lithops/monitoring/backends/rabbitmq/rabbitmq.py @@ -37,6 +37,11 @@ class RabbitmqMonitor(PollingMessageMonitor): cost a round trip per message. """ + #: How long the broker keeps the queue once nothing consumes from or + #: declares it, in seconds. cleanup() deletes it; this is only for a + #: client that died before getting there + QUEUE_EXPIRES = 24 * 3600 + def __init__( self, executor_id, @@ -70,22 +75,30 @@ def __init__( def _create_resources(self): """ - Opens the connection and declares the queue the workers publish to + Opens the connection and declares the queue the workers publish to. + + Not an auto-delete queue: the broker would delete it as soon as a + stopped monitor cancels its consumer, and whatever the workers still + running publish before the next monitor declares it again would be + dropped. cleanup() deletes it instead """ logger.debug( f'{log_prefix(self.executor_id)} - Creating RabbitMQ queue {self.queue}' ) self.connection = pika.BlockingConnection(self.pikaparams) channel = self.connection.channel() - channel.queue_declare(queue=self.queue, auto_delete=True) + channel.queue_declare( + queue=self.queue, + auto_delete=False, + arguments={'x-expires': self.QUEUE_EXPIRES * 1000}, + ) channel.close() def _consume(self, timeout): """ Returns the consumer generator, opening it on the first call and - after a connection has been lost. The queue is declared again on - the way, since an auto-delete queue is gone once its last consumer - has left + after a connection has been lost, in which case the queue is + declared again on the way """ if self.consumer is None: if self.connection is None or self.connection.is_closed: diff --git a/lithops/monitoring/backends/rabbitmq/status.py b/lithops/monitoring/backends/rabbitmq/status.py index c6fa5d808..0f936d0ef 100644 --- a/lithops/monitoring/backends/rabbitmq/status.py +++ b/lithops/monitoring/backends/rabbitmq/status.py @@ -95,15 +95,15 @@ def close(self) -> None: self._drop_channel() self._amqp = None - def _publish(self, payload: str) -> None: + def _publish_to(self, target: str, payload: str) -> None: + # Through the default exchange, which drops a message for a queue + # that is not there rather than creating it try: - channel = self._channel() - for queue in self._targets(): - channel.basic_publish( - exchange='', - routing_key=queue, - body=payload - ) + self._channel().basic_publish( + exchange='', + routing_key=target, + body=payload + ) except Exception: # The connection is broken, or was never opened. Dropped here so # that the retry of _send(), and the next call of this worker, diff --git a/lithops/monitoring/backends/redis/status.py b/lithops/monitoring/backends/redis/status.py index 02c5dd1b9..d5daaad96 100644 --- a/lithops/monitoring/backends/redis/status.py +++ b/lithops/monitoring/backends/redis/status.py @@ -28,6 +28,11 @@ class RedisCallStatus(MessageCallStatus): service_name = 'Redis' + #: How long a list that only best-effort publishes feed outlives the + #: last of them. A push onto a list that was deleted creates it again, + #: and nothing would come back to delete that one + BEST_EFFORT_TTL = 3600 + @cached_property def client(self): """ @@ -41,6 +46,11 @@ def client(self): lambda: redis_backend.redis_client(self.config.get('redis') or {}), ) - def _publish(self, payload: str) -> None: - for queue in self._targets(): - self.client.rpush(queue, payload) + def _publish_to(self, target: str, payload: str) -> None: + self.client.rpush(target, payload) + + def _publish_best_effort(self, target: str, payload: str) -> None: + pipe = self.client.pipeline() + pipe.rpush(target, payload) + pipe.expire(target, self.BEST_EFFORT_TTL) + pipe.execute() diff --git a/lithops/monitoring/backends/storage/storage.py b/lithops/monitoring/backends/storage/storage.py index 90dfec162..0826cafa5 100644 --- a/lithops/monitoring/backends/storage/storage.py +++ b/lithops/monitoring/backends/storage/storage.py @@ -23,6 +23,7 @@ _future_id, _is_finished, _is_started, + _status_id, ) from lithops.utils import log_prefix @@ -80,6 +81,7 @@ def __init__( self.callids_done_processed_status = set() self._ready_pool = None self._last_blind_sweep = time.time() + self._final_sweep = False @classmethod def prepare_config(cls, config, internal_storage): @@ -206,7 +208,7 @@ def _generate_tokens(self, callids_running, callids_done): Hands a token back to the invoker for every worker that finished the whole chunk of calls it was given """ - if not self.generate_tokens or not self.should_run: + if not self.generate_tokens or not self._releases_tokens(): return running_new = ( @@ -217,10 +219,16 @@ def _generate_tokens(self, callids_running, callids_done): for call_id, worker_id in running_new: self.callids_running_worker[call_id] = worker_id + # A completion whose init mark is not in this listing yet has no + # worker to charge it to. Leaving it out of the processed set means + # the next listing, which may carry the init, still counts it. + # Marking it processed here drops the token for good + attributed = set() for callid_done in done_new: worker_id = self.callids_running_worker.get(callid_done) if worker_id is None: continue + attributed.add(callid_done) self.callids_done_worker.setdefault(worker_id, set()).add( callid_done ) @@ -228,31 +236,77 @@ def _generate_tokens(self, callids_running, callids_done): # can be looked up without picking a call id back out of the set self.worker_job.setdefault(worker_id, callid_done[1]) + self._release_free_workers() + + self.callids_running_processed.update(running_new) + self.callids_done_processed.update(attributed) + + def _release_free_workers(self): + """ + Hands a token back for every worker whose calls are all done. + + A listing carries no status, so how many calls a worker was given + is worked out from any one of them: the invoker hands the calls out + in consecutive chunks from call 0, so the chunk a call falls in, and + the number of calls of the job, say how long that chunk is + """ present_jobs = self.present_jobs for worker_id, done_calls in self.callids_done_worker.items(): if worker_id in self.workers_done: continue job_id = self.worker_job.get(worker_id) - if job_id is None or job_id not in present_jobs: + if job_id is None or job_id in self._token_closed_jobs: + continue + if job_id not in present_jobs: continue chunksize = self.job_chunksize.get(job_id) - if chunksize is None or len(done_calls) < chunksize: + if chunksize is None: + continue + worker_calls = self._worker_calls( + *next(iter(done_calls)), chunksize + ) + if len(done_calls) < worker_calls: continue self.workers_done.add(worker_id) - if not self.should_run: + if not self._releases_tokens(): break self.token_bucket_q.put('#') - self.callids_running_processed.update(running_new) - self.callids_done_processed.update(done_new) + def _releases_tokens(self): + """ + Whether a worker found free is handed back to the invoker. The final + sweep runs once the monitor is stopped and still counts: a worker it + finds free belongs to a job no later monitor watches, and its token + would otherwise be gone for the rest of the session + """ + return self.should_run or self._final_sweep + + def _release_timed_out_worker(self, call_status): + worker_id = call_status.get('activation_id') + if not self.generate_tokens or worker_id is None: + return + if call_status['executor_id'] != self.executor_id: + return + self.callids_done_worker.setdefault(worker_id, set()).add( + _status_id(call_status) + ) + self.worker_job.setdefault(worker_id, call_status['job_id']) + self._release_free_workers() def _poll_and_process_job_status(self): """ Reads the job status from storage and applies it to the futures. Returns the call ids that are newly done """ + # Nothing tracked: do not list. An empty job_ids used to list the + # whole executor prefix, which on S3 is a LIST of every leftover + # job key and the function pickle, once per monitoring_interval, + # for as long as the monitor stays up after wait() + job_ids = self.job_ids() + if not job_ids: + return set() status = self.internal_storage.get_job_status( - self.executor_id, job_ids=self.job_ids() + self.executor_id, job_ids=job_ids ) callids_running, callids_done = status new_callids_done = ( @@ -298,6 +352,7 @@ def run(self): # One last sweep, so that statuses written between the final poll # and the stop are not lost. The storage may already be gone + self._final_sweep = True try: self._poll_and_process_job_status() except Exception as e: @@ -305,6 +360,8 @@ def run(self): f'{log_prefix(self.executor_id)} - The final status sweep ' f'did not go through: {e}' ) + finally: + self._final_sweep = False self._print_status_log(force=True) self._shutdown_ready_pool() diff --git a/lithops/monitoring/job_monitor.py b/lithops/monitoring/job_monitor.py index 0fdf6d719..a902fbeac 100644 --- a/lithops/monitoring/job_monitor.py +++ b/lithops/monitoring/job_monitor.py @@ -62,6 +62,7 @@ def __init__( self.token_bucket_q = queue.Queue() self.monitor = None self.job_chunksize = {} + self.job_total_calls = {} # Metrics are produced from the statuses the monitor reads, so the # telemetry of the executor is resolved here and handed to every @@ -79,7 +80,10 @@ def start(self, fs, job_id=None, chunksize=None, generate_tokens=False): """ if job_id: self.job_chunksize[job_id] = chunksize + self.job_total_calls[job_id] = len(fs) + # A monitor prepare() just built has not started yet, and is the one + # the workers of this job already report to if not self.monitor or self._thread_finished(): self._spawn_monitor(generate_tokens) elif generate_tokens: @@ -94,8 +98,13 @@ def prepare(self): """ Creates backend resources (queues, keys) before workers are invoked, so the first status is not published into nowhere. + + A monitor a failed wait() or the executor exit stopped is replaced + here, and not in start(), which runs once the workers are already + reporting: its thread may still be in a read that takes the first + statuses of the new job to the grave """ - if self.monitor is None: + if self.monitor is None or self._thread_finished(): self._spawn_monitor(generate_tokens=False) def _spawn_monitor(self, generate_tokens): @@ -103,6 +112,7 @@ def _spawn_monitor(self, generate_tokens): # thread is waited for first: two threads reading the same queue # would split the statuses between them, and the one on its way out # takes what it reads to the grave + previous = self.monitor self._join_monitor() monitor_config = self.MonitorClass.prepare_config( self.config, self.internal_storage @@ -120,9 +130,12 @@ def _spawn_monitor(self, generate_tokens): generate_tokens=generate_tokens, config=monitor_config ) + self.monitor.job_total_calls = self.job_total_calls # Attached before the caller adds any future, so that no status # can reach the monitor while it is still pointing at the no-op self.monitor.attach_telemetry(self.telemetry) + if previous is not None: + self.monitor.adopt_held_status(previous) def _thread_finished(self): """ @@ -173,6 +186,15 @@ def remove(self, fs): if self.monitor and self.monitor.is_alive(): self.monitor.remove_futures(fs) + def close_jobs(self, job_ids): + """ + The invoker will no longer wait for these jobs. Later statuses of + theirs must not hand another token back: the capacity they held + was already forgotten + """ + if self.monitor is not None: + self.monitor.close_jobs(job_ids) + def stop(self): """ Asks the monitor thread to exit, without waiting for it. diff --git a/lithops/monitoring/monitor.py b/lithops/monitoring/monitor.py index 195370285..550750398 100644 --- a/lithops/monitoring/monitor.py +++ b/lithops/monitoring/monitor.py @@ -24,6 +24,11 @@ from tblib import pickling_support +from lithops.monitoring.status import ( + LOGS_FIELD, + PARTIAL_STATUS_KEY, + chunk_call_count, +) from lithops.telemetry import NOOP as NOOP_TELEMETRY from lithops.telemetry.metrics import OUTCOME_CHAINED, OUTCOME_TIMEOUT from lithops.utils import _future_id, log_prefix, monitoring_queue_name @@ -106,6 +111,12 @@ class Monitor(threading.Thread): #: How many statuses that arrived before their future may be held MAX_HELD_STATUS = 100_000 + #: How long a held status may wait for its future beyond the longest + #: execution timeout of the tracked futures. The future of a nested call + #: comes to light in the status of the call that returned it, which + #: finishes within its own execution timeout or is timed out + HELD_STATUS_SLACK = 300 + #: Where the metrics of every call go. A class attribute, so that a #: monitor nobody attached telemetry to is safe rather than broken, #: and so that a backend that forgets to call super().__init__() does @@ -140,6 +151,9 @@ def __init__(self, executor_id, self._stopped = threading.Event() self.token_bucket_q = token_bucket_q self.job_chunksize = job_chunksize + # Calls per job of this executor, which tells the size of the last + # chunk of a job. Filled in by JobMonitor, which shares its own + self.job_total_calls = {} self.generate_tokens = generate_tokens self.config = config self.daemon = True @@ -149,6 +163,11 @@ def __init__(self, executor_id, # read from the monitor thread. One lock covers the set, the index # that finds a future by its call id, and the set of live job ids self._futures_lock = threading.RLock() + # State changes and token accounting run on the monitor thread and + # on the thread that submits a job (it applies statuses that arrived + # early). One lock, re-entrant because applying one status can + # reveal the futures whose own statuses were held + self._apply_lock = threading.RLock() self.futures = set() self._futures_by_id = {} self._timeout_query_failures = {} @@ -157,11 +176,17 @@ def __init__(self, executor_id, # vars for _generate_tokens self.workers_done = set() self.callids_done_worker = {} + # Jobs whose capacity the invoker already forgot. A late __end__ + # of theirs must not put another token in the bucket + self._token_closed_jobs = set() + # Jobs wait() dropped, whose workers still have to free a token + self._dropped_jobs = set() # vars for MessageMonitor._hold_status self._held_status = {} self._held_lock = threading.Lock() self._held_overflow_logged = False self._held_may_match = False + self._max_execution_timeout = 0 # When a status last arrived. A channel that is delivering has # nothing for the storage sweep to recover self._last_message_tstamp = time.time() @@ -239,6 +264,12 @@ def add_futures(self, fs): self.present_jobs = self.present_jobs | { future.job_id for future in fs } + self._max_execution_timeout = max( + [self._max_execution_timeout] + [ + getattr(future, 'execution_timeout', None) or 0 + for future in fs + ] + ) def remove_futures(self, fs): """ @@ -251,7 +282,19 @@ def remove_futures(self, fs): future_id = _future_id(future) if self._futures_by_id.get(future_id) is future: del self._futures_by_id[future_id] - self.present_jobs = {future.job_id for future in self.futures} + remaining = {future.job_id for future in self.futures} + self.present_jobs = remaining + self._dropped_jobs.update( + future.job_id for future in fs if future.job_id not in remaining + ) + + def close_jobs(self, job_ids): + """ + Marks jobs whose remaining worker tokens the invoker already + wrote off, so a late status does not hand one back again + """ + with self._apply_lock: + self._token_closed_jobs.update(job_ids) def tracked_futures(self): """ @@ -311,6 +354,37 @@ def cleanup(self): self._cleaned = True self._delete_resources() + def adopt_held_status(self, other): + """ + Takes over the statuses another monitor of the same queue was holding + for futures it did not track yet. Called on the monitor that replaces + it, before any future is added, so they are not lost with the old one + """ + with other._held_lock: + held, other._held_status = other._held_status, {} + if not held: + return + with self._held_lock: + self._held_status = {**held, **self._held_status} + self._held_may_match = True + + def _worker_calls(self, executor_id, job_id, call_id, chunksize): + """ + How many calls the worker that ran ``call_id`` was given, which is + the chunksize but for the last chunk of a job whose size is known + """ + total_calls = None + if executor_id == self.executor_id: + total_calls = self.job_total_calls.get(job_id) + return chunk_call_count(call_id, chunksize, total_calls) + + def _release_timed_out_worker(self, call_status): + """ + Counts a call that was timed out as done for the token bucket, so + that a worker that never reported back still hands its token back + once every other call of its chunk is done + """ + def attach_telemetry(self, telemetry): """ Points the monitor at the telemetry of its executor. Called by @@ -329,8 +403,14 @@ def _mark_running(self, future, call_status): service that redelivers a status, or a storage sweep that reads one the channel already delivered, therefore counts once """ - future._set_running(call_status) - self.telemetry.on_call_started(future, call_status) + with self._apply_lock: + # Checked again under the lock. The caller checked too, but an + # __end__ on the other thread can land between that check and + # here, and this write would put the call back to running + if _is_started(future): + return + future._set_running(call_status) + self.telemetry.on_call_started(future, call_status) def _mark_ready(self, future, call_status, outcome=None): """ @@ -340,8 +420,11 @@ def _mark_ready(self, future, call_status, outcome=None): Measured after the transition, so that the timestamp the future records for the arrival of the status is part of what is measured """ - future._set_ready(call_status) - self.telemetry.on_call_finished(future, call_status, outcome) + with self._apply_lock: + if _is_finished(future): + return + future._set_ready(call_status) + self.telemetry.on_call_finished(future, call_status, outcome) def _all_ready(self): """ @@ -449,6 +532,7 @@ def _future_timeout_checker(self, futures=None): 'worker_end_tstamp': time.time(), } self._mark_ready(fut, call_status, OUTCOME_TIMEOUT) + self._release_timed_out_worker(call_status) def _print_status_log(self, force=False): """ @@ -514,16 +598,35 @@ def _hold_status(self, call_status): the status that tells this monitor the nested futures exist. A message is read once, so dropping it here would leave a future running for ever. Held by call id, so an __end__ supersedes the - __init__ of the same call + __init__ of the same call. + + A worker that waits on an executor of its own sends every status of + it here, most of which never match a future of this one. They are + held without their logs, which are most of their size and which the + future can do without, and they give way once too old to match """ + held = dict(call_status) + held.pop(LOGS_FIELD, None) + status_id = _status_id(held) + now = time.time() with self._held_lock: - self._held_status[_status_id(call_status)] = call_status + # Taken out first, so that the dict stays in order of arrival + # and the first key is always the oldest + self._held_status.pop(status_id, None) + self._held_status[status_id] = (now, held) self._held_may_match = True + + oldest = now - self._max_execution_timeout - self.HELD_STATUS_SLACK + while self._held_status: + first = next(iter(self._held_status)) + if self._held_status[first][0] >= oldest: + break + del self._held_status[first] + if len(self._held_status) <= self.MAX_HELD_STATUS: return # A status whose future never shows up would be held for the - # whole life of the executor, so the oldest ones give way. A - # dict keeps insertion order, so the first key is the oldest + # whole life of the executor, so the oldest ones give way while len(self._held_status) > self.MAX_HELD_STATUS: del self._held_status[next(iter(self._held_status))] if not self._held_overflow_logged: @@ -550,7 +653,7 @@ def _take_held_status(self): future = self.future_by_id(future_id) if future is None: continue - call_status = self._held_status.pop(future_id) + _tstamp, call_status = self._held_status.pop(future_id) if not _is_finished(future): ready.append(call_status) return tuple(ready) @@ -622,25 +725,40 @@ def _generate_tokens(self, call_status): """ if not self.generate_tokens or not self.should_run: return - - chunksize = call_status.get('chunksize') - if chunksize is None: - chunksize = self.job_chunksize.get(call_status['job_id']) - if chunksize is None: + # The statuses of a nested executor come this way too, and its + # workers were never counted by the invoker of this one + if call_status['executor_id'] != self.executor_id: + return + if call_status.get('job_id') in self._token_closed_jobs: return call_id = _status_id(call_status) + worker_calls = call_status.get('worker_calls') + if worker_calls is None: + chunksize = call_status.get('chunksize') + if chunksize is None: + chunksize = self.job_chunksize.get(call_status['job_id']) + if chunksize is None: + return + worker_calls = self._worker_calls(*call_id, chunksize) + worker_id = call_status['activation_id'] - done_for_worker = self.callids_done_worker.setdefault(worker_id, set()) - done_for_worker.add(call_id) - - if ( - worker_id not in self.workers_done - and len(done_for_worker) >= chunksize - ): - self.workers_done.add(worker_id) - if self.should_run: - self.token_bucket_q.put('#') + # The two threads that apply statuses both get here. The read of + # the count and the decision to hand a token back have to be one + # step, or each of them hands one back + with self._apply_lock: + done_for_worker = self.callids_done_worker.setdefault( + worker_id, set() + ) + done_for_worker.add(call_id) + + if ( + worker_id not in self.workers_done + and len(done_for_worker) >= worker_calls + ): + self.workers_done.add(worker_id) + if self.should_run: + self.token_bucket_q.put('#') def _apply_status_message(self, call_status): """ @@ -654,11 +772,59 @@ def _apply_status_message(self, call_status): if not self._tag_future_as_running(call_status): self._hold_status(call_status) elif call_status['type'] == '__end__': + if call_status.get(PARTIAL_STATUS_KEY): + call_status = self._complete_partial_status(call_status) + if call_status is None: + return if self._tag_future_as_ready(call_status): self._generate_tokens(call_status) + elif call_status.get('job_id') in self._dropped_jobs: + # wait() dropped the futures, but the worker is still + # this executor's and must free its token, unless the + # invoker already wrote the job off + self._generate_tokens(call_status) else: self._hold_status(call_status) + def _complete_partial_status(self, call_status): + """ + Swaps a status whose message left out what did not fit for the full + one the worker wrote to the storage before sending it. + + Only for a future that is tracked and not finished: one that is not + tracked yet is held, and comes back here once it is. Returns None + when the storage copy cannot be read; the call is then left running, + for the storage sweep or the timeout checker to pick up + """ + future = self.future_by_id(_status_id(call_status)) + if future is None or _is_finished(future): + return call_status + + stored = None + if self.internal_storage is not None: + try: + stored = self.internal_storage.get_call_status( + *_status_id(call_status) + ) + future._status_query_count += 1 + except Exception: + logger.debug( + f'{log_prefix(self.executor_id)} - Could not read the ' + f'status of call {call_status["call_id"]} from the storage', + exc_info=True, + ) + if stored: + return stored + + # As an __init__, since that is all the future can be told + if not _is_started(future): + self._mark_running(future, dict(call_status, type='__init__')) + return None + + def _release_timed_out_worker(self, call_status): + if call_status.get('activation_id') is not None: + self._generate_tokens(call_status) + def _apply_recovered_status(self, future, call_status): if not super()._apply_recovered_status(future, call_status): return False diff --git a/lithops/monitoring/status.py b/lithops/monitoring/status.py index 1e62d6f94..91e1e7ce0 100644 --- a/lithops/monitoring/status.py +++ b/lithops/monitoring/status.py @@ -28,11 +28,30 @@ from lithops.utils import ( CURRENT_PY_VERSION, monitoring_queue_name, + remote_invoker_queue_name, sizeof_fmt, ) logger = logging.getLogger(__name__) +#: Set on a status message that left out fields the client cannot do without, +#: because the message service would not take them. The client reads the +#: full status back from the storage copy, written before the message +PARTIAL_STATUS_KEY = 'partial_status' + +#: Fields a message leaves out, in this order, when it does not fit. The logs +#: go first and alone, since the client can do without them; the rest carry +#: the outcome of the call, and dropping them makes the message partial +LOGS_FIELD = 'logs' +STORAGE_ONLY_FIELDS = ('result', 'exc_info', 'new_futures') + +_PROBE_ID = 'probe' +#: What the queue of a remote invoker adds to the queue of the executor it +#: invokes for +_REMOTE_INVOKER_SUFFIX = remote_invoker_queue_name(_PROBE_ID)[ + len(monitoring_queue_name(_PROBE_ID)): +] + #: Set to 0 to build a client per call instead of keeping one for the #: process. The escape hatch for a runtime where a client that outlives the #: call does not survive the fork of the next one @@ -43,6 +62,33 @@ _ATEXIT_REGISTERED = False +def is_remote_invoker_queue(name: str) -> bool: + """ + Whether a queue of the monitoring chain belongs to a remote invoker. + + The remote invoker deletes its queue once every chunk is invoked, long + before the calls finish, so publishing there is best effort + """ + return name.endswith(_REMOTE_INVOKER_SUFFIX) + + +def chunk_call_count(call_id: str, chunksize: int, total_calls: int = None): + """ + How many calls the worker that runs ``call_id`` was given. + + The invoker hands the calls out in consecutive chunks of ``chunksize`` + starting at call 0, so every chunk is full but the last one of the job. + Without the total, the chunksize is the best there is + """ + if not chunksize or not total_calls: + return chunksize + try: + first = int(call_id) // chunksize * chunksize + except (TypeError, ValueError): + return chunksize + return max(1, min(chunksize, total_calls - first)) + + def reuse_clients() -> bool: """ Whether one client serves every call of this process. @@ -141,7 +187,12 @@ def __init__(self, job: SimpleNamespace, internal_storage): 'call_id': job.call_id, 'job_id': job.job_id, 'executor_id': job.executor_id, - 'chunksize': job.chunksize + 'chunksize': job.chunksize, + # What frees the worker for the token bucket of the invoker: the + # last chunk of a job is usually shorter than the chunksize + 'worker_calls': chunk_call_count( + job.call_id, job.chunksize, getattr(job, 'total_calls', None) + ), } is_warm = os.environ.get('WARM_CONTAINER', '').lower() in { @@ -201,7 +252,7 @@ class MessageCallStatus(StorageCallStatus): which reaches the client faster, and falls back to Object Storage at the end. - Subclasses implement :meth:`_publish`. + Subclasses implement :meth:`_publish_to`. """ MAX_ATTEMPTS = 5 @@ -209,6 +260,10 @@ class MessageCallStatus(StorageCallStatus): MAX_RETRY_SLEEP = 5 service_name = 'message service' + #: Largest status the service takes in one message, in bytes of the + #: serialized JSON. None when there is no practical limit + MAX_MESSAGE_SIZE = None + def __init__(self, job: SimpleNamespace, internal_storage): super().__init__(job, internal_storage) # Clients this object built for itself, which nothing else uses and @@ -265,38 +320,100 @@ def _send(self) -> None: The storage copy is what the client reads back when the message is lost, which a message service that delivers at most once can do; see - MessageMonitor._storage_sweep() + MessageMonitor._storage_sweep(). A partial message sends the client + there right away, so in that case the copy is written first + """ + payload, partial = self._message_payload() + store = self.status['type'] == '__end__' + + if store and partial: + super()._send() + self._publish_to_chain(payload) + if store and not partial: + super()._send() + + def _message_payload(self): + """ + The status as the message carries it, and whether it is partial. + + The worker puts the logs of the call in its last status, and those + alone go past what Azure Queue takes in a message. They are left + out first, since the client can do without them; if the message is + still too big, so is what the storage copy holds anyway """ - dmpd_response_status = json.dumps(self.status) + payload = json.dumps(self.status) + limit = self.MAX_MESSAGE_SIZE + if limit is None or len(payload.encode('utf-8')) <= limit: + return payload, False + + status = dict(self.status) + status.pop(LOGS_FIELD, None) + payload = json.dumps(status) + if len(payload.encode('utf-8')) <= limit: + return payload, False + + for key in STORAGE_ONLY_FIELDS: + status.pop(key, None) + status[PARTIAL_STATUS_KEY] = True + logger.info( + f'The execution status does not fit in a {self.service_name} ' + 'message; the client reads it from the storage' + ) + return json.dumps(status), True + + def _publish_to_chain(self, payload: str) -> None: + """ + Publishes the status to every queue of the chain, each one on its own. + + The queues of the executors are retried: a status lost there leaves + the client with a call that finishes only through the storage sweep, + or, for a nested future, only at its execution timeout. The queue of + a remote invoker is tried once: the invoker deletes it as soon as + every chunk is invoked, and retrying there would only resend the + status to the queues that already have it + """ + targets = self._targets() + pending = [t for t in targets if not is_remote_invoker_queue(t)] exc = None for attempt in range(self.MAX_ATTEMPTS): - try: - self._publish(dmpd_response_status) - logger.info( - f"Execution status sent to {self.service_name} - " - f"Size: {sizeof_fmt(len(dmpd_response_status))}" - ) - exc = None + failed = [] + for target in pending: + try: + self._publish_to(target, payload) + except Exception as e: + exc = e + failed.append(target) + pending = failed + if not pending or attempt == self.MAX_ATTEMPTS - 1: break - except Exception as e: - exc = e - if attempt == self.MAX_ATTEMPTS - 1: - break - # Backed off, so that the attempts span a broker hiccup - # instead of being spent within the same second - time.sleep(min( - self.RETRY_SLEEP * (2 ** attempt), self.MAX_RETRY_SLEEP - )) - - if exc is not None: + # Backed off, so that the attempts span a broker hiccup + # instead of being spent within the same second + time.sleep(min( + self.RETRY_SLEEP * (2 ** attempt), self.MAX_RETRY_SLEEP + )) + + if pending: logger.error( f"Could not send the execution status to {self.service_name} " f"after {self.MAX_ATTEMPTS} attempts: {exc}" ) + else: + logger.info( + f"Execution status sent to {self.service_name} - " + f"Size: {sizeof_fmt(len(payload))}" + ) - if self.status['type'] == '__end__': - super()._send() + for target in targets: + if not is_remote_invoker_queue(target): + continue + try: + self._publish_best_effort(target, payload) + except Exception as e: + logger.debug( + f'Could not send the execution status to {target}, ' + f'which may be gone already: {e}' + ) def _targets(self) -> list: """ @@ -350,5 +467,17 @@ def _release_cached(self, *names: str) -> None: self._own_clients.discard(name) _release_client(client, self.service_name) - def _publish(self, payload: str) -> None: + def _publish_to(self, target: str, payload: str) -> None: + """ + Publishes a status to one queue of the chain. It must not create the + queue: the monitor that reads it did, and one that is not there + belongs to a reader that is gone + """ raise NotImplementedError + + def _publish_best_effort(self, target: str, payload: str) -> None: + """ + Publishes a status to a queue that may have been deleted already. + Override when a publish to a queue that is gone would bring it back + """ + self._publish_to(target, payload) diff --git a/lithops/multiprocessing/connection.py b/lithops/multiprocessing/connection.py index 9d7fffacd..70e58c6e5 100644 --- a/lithops/multiprocessing/connection.py +++ b/lithops/multiprocessing/connection.py @@ -25,6 +25,7 @@ from . import util from . import config as mp_config from .errors import BufferTooShort +from .synchronize import _blpop from queue import Queue logger = logging.getLogger(__name__) @@ -267,6 +268,19 @@ def poll(self, timeout=0.0): self._check_readable() return self._poll(timeout) + def recv_bytes_within(self, timeout): + """ + The next message, waiting at most ``timeout`` seconds, or None + if none came. Zero or less does not wait at all. + + Redis overrides this so looking and taking are one step + """ + self._check_closed() + self._check_readable() + if not self._poll(max(timeout, 0)): + return None + return self._recv_bytes() + def __enter__(self): return self @@ -280,6 +294,9 @@ class _RedisConnection(_ConnectionBase): """ _write = None _read = None + #: The reference of the queue this connection carries, if any, whose + #: counter is refreshed along with the list on every write + _ref = None def __init__(self, handle, readable=True, writable=True): super().__init__(handle, readable, writable) @@ -326,11 +343,6 @@ def __setstate__(self, state): def __len__(self): return self._client.llen(self._handle) - def _set_expiry(self, key): - logger.debug('Set key %s expiry time', key) - self._client.expire(key, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) - self._set_expiry = lambda key: None - def _close(self, _close=None): # Only the subscription belongs to this connection. The client is the # one every shared object of the process talks through, so closing it @@ -340,13 +352,41 @@ def _close(self, _close=None): self._pubsub = None def _listwrite(self, handle, buf): - self._set_expiry(handle) - return self._client.rpush(handle, buf) + # The expiry goes after the push, on every write: EXPIRE does nothing + # on a list that does not exist yet, and Redis deletes the list, + # expiry and all, whenever the reader drains it + pipeline = self._client.pipeline() + pipeline.rpush(handle, buf) + pipeline.expire(handle, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + if self._ref is not None: + self._ref.refresh(pipeline) + return pipeline.execute()[0] def _listread(self, handle): _, v = self._client.blpop([handle]) return v + def recv_bytes_within(self, timeout): + """ + The next message, waiting at most ``timeout`` seconds for one, or + None if none came. Zero or less does not wait at all. + + On a list, looking and taking are one step. With several readers, + poll() followed by a read let two of them see the same last message, + and the one that lost the race blocked in BLPOP for ever + """ + self._check_closed() + self._check_readable() + if self._pubsub is not None: + # A subscriber is the only reader of its messages + if not self._poll(max(timeout, 0)): + return None + return self._read(self._handle) + if timeout <= 0: + return self._client.lpop(self._handle) + popped = _blpop(self._client, self._handle, timeout) + return None if popped is None else popped[1] + def _channelwrite(self, handle, buf): return self._client.publish(handle, buf) @@ -649,13 +689,13 @@ def accept(self): return c def close(self): + # Only the subscription belongs to the listener. The client is the + # one the whole process shares, and closing it broke every other + # connection, blocking reads on other threads included try: self._pubsub.close() self._pubsub = None self._gen = None - if hasattr(self._client, 'close'): - self._client.close() - self._client = None finally: unlink = self._unlink if unlink is not None: diff --git a/lithops/multiprocessing/managers.py b/lithops/multiprocessing/managers.py index 50e38892e..46102e326 100644 --- a/lithops/multiprocessing/managers.py +++ b/lithops/multiprocessing/managers.py @@ -290,7 +290,7 @@ def _init_obj(self, obj): else: shared = obj.__shared__ - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() for attr_name in shared: attr = getattr(obj, attr_name) attr_bin = self._pickler.dumps(attr) @@ -364,7 +364,7 @@ def _call(self, *args, **kwargs): else: shared = self._shared_object.__shared__ - pipeline = self._proxy._client.pipeline() + pipeline = self._proxy._ref.pipeline() for attr_name in shared: attr = getattr(self._shared_object, attr_name) attr_bin = self._proxy._pickler.dumps(attr) @@ -402,13 +402,15 @@ class ListProxy(BaseProxy): # KEYS[2] - key to extend with # ARGV[1] - number of repetitions # A = A + B * C + # Pushed a thousand values at a time: unpack() puts every value on the + # Lua stack, which holds about 8000, so a longer list raised + # "too many results to unpack" LUA_EXTEND_LIST_SCRIPT = """ local values = redis.call('LRANGE', KEYS[2], 0, -1) - if #values == 0 then - return - else - for i=1,tonumber(ARGV[1]) do - redis.call('RPUSH', KEYS[1], unpack(values)) + local n = #values + for i=1,tonumber(ARGV[1]) do + for j=1,n,1000 do + redis.call('RPUSH', KEYS[1], unpack(values, j, math.min(j + 999, n))) end end """ @@ -449,6 +451,7 @@ def apply(pipe): self._oid, *[self._pickler.dumps(v) for v in new_items] ) pipe.expire(self._oid, self._expiry()) + self._ref.refresh(pipe) self._client.transaction(apply, self._oid) return answer['value'] @@ -458,7 +461,7 @@ def __setitem__(self, i, obj): idx = i.__index__() serialized = self._pickler.dumps(obj) try: - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.lset(self._oid, idx, serialized) pipeline.expire(self._oid, self._expiry()) pipeline.execute() @@ -484,7 +487,7 @@ def change(items): def __getitem__(self, i): if isinstance(i, int) or hasattr(i, '__index__'): idx = i.__index__() - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.lindex(self._oid, idx) pipeline.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) serialized, _ = pipeline.execute() @@ -501,7 +504,7 @@ def __getitem__(self, i): return self.tolist()[i] if start is None: return [] - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.lrange(self._oid, start, end) pipeline.expire(self._oid, self._expiry()) serialized, _ = pipeline.execute() @@ -523,7 +526,7 @@ def extend(self, iterable): values = [self._pickler.dumps(obj) for obj in iterable] if not values: return - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.rpush(self._oid, *values) pipeline.expire(self._oid, self._expiry()) pipeline.execute() @@ -536,18 +539,20 @@ def _extend_same_type(self, listproxy, repeat=1): # proxy -- ListProxy(other), a deepcopy, an in-place multiply -- # got a key that never expired, while one built from a plain list # got one that did - self._client.expire(self._oid, self._expiry()) + pipeline = self._ref.pipeline() + pipeline.expire(self._oid, self._expiry()) + pipeline.execute() def append(self, obj): serialized = self._pickler.dumps(obj) - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.rpush(self._oid, serialized) pipeline.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) pipeline.execute() def pop(self, index=None): if index is None: - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.rpop(self._oid) pipeline.expire(self._oid, self._expiry()) serialized, _ = pipeline.execute() @@ -625,7 +630,7 @@ def __imul__(self, n): return self def __len__(self): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.llen(self._oid) pipeline.expire(self._oid, self._expiry()) length, _ = pipeline.execute() @@ -659,7 +664,7 @@ def change(items): self._mutate(change) def tolist(self): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.lrange(self._oid, 0, -1) pipeline.expire(self._oid, self._expiry()) serialized, _ = pipeline.execute() @@ -710,13 +715,13 @@ def _referent(self): def __setitem__(self, k, v): serialized = self._pickler.dumps(v) - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hset(self._oid, self._field(k), serialized) pipeline.expire(self._oid, self._expiry()) pipeline.execute() def __getitem__(self, k): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hget(self._oid, self._field(k)) pipeline.expire(self._oid, self._expiry()) serialized, _ = pipeline.execute() @@ -726,7 +731,7 @@ def __getitem__(self, k): return self._pickler.loads(serialized) def __delitem__(self, k): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hdel(self._oid, self._field(k)) pipeline.expire(self._oid, self._expiry()) res, _ = pipeline.execute() @@ -735,14 +740,14 @@ def __delitem__(self, k): raise KeyError(k) def __contains__(self, k): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hexists(self._oid, self._field(k)) pipeline.expire(self._oid, self._expiry()) exists, _ = pipeline.execute() return bool(exists) def __len__(self): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hlen(self._oid) pipeline.expire(self._oid, self._expiry()) length, _ = pipeline.execute() @@ -770,7 +775,7 @@ def pop(self, k, *args): 'pop expected at most 2 arguments, got {}'.format(1 + len(args)) ) field = self._field(k) - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hget(self._oid, field) pipeline.hdel(self._oid, field) pipeline.expire(self._oid, self._expiry()) @@ -804,13 +809,14 @@ def apply(pipe): pipe.multi() pipe.hdel(self._oid, field) pipe.expire(self._oid, self._expiry()) + self._ref.refresh(pipe) self._client.transaction(apply, self._oid) return answer['value'] def setdefault(self, k, default=None): serialized = self._pickler.dumps(default) - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hsetnx(self._oid, self._field(k), serialized) # Every other writer refreshes the expiry. A dict only ever written # through setdefault used to get a key that outlived the job @@ -843,20 +849,20 @@ def update(self, *args, **kwargs): if items: # One pipelined HSET rather than the deprecated HMSET and a # separate round trip for the expiry - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hset(self._oid, mapping=items) pipeline.expire(self._oid, self._expiry()) pipeline.execute() def keys(self): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hkeys(self._oid) pipeline.expire(self._oid, self._expiry()) fields, _ = pipeline.execute() return [self._pickler.loads(k) for k in fields] def values(self): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hvals(self._oid) pipeline.expire(self._oid, self._expiry()) values, _ = pipeline.execute() @@ -876,7 +882,7 @@ def copy(self): return self.todict() def todict(self): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.hgetall(self._oid) pipeline.expire(self._oid, self._expiry()) raw_dict, _ = pipeline.execute() @@ -932,7 +938,7 @@ def _referent(self): return self.get() def get(self): - pipeline = self._client.pipeline() + pipeline = self._ref.pipeline() pipeline.get(self._oid) # Read without refreshing, a value that is polled and never written # disappears once REDIS_EXPIRY_TIME is up, mid-job @@ -944,7 +950,9 @@ def get(self): def set(self, value): serialized = self._pickler.dumps(value) - self._client.set(self._oid, serialized, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline = self._ref.pipeline() + pipeline.set(self._oid, serialized, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline.execute() value = property(get, set) diff --git a/lithops/multiprocessing/pool.py b/lithops/multiprocessing/pool.py index f014693d6..24731bc62 100644 --- a/lithops/multiprocessing/pool.py +++ b/lithops/multiprocessing/pool.py @@ -14,6 +14,8 @@ # import itertools import logging +import threading +import time from lithops import FunctionExecutor @@ -40,6 +42,13 @@ job_counter = itertools.count() +#: How often the thread that runs the callbacks of a result looks at calls +#: still running: it starts here and doubles up to the cap +HANDLER_MIN_SLEEP = 0.05 +HANDLER_MAX_SLEEP = 1.0 +#: How often that thread reads the status of a call from storage itself +HANDLER_STORAGE_CHECK = 10.0 + # # Class representing a process pool @@ -75,6 +84,15 @@ def __init__(self, processes=None, initializer=None, initargs=None, maxtasksperc self._processes = self._executor.invoker.max_workers self._remote_logger, self._logger_stream = util.setup_log_streaming(self._executor) + self._terminated = threading.Event() + self._handlers = [] + + def _track(self, result): + """Keeps the callback thread of a result for join() to wait on""" + if result._handler is not None: + self._handlers = [t for t in self._handlers if t.is_alive()] + self._handlers.append(result._handler) + return result def apply(self, func, args=(), kwds={}): """ @@ -153,9 +171,10 @@ def apply_async(self, func, args=(), kwds={}, callback=None, error_callback=None 'op': 'apply'}, extra_env=extra_env) - result = ApplyResult(self._executor, [futures], callback, error_callback) + result = ApplyResult(self._executor, [futures], callback, error_callback, + cancelled=self._terminated) - return result + return self._track(result) def map_async(self, func, iterable, chunksize=None, callback=None, error_callback=None): """ @@ -192,9 +211,10 @@ def _map_async(self, func, iterable, chunksize=None, callback=None, error_callba extra_args=extra_args, extra_env=extra_env) - result = MapResult(self._executor, futures, callback, error_callback) + result = MapResult(self._executor, futures, callback, error_callback, + cancelled=self._terminated) - return result + return self._track(result) def __reduce__(self): raise NotImplementedError('pool objects cannot be passed between processes or pickled') @@ -207,6 +227,7 @@ def close(self): def terminate(self): logger.debug('terminating pool') self._state = TERMINATE + self._terminated.set() self._release() def join(self): @@ -214,6 +235,12 @@ def join(self): if self._state not in (CLOSE, TERMINATE): raise ValueError('Pool is still running') if self._state == CLOSE: + # The callbacks read the results through the executor, which + # _release() gives back, and the standard library's join() does + # not return before they have run either + for handler in self._handlers: + handler.join() + self._handlers = [] self._wait_for_calls() self._release() @@ -286,7 +313,7 @@ class ThreadPool(Pool): class ApplyResult(object): - def __init__(self, executor, futures, callback, error_callback): + def __init__(self, executor, futures, callback, error_callback, cancelled=None): self._job = next(job_counter) self._futures = futures self._executor = executor @@ -294,12 +321,25 @@ def __init__(self, executor, futures, callback, error_callback): self._error_callback = error_callback self._value = None self._exception = None + self._collected = False + self._cancelled = cancelled if cancelled is not None else threading.Event() + # As in the standard library, the callbacks run once, as soon as the + # calls finish, whether or not anybody ever calls get() + self._event = None + self._handler = None + if callback is not None or error_callback is not None: + self._event = threading.Event() + self._handler = threading.Thread(target=self._handle, daemon=True) + self._handler.start() def ready(self): + if self._handler is not None: + return self._event.is_set() # A call whose status has arrived is finished as far as the caller is # concerned; `done` only turns true once its result was downloaded return all( - fut.success or fut.done or fut.error for fut in self._futures + fut.ready or fut.success or fut.done or fut.error + for fut in self._futures ) def successful(self): @@ -312,55 +352,129 @@ def wait(self, timeout=None): Waits for the calls, reporting nothing, as in the standard library. A wait that timed out leaves the result there to be fetched later """ + if self._handler is not None: + self._event.wait(timeout) + return try: - self._executor.wait(self._futures, download_results=False, timeout=timeout) + self._wait(timeout, download_results=False) except Exception: logger.debug('Timed out waiting for the pool results', exc_info=True) - def _get_values(self, timeout=None): + def _wait(self, timeout, download_results): + try: + util.wait_futures(self._executor, self._futures, + download_results=download_results, timeout=timeout) + except TimeoutError as exc: + if timeout is None: + raise + # Lithops reports it as the builtin, which is an OSError and so + # not what `except multiprocessing.TimeoutError` catches + raise ProcessTimeoutError(str(exc)) from exc + + def _collect(self): """ - The value of every call, in order. + Reads the value of every call, or the exception of the first one that + failed, from calls that have finished. Read from the futures rather than through get_result(), which unwraps a lone result depending on what the executor was last asked to do. A map in between would otherwise change the shape of this result, and a call that returns a list of its own is indistinguishable either way """ + storage = self._executor.internal_storage try: - self._executor.wait( - self._futures, download_results=True, timeout=timeout - ) - except TimeoutError as exc: - # Lithops reports it as the builtin, which is an OSError and so - # not what `except multiprocessing.TimeoutError` catches - raise ProcessTimeoutError(str(exc)) from exc + values = [fut.result(internal_storage=storage) for fut in self._futures] except Exception as exc: - # The call raised, and wait() re-raises it while downloading the - # results. The standard library hands that to error_callback - # before letting get() raise it - self._fail(exc) - raise - values = [] - for fut in self._futures: - try: - values.append(fut.result()) - except Exception as exc: - self._fail(exc) - raise - util.export_execution_details(self._futures, self._executor) - return values + self._exception = exc + else: + self._value = self._unwrap(values) + util.export_execution_details(self._futures, self._executor) + self._collected = True + + def _unwrap(self, values): + """The value of the single call this result stands for""" + return values[0] + + def _handle(self): + """ + Collects the result once the calls finish and runs the callback or + the error_callback, which is what the result handler thread of the + standard library does. + + The calls are polled one at a time rather than through lithops.wait, + which cancels the process-wide SIGALRM as it returns: that alarm is + what bounds a get(timeout) the main thread may be running meanwhile + """ + try: + if self._wait_in_thread(): + self._collect() + except Exception as exc: + self._exception = exc + try: + # terminate() drops the callbacks of what had not finished + if self._cancelled.is_set(): + return + if self._exception is None: + if self._callback is not None: + self._callback(self._value) + elif self._error_callback is not None: + self._error_callback(self._exception) + except Exception: + logger.exception('Error in the callback of a pool result') + finally: + self._event.set() - def _fail(self, exc): - """Records the failure of a call and reports it to error_callback""" - self._exception = exc - if self._error_callback is not None: - self._error_callback(exc) + def _wait_in_thread(self): + """ + Waits for every call to finish. False if the pool was terminated. + + The job monitor of the executor marks a call ready as soon as its + status arrives, and applying that status reads nothing from storage. + Storage itself is only asked every HANDLER_STORAGE_CHECK seconds, in + case the monitor is not watching the call: one request per result + and poll would add up to hundreds a second for a pool with that many + results pending + """ + storage = self._executor.internal_storage + delay = HANDLER_MIN_SLEEP + last_check = time.monotonic() + for fut in self._futures: + while not (fut.success or fut.done): + if self._cancelled.is_set(): + return False + now = time.monotonic() + if fut.ready or now - last_check >= HANDLER_STORAGE_CHECK: + if not fut.ready: + last_check = now + found = fut.status(throw_except=False, + internal_storage=storage, + check_only=True) + # A status read from storage is only recorded by that + # call; the next one applies it + if found is not None and not (fut.success or fut.done): + fut.status(throw_except=False, + internal_storage=storage, check_only=True) + if not (fut.success or fut.done): + time.sleep(delay) + delay = min(delay * 2, HANDLER_MAX_SLEEP) + return True def get(self, timeout=None): - """The value of the single call this result stands for""" - self._value = self._get_values(timeout)[0] - if self._callback is not None: - self._callback(self._value) + if self._handler is not None: + if not self._event.wait(timeout): + raise ProcessTimeoutError( + 'Timeout of {} seconds exceeded waiting for the result'.format(timeout) + ) + elif not self._collected: + # Download in _collect, which reraises. wait() with + # download_results=True and throw_except=False would mark a + # missing result as Error and hand None back + self._wait(timeout, download_results=False) + self._collect() + if self._exception is not None: + raise self._exception + if self._cancelled.is_set() and not self._collected: + raise ProcessTimeoutError('the pool was terminated') return self._value @@ -373,12 +487,9 @@ def get(self, timeout=None): class MapResult(ApplyResult): - def get(self, timeout=None): + def _unwrap(self, values): """The list of values, one per item of the iterable""" - self._value = self._get_values(timeout) - if self._callback is not None: - self._callback(self._value) - return self._value + return values # diff --git a/lithops/multiprocessing/process.py b/lithops/multiprocessing/process.py index 32287f186..77915e0e3 100644 --- a/lithops/multiprocessing/process.py +++ b/lithops/multiprocessing/process.py @@ -241,14 +241,25 @@ def close(self): def join(self, timeout=None): """ - Wait until child process terminates + Wait until child process terminates. + + A timeout that runs out returns None and leaves the process running, + as in the standard library, so it can be joined again. A process + whose target raised re-raises it here """ assert self._parent_pid == os.getpid(), 'can only join a child process' assert self._pid, 'can only join a started process' + try: + util.wait_futures(self._executor, [self._future], timeout=timeout) + except TimeoutError: + if timeout is None: + raise + return None + exception = None try: - self._executor.wait(fs=[self._future], timeout=timeout) + self._future.status(internal_storage=self._executor.internal_storage) except Exception as e: exception = e finally: diff --git a/lithops/multiprocessing/queues.py b/lithops/multiprocessing/queues.py index 9f008b02b..cea24dc78 100644 --- a/lithops/multiprocessing/queues.py +++ b/lithops/multiprocessing/queues.py @@ -62,6 +62,7 @@ def _after_fork(self): self._send_bytes = self._writer.send_bytes self._recv_bytes = self._reader.recv_bytes self._poll = self._reader.poll + self._writer._ref = self._ref def put(self, obj, block=True, timeout=None): """ @@ -91,12 +92,9 @@ def get(self, block=True, timeout=None): if block and timeout is None: res = self._recv_bytes() else: - if block: - if not self._poll(timeout): - raise Empty - elif not self._poll(): + res = self._reader.recv_bytes_within(timeout if block else 0) + if res is None: raise Empty - res = self._recv_bytes() return cloudpickle.loads(res) @@ -148,6 +146,11 @@ def __init__(self): self._ref = util.RemoteReference(referenced=[self._reader._handle, self._reader._subhandle], client=self._reader._client) self._poll = self._reader.poll + self._writer._ref = self._ref + + def __setstate__(self, state): + self.__dict__.update(state) + self._writer._ref = self._ref def put(self, obj, block=True, timeout=None): assert not self._closed @@ -158,12 +161,9 @@ def get(self, block=True, timeout=None): if block and timeout is None: res = self._reader.recv_bytes() else: - if block: - if not self._poll(timeout): - raise Empty - elif not self._poll(): + res = self._reader.recv_bytes_within(timeout if block else 0) + if res is None: raise Empty - res = self._reader.recv_bytes() return cloudpickle.loads(res) diff --git a/lithops/multiprocessing/sharedctypes.py b/lithops/multiprocessing/sharedctypes.py index 7b0d7ea0d..6c863b7ce 100644 --- a/lithops/multiprocessing/sharedctypes.py +++ b/lithops/multiprocessing/sharedctypes.py @@ -12,6 +12,7 @@ import ctypes import cloudpickle import logging +import redis from . import util from . import get_context @@ -73,7 +74,9 @@ def __setattr__(self, key, value): if key == 'value': obj = cloudpickle.dumps(value) logger.debug('Set raw value %s of size %i B', self._oid, len(obj)) - self._client.set(self._oid, obj, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline = self._ref.pipeline() + pipeline.set(self._oid, obj, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline.execute() else: super().__setattr__(key, value) @@ -132,10 +135,13 @@ def __getitem__(self, i): stop -= 1 logger.debug('Requested get list slice from %i to %i', start, stop) objl = self._client.lrange(self._oid, start, stop) - self._client.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + self._refresh_expiry() return [cloudpickle.loads(obj) for obj in objl] else: obj = self._client.lindex(self._oid, i) + if obj is None: + # LINDEX answers nil past either end, as ctypes raises + raise IndexError('invalid index') logger.debug('Requested get list index %i of size %i B', i, len(obj)) return cloudpickle.loads(obj) @@ -151,8 +157,17 @@ def __setitem__(self, i, value): else: obj = cloudpickle.dumps(value) logger.debug('Requested set list index %i of size %i B', i, len(obj)) - self._client.lset(self._oid, i, obj) - self._client.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + try: + self._client.lset(self._oid, i, obj) + except redis.exceptions.ResponseError: + # LSET refuses an index past either end + raise IndexError('invalid index') + self._refresh_expiry() + + def _refresh_expiry(self): + pipeline = self._ref.pipeline() + pipeline.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline.execute() class SynchronizedArrayProxy(RawArrayProxy, SynchronizedSharedCTypeProxy): @@ -173,7 +188,7 @@ def __setattr__(self, key, value): obj = cloudpickle.dumps(elem) logger.debug('Requested set string index %i of size %i B', i, len(obj)) self._client.lset(self._oid, i, obj) - self._client.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + self._refresh_expiry() else: super().__setattr__(key, value) @@ -189,11 +204,13 @@ def __getitem__(self, i): stop -= 1 # lrange is inclusive on both ends logger.debug('Requested get string slice from %i to %i', start, stop) objl = self._client.lrange(self._oid, start, stop) - self._client.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + self._refresh_expiry() return bytes([cloudpickle.loads(obj) for obj in objl]) else: obj = self._client.lindex(self._oid, i) - self._client.expire(self._oid, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + if obj is None: + raise IndexError('invalid index') + self._refresh_expiry() return bytes([cloudpickle.loads(obj)]) diff --git a/lithops/multiprocessing/synchronize.py b/lithops/multiprocessing/synchronize.py index 73f80f885..78ad5707f 100644 --- a/lithops/multiprocessing/synchronize.py +++ b/lithops/multiprocessing/synchronize.py @@ -9,6 +9,7 @@ # Modifications Copyright (c) 2020 Cloudlab URV # +import os import threading import math import time @@ -128,17 +129,19 @@ def acquire(self, block=True, timeout=None): """ if not block or (timeout is not None and timeout <= 0): logger.debug('Requested non-blocking acquire for lock %s', self._name) - return self._client.lpop(self._name) is not None - - if timeout is None: + acquired = self._client.lpop(self._name) is not None + elif timeout is None: logger.debug('Requested blocking acquire for lock %s', self._name) self._client.blpop([self._name]) - return True - - logger.debug( - 'Requested acquire for lock %s within %s s', self._name, timeout - ) - return _blpop(self._client, self._name, timeout) is not None + acquired = True + else: + logger.debug( + 'Requested acquire for lock %s within %s s', self._name, timeout + ) + acquired = _blpop(self._client, self._name, timeout) is not None + if acquired: + self._refresh_expiry() + return acquired def release(self): logger.debug('Requested release for lock %s', self._name) @@ -149,6 +152,22 @@ def release(self): # What the standard library raises for a lock that was not held # and for a bounded semaphore released more often than acquired raise ValueError('semaphore or lock released too many times') + self._refresh_expiry() + + def _refresh_expiry(self): + """ + Pushes the key's deadline out again. + + Redis deletes a list once its last token is taken, expiry and all, + and the release script recreates it with none: without this a lock + used once never expires. A semaphore with tokens left keeps its + key, and the deadline set at creation would take those tokens + """ + pipeline = self._ref.pipeline() + pipeline.expire( + self._name, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME) + ) + pipeline.execute() def __repr__(self): try: @@ -230,34 +249,46 @@ class RLock(Lock): def __init__(self): super().__init__() self._count = 0 + self._owner = None def __setstate__(self, state): super().__setstate__(state) self._count = 0 + self._owner = None + + def _holder(self): + """The process and thread that may re-enter without a new token""" + return (os.getpid(), threading.get_ident()) def acquire(self, block=True, timeout=None): - if self.owned: + holder = self._holder() + # owned is one flag for the whole object. Another thread in this + # process would see it and walk in beside the holder + if self._owner == holder: self._count += 1 return True res = super().acquire(block, timeout) if res: self._count = 1 + self._owner = holder return res def release(self): - if not self.owned: + if self._owner != self._holder(): # The wording the standard library uses raise AssertionError( 'attempt to release recursive lock not owned by thread' ) self._count -= 1 if self._count == 0: + self._owner = None super().release() def _release_save(self): """Release all acquisitions while a condition waits.""" count = self._count self._count = 0 + self._owner = None super().release() return count @@ -336,19 +367,32 @@ def wait(self, timeout=None): notified = self._client.lpop(wait_handle) is not None else: notified = _blpop(self._client, wait_handle, timeout) is not None - self._client.expire(wait_handle, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) finally: self._acquire_restore(state) + if not notified: + # A notify that won the race already took our handle off the + # list and pushed a token. Take that token. Otherwise take + # ourselves off the list: the next notify pops the oldest + # handle, and a waiter that has gone spends that wakeup + if self._client.lpop(wait_handle) is not None: + notified = True + else: + self._client.lrem(self._notify_handle, 1, wait_handle) + self._client.expire( + wait_handle, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME) + ) # Whether a notify arrived, rather than the timeout expiring, which # is what the standard library returns and callers branch on return notified - def notify(self): + def notify(self, n=1): assert self._lock.owned logger.debug('Notify condition %s', self._notify_handle) - wait_handle = self._client.lpop(self._notify_handle) - if wait_handle is not None: + for _ in range(n): + wait_handle = self._client.lpop(self._notify_handle) + if wait_handle is None: + break res = self._client.rpush(wait_handle, '') if not res: @@ -454,7 +498,9 @@ def _state(self): @_state.setter def _state(self, value): - self._client.set(self._state_handle, value, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline = self._ref.pipeline() + pipeline.set(self._state_handle, value, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline.execute() @property def _count(self): @@ -462,4 +508,6 @@ def _count(self): @_count.setter def _count(self, value): - self._client.set(self._count_handle, value, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline = self._ref.pipeline() + pipeline.set(self._count_handle, value, ex=mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + pipeline.execute() diff --git a/lithops/multiprocessing/util.py b/lithops/multiprocessing/util.py index aaf8d850c..5616c0330 100644 --- a/lithops/multiprocessing/util.py +++ b/lithops/multiprocessing/util.py @@ -21,6 +21,7 @@ import json import socket from lithops.config import load_config +from lithops.wait import wait as lithops_wait from . import config as mp_config @@ -118,6 +119,26 @@ def get_network_ip(): # class RemoteReference: + # KEYS[1] - reference counter + # KEYS[2..n] - keys of the shared object, the counter among them + # ARGV[1] - expiry time + # Gives back one reference and deletes the object once none is left. + # A counter that is gone -- it expired, or the object was already + # collected -- says nothing about who still holds the object, so it is + # left alone rather than decremented to -1 and taken for the last owner + LUA_DECREF_SCRIPT = """ + if redis.call('exists', KEYS[1]) == 0 then + return nil + end + local count = redis.call('decr', KEYS[1]) + if count <= 0 then + redis.call('del', unpack(KEYS)) + else + redis.call('expire', KEYS[1], ARGV[1]) + end + return count + """ + def __init__(self, referenced, managed=False, client=None): if isinstance(referenced, str): referenced = [referenced] @@ -191,11 +212,27 @@ def incref(self): def decref(self): if not self.managed: - pipeline = self._client.pipeline() - pipeline.decr(self._rck, 1) - pipeline.expire(self._rck, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) - counter, _ = pipeline.execute() - return int(counter) + counter = self._release(self._client, self._rck, self._referenced) + return None if counter is None else int(counter) + + def refresh(self, pipeline=None): + """ + Pushes the counter's deadline out along with the object's. + + The counter is only written when an owner comes or goes, while the + object's keys are refreshed on every use, so an object in use for + longer than REDIS_EXPIRY_TIME lost its counter. Queued on + ``pipeline`` when one is given. Returns whether anything was sent + """ + if self.managed: + return False + target = self._client if pipeline is None else pipeline + target.expire(self._rck, mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)) + return True + + def pipeline(self): + """A pipeline of the object's client that also refreshes the counter""" + return _RefreshingPipeline(self._client.pipeline(), self) def refcount(self): count = self._client.get(self._rck) @@ -215,9 +252,59 @@ def _finalize(client, rck, referenced): zero is what says nobody is left; it used to have to go negative, which is one owner too many """ - count = int(client.decr(rck, 1)) - if count <= 0 and len(referenced) > 0: - client.delete(*referenced) + RemoteReference._release(client, rck, referenced) + + @staticmethod + def _release(client, rck, referenced): + script = client.register_script(RemoteReference.LUA_DECREF_SCRIPT) + return script(keys=[rck] + list(referenced), + args=[mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME)], + client=client) + + +class _RefreshingPipeline: + """ + A pipeline that refreshes the reference counter of the object as it runs. + + The counter's EXPIRE is queued last and its reply dropped, so callers + unpack the replies of the commands they queued, as before + """ + + def __init__(self, pipeline, ref): + self._pipeline = pipeline + self._ref = ref + + def __getattr__(self, name): + return getattr(self._pipeline, name) + + def execute(self): + queued = self._ref.refresh(self._pipeline) + results = self._pipeline.execute() + return results[:-1] if queued else results + + +def wait_futures(executor, futures, download_results=False, timeout=None): + """ + Waits for some calls of ``executor``, leaving them and the executor as + they are. + + FunctionExecutor.wait() takes any exception, a timeout included, as the + end of the job: it stops the invoker, marks the futures failed and + deletes the job data, so a pool result or a process that was only waited + on with a timeout could never be waited on again. A call that raised is + not reported here either; reading its status or result raises it. + + Runs out with the builtin TimeoutError, from the SIGALRM lithops.wait + arms, so a timeout only works from the main thread + """ + lithops_wait( + fs=futures, + internal_storage=executor.internal_storage, + job_monitor=executor._monitor_of(futures), + download_results=download_results, + throw_except=False, + timeout=timeout, + ) # diff --git a/lithops/storage/storage.py b/lithops/storage/storage.py index 0151161d3..29d19309d 100644 --- a/lithops/storage/storage.py +++ b/lithops/storage/storage.py @@ -381,8 +381,16 @@ def get_job_status(self, executor_id, job_ids: Optional[Iterable[str]] = None): have finished, as two sets. Listing the prefix of each given job keeps finished jobs out of the - listing; without job_ids the whole executor prefix is listed - """ + listing. ``job_ids=None`` still lists the whole executor prefix, for + callers that do not know the jobs. An empty collection means there + is nothing to watch: no list is issued. An empty set must not fall + through to the executor prefix, because that prefix is also a prefix + of every job key (``executor_id-job_id``) and of the function + pickle, and a LIST of it on object storage is both wide and + expensive + """ + if job_ids is not None and not job_ids: + return set(), set() if job_ids: keys = [] # Copied first: a caller may pass a set that its own threads diff --git a/lithops/tests/mp_fakeredis.py b/lithops/tests/mp_fakeredis.py index 73654c3b5..1144e3f58 100644 --- a/lithops/tests/mp_fakeredis.py +++ b/lithops/tests/mp_fakeredis.py @@ -26,6 +26,8 @@ import threading import time +from redis.exceptions import ResponseError + def _to_bytes(value): """What the server stores: every value becomes bytes""" @@ -86,15 +88,33 @@ def keys(self, pattern='*'): def _record(self, name, *args): self.commands.append((name,) + args) + def advance(self, seconds): + """ + Lets ``seconds`` go by: every expiry counts down, and a key whose + expiry runs out is deleted, as the server does + """ + with self._cond: + for key, ttl in list(self.expiries.items()): + ttl -= seconds + if ttl <= 0: + self.strings.pop(key, None) + self.lists.pop(key, None) + del self.expiries[key] + else: + self.expiries[key] = ttl + # -- strings ----------------------------------------------------------- def set(self, key, value, ex=None): + """Without ``ex``, SET drops whatever expiry the key had""" key = _key(key) self._record('set', key) with self._cond: self.strings[key] = _to_bytes(value) if ex is not None: self.expiries[key] = ex + else: + self.expiries.pop(key, None) return True def get(self, key): @@ -148,13 +168,21 @@ def lpush(self, key, *values): self._cond.notify_all() return len(items) + def _drop_if_empty(self, key): + """The server deletes a list, and its expiry, once it is empty""" + if key in self.lists and not self.lists[key]: + del self.lists[key] + self.expiries.pop(key, None) + def lpop(self, key): key = _key(key) with self._cond: items = self.lists.get(key) if not items: return None - return items.pop(0) + item = items.pop(0) + self._drop_if_empty(key) + return item def blpop(self, keys, timeout=0): """Blocks until one of the keys has an element, as the server does""" @@ -167,7 +195,9 @@ def blpop(self, keys, timeout=0): for key in keys: items = self.lists.get(key) if items: - return key, items.pop(0) + item = items.pop(0) + self._drop_if_empty(key) + return key, item remaining = None if end is None else end - time.monotonic() if remaining is not None and remaining <= 0: return None @@ -177,6 +207,34 @@ def llen(self, key): key = _key(key) return len(self.lists.get(key, [])) + def lrem(self, key, count, value): + """Removes up to ``count`` occurrences of ``value``. Zero removes all""" + key = _key(key) + value = _to_bytes(value) + with self._cond: + items = self.lists.get(key) + if not items: + return 0 + removed = 0 + if count >= 0: + kept = [] + for item in items: + if item == value and (count == 0 or removed < count): + removed += 1 + continue + kept.append(item) + else: + kept = [] + for item in reversed(items): + if item == value and removed < -count: + removed += 1 + continue + kept.append(item) + kept.reverse() + self.lists[key] = kept + self._drop_if_empty(key) + return removed + def lrange(self, key, start, end): key = _key(key) items = self.lists.get(key, []) @@ -193,10 +251,13 @@ def lindex(self, key, index): return None def lset(self, key, index, value): + """The server refuses a missing key and an index past either end""" key = _key(key) - items = self.lists.setdefault(key, []) - while len(items) <= index: - items.append(b'') + items = self.lists.get(key) + if items is None: + raise ResponseError('no such key') + if not -len(items) <= index < len(items): + raise ResponseError('index out of range') items[index] = _to_bytes(value) return True @@ -213,9 +274,16 @@ def pubsub(self): def register_script(self, script): """ - The only script the package registers is the capped release of - SemLock, reimplemented here rather than running Lua + The scripts the package registers, reimplemented here rather than + running Lua: the capped release of SemLock and the release of a + remote reference. Any other one cannot be run """ + from lithops.multiprocessing.synchronize import SemLock + from lithops.multiprocessing.util import RemoteReference + if script == SemLock.LUA_RELEASE_SCRIPT: + return FakeSemLockRelease(self) + if script == RemoteReference.LUA_DECREF_SCRIPT: + return FakeDecref(self) return FakeScript(self) # -- pipelines --------------------------------------------------------- @@ -242,6 +310,12 @@ class FakeScript: def __init__(self, server): self._server = server + def __call__(self, keys, args, client=None): + raise NotImplementedError('the fake server cannot run this script') + + +class FakeSemLockRelease(FakeScript): + def __call__(self, keys, args, client=None): server = client if client is not None else self._server name = _key(keys[0]) @@ -257,6 +331,26 @@ def __call__(self, keys, args, client=None): return current + 1 +class FakeDecref(FakeScript): + """ + Decrements a reference counter that exists, deleting the object once it + reaches zero and refreshing the counter otherwise + """ + + def __call__(self, keys, args, client=None): + server = client if client is not None else self._server + counter = _key(keys[0]) + with server._cond: + if counter not in server.strings: + return None + count = server.incr(counter, -1) + if count <= 0: + server.delete(*keys) + else: + server.expiries[counter] = int(args[0]) + return count + + class FakePubSub: def __init__(self, server): self._server = server diff --git a/lithops/tests/test_executors.py b/lithops/tests/test_executors.py index 5968b87f7..7787ee02b 100644 --- a/lithops/tests/test_executors.py +++ b/lithops/tests/test_executors.py @@ -216,7 +216,9 @@ def test_cleanup_jobs_omits_exception_kwarg_on_success(self): with patch.object(executor, 'clean') as clean: executor._cleanup_jobs([future]) executor.compute_handler.clear.assert_called_once_with({future.job_key}) - clean.assert_called_once_with(clean_cloudobjects=False, force=False) + clean.assert_called_once_with( + fs=[future], clean_cloudobjects=False, force=False + ) def test_cleanup_jobs_passes_exception_and_force(self): executor = _bare_executor() @@ -227,7 +229,55 @@ def test_cleanup_jobs_passes_exception_and_force(self): executor.compute_handler.clear.assert_called_once_with( {future.job_key}, exception=error ) - clean.assert_called_once_with(clean_cloudobjects=False, force=True) + clean.assert_called_once_with( + fs=[future], clean_cloudobjects=False, force=True + ) + + def test_clean_keeps_a_job_with_results_still_to_read(self): + """ + One job is one storage prefix. A call whose small result came back + inside its status is done, while its sibling's result still waits in + storage: deleting the prefix then loses it, and a later get_result() + fails with 'Unable to get the result' + """ + read = FakeFuture(executor_id='abc-0', job_id='M000', done=True) + unread = FakeFuture( + executor_id='abc-0', job_id='M000', done=False, success=True + ) + executor = _bare_executor( + cleaned_jobs=set(), executor_id='abc-0', futures=[read, unread] + ) + with patch('lithops.executors._dump_cleaner_data') as dump, \ + patch('lithops.executors.sp.Popen'): + executor.clean(fs=[read, unread], clean_cloudobjects=False) + dump.assert_not_called() + assert executor.cleaned_jobs == set() + + unread.done = True + with patch('lithops.executors._dump_cleaner_data') as dump, \ + patch('lithops.executors.sp.Popen'): + executor.clean(fs=[read, unread], clean_cloudobjects=False) + assert create_job_key('abc-0', 'M000') in executor.cleaned_jobs + + def test_clean_on_exit_deletes_a_job_with_unread_results(self): + """ + After the process exits nothing will read the leftover result, so + keeping the prefix would leak it for the rest of the bucket's life + """ + read = FakeFuture(executor_id='abc-0', job_id='M000', done=True) + unread = FakeFuture( + executor_id='abc-0', job_id='M000', done=False, success=True + ) + executor = _bare_executor( + cleaned_jobs=set(), executor_id='abc-0', futures=[read, unread] + ) + with patch('lithops.executors._dump_cleaner_data') as dump, \ + patch('lithops.executors.sp.Popen'): + executor.clean( + fs=[read, unread], clean_cloudobjects=False, on_exit=True + ) + assert create_job_key('abc-0', 'M000') in executor.cleaned_jobs + dump.assert_called_once() def test_clean_does_not_wrap_futures_list(self): future = FakeFuture(executor_id='abc-0', job_id='M000', done=True) @@ -339,29 +389,37 @@ def test_wait_cleans_when_all_completed(self, mock_wait): assert cleanup.call_args.kwargs.get('exception') is None @patch('lithops.executors.wait') - def test_wait_stops_monitor_when_all_tracked_futures_are_done(self, mock_wait): + def test_wait_keeps_the_monitor_for_the_next_map(self, mock_wait): + """ + The monitor belongs to the executor. Stopping it after every wait() + made the next map() join that thread and spawn another, which is + what made a tight map/wait loop (Cubed) slower, and lost the first + statuses of the new job on a message backend + """ future = FakeFuture(done=True, success=True) executor = _bare_executor(futures=[future]) executor.wait([future], return_when=ALL_COMPLETED, show_progressbar=False) - executor.job_monitor.stop.assert_called_once() + executor.job_monitor.stop.assert_not_called() + executor.job_monitor.remove.assert_called_once_with([future]) @patch('lithops.executors.wait') - def test_wait_stops_monitor_before_cleaning(self, mock_wait): + def test_wait_drops_finished_futures_before_cleaning(self, mock_wait): future = FakeFuture(done=True, success=True) executor = _bare_executor(data_cleaner=True, futures=[future]) order = [] - executor._stop_monitor_if_idle = lambda *a, **k: order.append('stop') + executor._release_finished_from_monitor = lambda *a, **k: order.append('release') executor._cleanup_jobs = lambda *a, **k: order.append('clean') executor.wait([future], return_when=ALL_COMPLETED, show_progressbar=False) - assert order == ['stop', 'clean'] + assert order == ['release', 'clean'] @patch('lithops.executors.wait') - def test_wait_keeps_monitor_when_other_futures_are_pending(self, mock_wait): + def test_wait_does_not_drop_pending_futures_from_the_monitor(self, mock_wait): done = FakeFuture(done=True, success=True) pending = FakeFuture(done=False, success=False) executor = _bare_executor(futures=[done, pending]) - executor.wait([done], return_when=ALL_COMPLETED, show_progressbar=False) + executor.wait([done, pending], return_when=ALL_COMPLETED, show_progressbar=False) executor.job_monitor.stop.assert_not_called() + executor.job_monitor.remove.assert_called_once_with([done]) def test_exit_waits_for_the_invoker_threads(self): """ @@ -417,7 +475,11 @@ def test_a_failure_at_exit_does_not_stop_the_remaining_hooks(self): clean.assert_called_once() @patch('lithops.executors.wait', side_effect=RuntimeError('boom')) - def test_wait_exception_stops_invoker_and_reraises(self, mock_wait): + def test_wait_exception_drops_its_queued_calls_and_reraises(self, mock_wait): + """ + Stopping the invoker used to drop the queued calls of every job of + the executor, so another job still running never got its workers + """ future = FakeFuture() executor = _bare_executor(data_cleaner=True) @@ -425,12 +487,59 @@ def test_wait_exception_stops_invoker_and_reraises(self, mock_wait): with pytest.raises(RuntimeError, match='boom'): executor.wait([future], show_progressbar=False) - executor.invoker.stop.assert_called_once() + executor.invoker.stop.assert_not_called() + executor.invoker.discard_pending.assert_called_once_with( + {future.job_key}, {future.job_id} + ) executor.job_monitor.remove.assert_called_once() assert future._exception_set is True assert cleanup.call_args.kwargs['force'] is True assert isinstance(cleanup.call_args.kwargs['exception'], RuntimeError) + @patch('lithops.executors.wait', side_effect=TimeoutError('late')) + def test_a_failed_wait_only_cleans_the_jobs_it_waited_on(self, mock_wait): + """ + A timeout waiting on one job used to delete the data of every job + of the executor, including one still running that nobody waited on + """ + waited = FakeFuture(executor_id='abc-0', job_id='M000') + other = FakeFuture( + executor_id='abc-0', job_id='M001', job_key='abc-0/M001' + ) + executor = _bare_executor( + data_cleaner=True, executor_id='abc-0', futures=[waited, other] + ) + with patch('lithops.executors._dump_cleaner_data') as dump, \ + patch('lithops.executors.sp.Popen'): + with pytest.raises(TimeoutError): + executor.wait([waited], show_progressbar=False) + cleaned = dump.call_args[0][0]['jobs_to_clean'] + assert cleaned == {create_job_key('abc-0', 'M000')} + + @patch('lithops.executors.wait', side_effect=KeyboardInterrupt) + def test_ctrl_c_in_wait_stops_every_invocation(self, mock_wait): + executor = _bare_executor() + with pytest.raises(KeyboardInterrupt): + executor.wait([FakeFuture()], show_progressbar=False) + executor.invoker.stop.assert_called_once_with(wait=True) + + @patch('lithops.executors.wait', side_effect=TimeoutError('late')) + def test_a_failed_wait_honours_clean_jobs(self, mock_wait): + future = FakeFuture() + executor = _bare_executor(data_cleaner=True) + with patch.object(executor, '_cleanup_jobs') as cleanup: + with pytest.raises(TimeoutError): + executor.wait([future], show_progressbar=False, + clean_jobs=False) + cleanup.assert_not_called() + + def test_get_result_takes_a_single_future(self): + """The signature takes a ResponseFuture, which has no len()""" + future = FakeFuture(_result=42) + executor = _bare_executor(last_call='call_async', futures=[future]) + with patch.object(executor, 'wait', return_value=([future], [])): + assert executor.get_result(future) == 42 + def test_get_result_unwraps_single_non_map_result(self): future = FakeFuture(_result=42) executor = _bare_executor(last_call='call_async', futures=[future]) diff --git a/lithops/tests/test_future.py b/lithops/tests/test_future.py index 9f245eaef..a72b8924f 100644 --- a/lithops/tests/test_future.py +++ b/lithops/tests/test_future.py @@ -14,6 +14,7 @@ import base64 import pickle +import sys import zlib from types import SimpleNamespace from unittest.mock import MagicMock, patch @@ -318,6 +319,47 @@ def test_handler_exception_strips_marker_argument(self): future.status(internal_storage=storage) assert future._handler_exception is True + def test_a_status_without_result_size_does_not_crash(self): + """ + A worker that died before writing its function stats sends a + finished status with no func_result_size. Reading it used to raise + KeyError in the wait thread pool, which crashed get_result() even + with throw_except=False + """ + future = _future() + future._set_invoked() + storage = MagicMock() + storage.get_storage_config.return_value = STORAGE_CONFIG + status = _end_status() + del status['func_result_size'] + storage.get_call_status.return_value = status + future.status(internal_storage=storage, throw_except=False) + assert future.done + assert future.result(internal_storage=storage) is None + + def test_a_remote_sys_exit_keeps_its_exit_code(self): + """ + tblib, which the worker installs, rebuilds a SystemExit with code + None. Re-raised on the client, sys.exit(3) in the function would + end the client program with status 0 + """ + from tblib import pickling_support + pickling_support.install() + try: + sys.exit(3) + except SystemExit: + exc_info = sys.exc_info() + future = _future() + future._set_invoked() + storage = MagicMock() + storage.get_storage_config.return_value = STORAGE_CONFIG + storage.get_call_status.return_value = _end_status( + exception=True, exc_info=_encode(exc_info), + ) + with pytest.raises(SystemExit) as raised: + future.status(internal_storage=storage) + assert raised.value.code == 3 + def test_pickle_fail_wraps_exception_dict(self): future = _future() future._set_invoked() diff --git a/lithops/tests/test_invokers.py b/lithops/tests/test_invokers.py index 20a076f64..9e91efea2 100644 --- a/lithops/tests/test_invokers.py +++ b/lithops/tests/test_invokers.py @@ -317,6 +317,59 @@ def test_drain_token_bucket_consumes_until_zero(self): assert inv.running_workers == 0 assert inv.job_monitor.token_bucket_q.qsize() == 1 + def test_discard_pending_keeps_the_calls_of_other_jobs(self): + inv = self._faas() + failed = _job(chunksize=2) + failed.job_key = 'sess-0/M000' + other = _job(chunksize=2) + other.job_key = 'sess-0/M001' + inv._queue_call_ranges(failed, range(4)) + inv._queue_call_ranges(other, range(3)) + inv.running_workers = 4 + inv.job_monitor.token_bucket_q.put('#') + inv.discard_pending({'sess-0/M000'}) + left = [] + while not inv.pending_calls_q.empty(): + left.append(inv.pending_calls_q.get()[0]) + assert left == [other, other] + assert inv.running_workers == 4 + inv.job_monitor.close_jobs.assert_not_called() + + def test_discard_pending_forgets_workers_when_no_other_job_is_queued(self): + """ + wait() also drops those jobs from the monitor, so their workers + never put a token back. Without forgetting them, the next map() + of this executor stays capped by a count that never comes down + """ + inv = self._faas() + inv.running_workers = 4 + inv.job_monitor.token_bucket_q.put('#') + failed = _job(chunksize=1) + failed.job_key = 'sess-0/M000' + inv._queue_call_ranges(failed, range(2)) + inv.discard_pending({'sess-0/M000'}, {'M000'}) + assert inv.running_workers == 0 + assert inv.pending_calls_q.empty() + assert inv.job_monitor.token_bucket_q.empty() + inv.job_monitor.close_jobs.assert_called_once_with({'M000'}) + + def test_a_restart_forgets_tokens_handed_back_after_the_stop(self): + """ + A monitor's final sweep can hand tokens back after the invoker + stopped. The restart counts no running worker, so each of those + tokens would invoke one worker beyond max_workers + """ + inv = self._faas() + inv.max_workers = 1 + inv.ASYNC_INVOKERS = 1 + for _ in range(3): + inv.job_monitor.token_bucket_q.put('#') + with patch.object(inv, '_async_invoker_loop'), \ + patch.object(inv, '_invoke_direct'): + inv.compute_handler = MagicMock() + inv._invoke_job(_job(chunksize=1, total_calls=2)) + assert inv.job_monitor.token_bucket_q.qsize() == 1 + def test_queue_call_ranges_chunks_ids(self): inv = self._faas() job = _job(chunksize=2) diff --git a/lithops/tests/test_localhost.py b/lithops/tests/test_localhost.py index b7c1dd8a6..ba8ed702d 100644 --- a/lithops/tests/test_localhost.py +++ b/lithops/tests/test_localhost.py @@ -104,6 +104,36 @@ def test_environment_python_tagged_image_is_container(self): localhost_config.LocalhostEnvironment.CONTAINER ) + def test_environment_default_for_every_interpreter_basename(self): + # The default runtime is basename(sys.executable), which is not + # always a plain pythonX.Y: free-threaded and debug builds, the + # python.org macOS installer and Windows GUI interpreters all have + # suffixes of their own, and none of them is a docker image + for runtime in ( + 'python3.13t', + 'python3.14t', + 'python3.12d', + 'python3-intel64', + 'pythonw', + 'pythonw.exe', + 'Python.exe', + ): + assert localhost_config.get_environment(runtime) is ( + localhost_config.LocalhostEnvironment.DEFAULT + ), runtime + + def test_environment_container_for_python_images(self): + for runtime in ( + 'python:3.12', + 'python:3.12-slim', + 'registry/python', + 'registry.example.com:5000/python', + 'docker.io/library/python:3.12', + ): + assert localhost_config.get_environment(runtime) is ( + localhost_config.LocalhostEnvironment.CONTAINER + ), runtime + def test_environment_enum_values(self): assert localhost_config.LocalhostEnvironment.DEFAULT.value == 'default' assert localhost_config.LocalhostEnvironment.CONTAINER.value == 'container' diff --git a/lithops/tests/test_monitor.py b/lithops/tests/test_monitor.py index 028bc8981..a4a7578d4 100644 --- a/lithops/tests/test_monitor.py +++ b/lithops/tests/test_monitor.py @@ -831,6 +831,40 @@ def test_generate_tokens_waits_for_full_chunk_then_does_not_repeat(self): monitor._generate_tokens(running, all_done) assert monitor.token_bucket_q.empty() + def test_generate_tokens_emits_when_done_is_listed_before_running(self): + """ + A listing can return the status object before the init mark: the + init write failed, or the list is not read-after-write consistent. + Treating that completion as already accounted leaves the worker + token unissued, and the calls still queued never start + """ + monitor = self._storage(chunksize=1) + monitor.present_jobs.add('M000') + done = {('sess-0', 'M000', '00000')} + monitor._generate_tokens(set(), done) + assert monitor.token_bucket_q.empty() + + running = {(('sess-0', 'M000', '00000'), 'w1')} + monitor._generate_tokens(running, done) + assert monitor.token_bucket_q.get_nowait() == '#' + + def test_the_final_sweep_hands_back_the_workers_it_finds_free(self): + """ + wait() stops the monitor once its futures are done, which the blind + sweep can find before the listing credits their worker. The sweep + run() makes after the stop is then the last chance for that token: + the next monitor does not watch this job + """ + monitor = self._storage(chunksize=1) + monitor.present_jobs.add('M000') + monitor.internal_storage.get_job_status.return_value = ( + {(('sess-0', 'M000', '00000'), 'w1')}, + {('sess-0', 'M000', '00000')}, + ) + monitor.should_run = False + monitor.run() + assert monitor.token_bucket_q.get_nowait() == '#' + def test_generate_tokens_one_per_worker(self): monitor = self._storage(chunksize=1) running = { @@ -901,6 +935,7 @@ def test_tag_future_as_ready_queries_only_matching_ids_when_not_near_complete( def test_poll_and_process_returns_new_done_ids_and_tags(self): monitor = self._storage() + monitor.add_futures([FakeFuture('M000', invoked=True, call_id='00000')]) monitor._generate_tokens = MagicMock() monitor._tag_future_as_running = MagicMock() monitor._tag_future_as_ready = MagicMock() @@ -911,13 +946,29 @@ def test_poll_and_process_returns_new_done_ids_and_tags(self): new = monitor._poll_and_process_job_status() assert new == done monitor.internal_storage.get_job_status.assert_called_once_with( - 'sess-0', job_ids=set() + 'sess-0', job_ids={'M000'} ) monitor._generate_tokens.assert_called_once_with(running, done) monitor._tag_future_as_running.assert_called_once_with(running) monitor._tag_future_as_ready.assert_called_once_with(done) monitor._print_status_log.assert_called_once_with() + def test_poll_and_process_does_not_list_storage_when_idle(self): + """ + The monitor stays up after wait() with no futures left. A LIST of + the executor prefix then is a paid object-storage call for nothing + """ + monitor = self._storage() + monitor._generate_tokens = MagicMock() + monitor._tag_future_as_running = MagicMock() + monitor._tag_future_as_ready = MagicMock() + new = monitor._poll_and_process_job_status() + assert new == set() + monitor.internal_storage.get_job_status.assert_not_called() + monitor._generate_tokens.assert_not_called() + monitor._tag_future_as_running.assert_not_called() + monitor._tag_future_as_ready.assert_not_called() + def test_poll_and_process_emits_token_when_chunk_completes(self): monitor = self._storage() future0 = FakeFuture('M000', invoked=True, call_id='00000') @@ -1321,6 +1372,52 @@ def _receive_messages(self, timeout): monitor._apply_status_message(second) assert tokens.qsize() == 1 + def test_a_removed_job_still_hands_its_token_back(self): + """ + wait() drops the futures of a failed job so they are no longer + tagged ready. The worker that ran them is still this executor's + and must free its token, or a later map() stays short of workers + """ + class FakePoll(PollingMessageMonitor): + backend_name = 'fake' + + def _receive_messages(self, timeout): + return [] + + tokens = queue.Queue() + monitor = FakePoll( + 'sess-0', None, tokens, {'M000': 1}, True, {} + ) + future = FakeFuture('M000', invoked=True) + monitor.add_futures([future]) + monitor.remove_futures([future]) + payload, _raw = _status(kind='__end__') + monitor._apply_status_message(payload) + assert tokens.qsize() == 1 + + def test_a_closed_job_does_not_hand_a_late_token_back(self): + """ + The invoker already forgot this job's workers. A late __end__ + must not put another token in the bucket + """ + class FakePoll(PollingMessageMonitor): + backend_name = 'fake' + + def _receive_messages(self, timeout): + return [] + + tokens = queue.Queue() + monitor = FakePoll( + 'sess-0', None, tokens, {'M000': 1}, True, {} + ) + future = FakeFuture('M000', invoked=True) + monitor.add_futures([future]) + monitor.remove_futures([future]) + monitor.close_jobs({'M000'}) + payload, _raw = _status(kind='__end__') + monitor._apply_status_message(payload) + assert tokens.qsize() == 0 + def test_stop_does_not_delete_cleanup_does_once(self): class FakePoll(PollingMessageMonitor): backend_name = 'fake' @@ -1508,6 +1605,109 @@ def test_a_redelivered_end_frees_one_token_not_two(self): monitor._apply_status_message(dict(second)) assert tokens.qsize() == 1 + def test_two_threads_finishing_one_chunk_release_one_token(self): + """ + The submitter thread applies a status that was held, while the + monitor thread applies the one that just arrived. Both can see the + chunk cross its size and each hand a token back + """ + tokens = queue.Queue() + monitor = self._monitor(tokens=tokens, chunksize={'M000': 2}) + monitor.add_futures([ + FakeFuture('M000', invoked=True, call_id='00000'), + FakeFuture('M000', invoked=True, call_id='00001'), + ]) + + class StaleMembership(set): + """ + Reports the membership it saw, then waits. Both threads can + observe "not done yet" before either records the worker + """ + + def __contains__(self, item): + found = super().__contains__(item) + time.sleep(0.05) + return found + + monitor.workers_done = StaleMembership() + start = threading.Barrier(2) + errors = [] + + def apply(call_id): + try: + start.wait(timeout=2) + payload, _raw = _status( + call_id=call_id, kind='__end__', chunksize=2 + ) + payload['activation_id'] = 'w1' + monitor._generate_tokens(payload) + except Exception as exc: # noqa: BLE001 - recorded, not handled + errors.append(exc) + + threads = [ + threading.Thread(target=apply, args=('00000',)), + threading.Thread(target=apply, args=('00001',)), + ] + for thread in threads: + thread.start() + for thread in threads: + thread.join(timeout=5) + + assert not errors + assert all(not thread.is_alive() for thread in threads) + assert tokens.qsize() == 1 + + def test_an_init_cannot_overwrite_an_end_applied_at_the_same_time(self): + """ + The check that a future is not finished and the write that marks it + running are separate. An __init__ that passes the check can land + after the __end__ and put a finished call back to running + """ + monitor = self._monitor() + entered_running = threading.Event() + + class SlowRunning(FakeFuture): + def _set_running(self, call_status): + entered_running.set() + time.sleep(0.05) + self.ready = False + super()._set_running(call_status) + + future = SlowRunning('M000', invoked=True, call_id='00000') + monitor.add_futures([future]) + init, _raw = _status(kind='__init__') + end, _raw = _status(kind='__end__') + errors = [] + + def apply_init(): + try: + monitor._apply_status_message(init) + except Exception as exc: # noqa: BLE001 - recorded, not handled + errors.append(exc) + + def apply_end(): + try: + # Only once the init has passed its "not started" check and + # is inside the transition, so the end cannot simply win + # the race by running first + assert entered_running.wait(timeout=2) + monitor._apply_status_message(end) + except Exception as exc: # noqa: BLE001 - recorded, not handled + errors.append(exc) + + threads = [ + threading.Thread(target=apply_init), + threading.Thread(target=apply_end), + ] + for thread in threads: + thread.start() + for thread in threads: + thread.join(timeout=5) + + assert not errors + assert future.ready is True + assert future.running is False + def test_a_status_of_a_tracked_future_is_never_held(self): """ A second __init__ of a call that is already running used to be held @@ -1763,7 +1963,7 @@ class Fake(MessageCallStatus): RETRY_SLEEP = 0 closed = 0 - def _publish(self, payload): + def _publish_to(self, target, payload): publish(payload) def close(self): @@ -1779,7 +1979,7 @@ class Plain(MessageCallStatus): service_name = 'plain' RETRY_SLEEP = 0 - def _publish(self, payload): + def _publish_to(self, target, payload): publish(payload) return Plain @@ -2033,6 +2233,224 @@ def test_no_client_is_built_before_the_first_status(self): cls(self._job(name), MagicMock()) assert build.call_count == 0, name + def _chain_status_cls(self, published, fails): + from lithops.monitoring.status import MessageCallStatus + + class Chain(MessageCallStatus): + service_name = 'chain' + RETRY_SLEEP = 0 + + def _publish_to(self, target, payload): + published.append(target) + if fails(target): + raise ConnectionError(f'{target} is not there') + + return Chain + + def test_a_remote_invoker_queue_that_is_gone_is_tried_once(self): + """ + The remote invoker deletes its queue as soon as every chunk is + invoked, long before the calls finish. Every status then went + through five attempts with back-off, each one sending it to the + client's queue again + """ + invoker_queue = remote_invoker_queue_name('sess-0') + job = self._job() + job.monitoring_queues = ['lithops-sess-0', invoker_queue] + published = [] + cls = self._chain_status_cls( + published, lambda target: target == invoker_queue + ) + with patch('lithops.monitoring.status.time.sleep') as sleep, \ + patch('lithops.monitoring.status.logger') as log: + cls(job, MagicMock()).send_finish_event() + + assert published == ['lithops-sess-0', invoker_queue] + sleep.assert_not_called() + log.error.assert_not_called() + + def test_only_the_queue_that_failed_is_retried(self): + """ + A nested call reports to its parent's queue as well, which is the + only way the parent learns of the futures it is handed back, so + that one is retried; the queues that took the status do not get it + a second time + """ + job = self._job() + job.monitoring_queues = ['lithops-parent', 'lithops-sess-0'] + published = [] + failures = iter([True]) + cls = self._chain_status_cls( + published, + lambda target: target == 'lithops-parent' + and next(failures, False), + ) + cls(job, MagicMock()).send_init_event() + + assert published == [ + 'lithops-parent', 'lithops-sess-0', 'lithops-parent' + ] + + def test_redis_does_not_bring_back_a_deleted_invoker_list_for_good(self): + """ + An RPUSH onto a list that was deleted creates it again, and nothing + would ever delete that one + """ + from lithops.monitoring.backends.redis.status import RedisCallStatus + from lithops.tests.mp_fakeredis import FakeRedis + + client = FakeRedis() + invoker_queue = remote_invoker_queue_name('sess-0') + job = self._job('redis') + job.monitoring_queues = ['lithops-sess-0', invoker_queue] + with _client(redis_backend, 'redis_client', client): + RedisCallStatus(job, MagicMock()).send_init_event() + + assert client.llen(invoker_queue) == 1 + client.advance(RedisCallStatus.BEST_EFFORT_TTL) + assert client.llen(invoker_queue) == 0 + assert client.llen('lithops-sess-0') == 1 + + def test_sqs_never_creates_a_queue_from_the_worker(self): + """ + Creating the queue of a remote invoker that is gone left an orphan + queue behind, one per executor, that nothing deletes + """ + from lithops.monitoring.backends.aws_sqs.status import SqsCallStatus + + class QueueDoesNotExist(Exception): + pass + + invoker_queue = remote_invoker_queue_name('sess-0') + + def queue_url(QueueName): + if QueueName == invoker_queue: + raise QueueDoesNotExist(QueueName) + return {'QueueUrl': f'https://sqs/{QueueName}'} + + client = MagicMock() + client.get_queue_url.side_effect = queue_url + job = self._job('aws_sqs') + job.monitoring_queues = ['lithops-sess-0', invoker_queue] + with _client(sqs_backend, 'sqs_client', client), \ + patch('lithops.monitoring.status.time.sleep') as sleep: + SqsCallStatus(job, MagicMock()).send_init_event() + + client.create_queue.assert_not_called() + sleep.assert_not_called() + urls = [ + c.kwargs['QueueUrl'] for c in client.send_message.call_args_list + ] + assert urls == ['https://sqs/lithops-sess-0'] + + def test_pubsub_makes_no_admin_request_per_call(self): + """ + Every call used to ask for the creation of every topic of its chain, + which the monitor had already created, before publishing to it + """ + from lithops.monitoring.backends.gcp_pubsub.status import ( + GcpPubsubCallStatus, + ) + + publisher = MagicMock() + job = self._job('gcp_pubsub') + job.config['gcp_pubsub'] = {'project_name': 'proj'} + with patch.object( + pubsub_backend, 'pubsub_clients', + return_value=(publisher, MagicMock()), + ): + for call_id in ('00000', '00001', '00002'): + job.call_id = call_id + status = GcpPubsubCallStatus(job, MagicMock()) + status.send_init_event() + status.send_finish_event() + + publisher.create_topic.assert_not_called() + topics = {c.args[0] for c in publisher.publish.call_args_list} + assert topics == {'projects/proj/topics/lithops-sess-0'} + assert publisher.publish.call_count == 6 + + def _azure_status(self, storage, events=None): + from lithops.monitoring.backends.azure_queue.status import ( + AzureQueueCallStatus, + ) + + queue_client = MagicMock() + service = MagicMock() + service.get_queue_client.return_value = queue_client + if events is not None: + storage.put_data.side_effect = \ + lambda key, data: events.append('storage') + queue_client.send_message.side_effect = \ + lambda body: events.append('message') + with _client(azure_backend, 'queue_service', service): + status = AzureQueueCallStatus(self._job('azure_queue'), storage) + status.service + return status, queue_client + + def test_azure_leaves_the_logs_out_of_a_status_that_does_not_fit(self): + """ + The worker puts the logs of the call in its last status, and a + chatty function takes that past the 64 KiB Azure Queue takes: the + __end__ failed five times and only reached the client through the + storage sweep, a minute later + """ + from lithops.monitoring.status import PARTIAL_STATUS_KEY + + storage = MagicMock() + status, queue_client = self._azure_status(storage) + logs = 'x' * 100_000 + status.add('logs', logs) + status.send_finish_event() + + queue_client.send_message.assert_called_once() + body = queue_client.send_message.call_args.args[0] + assert len(body.encode('utf-8')) <= status.MAX_MESSAGE_SIZE + message = json.loads(body) + assert 'logs' not in message + assert PARTIAL_STATUS_KEY not in message + assert message['type'] == '__end__' + stored = json.loads(storage.put_data.call_args.args[1]) + assert stored['logs'] == logs + + def test_a_status_that_still_does_not_fit_is_sent_partial(self): + """ + What is left once the logs are out can still be too big, a large + traceback for one. The message then only tells the client to read + the storage copy, which has to be there before the message is + """ + from lithops.monitoring.status import PARTIAL_STATUS_KEY + + storage = MagicMock() + events = [] + status, queue_client = self._azure_status(storage, events) + status.add('exception', True) + status.add('exc_info', 'x' * 100_000) + status.send_finish_event() + + assert events == ['storage', 'message'] + message = json.loads(queue_client.send_message.call_args.args[0]) + assert message[PARTIAL_STATUS_KEY] is True + assert 'exc_info' not in message + assert message['exception'] is True + assert message['call_id'] == '00000' + stored = json.loads(storage.put_data.call_args.args[1]) + assert stored['exc_info'] == 'x' * 100_000 + + def test_the_worker_reports_how_many_calls_its_chunk_has(self): + """ + The last chunk of a job is usually shorter than the chunksize, and + the worker that runs it has to say so, or the client waits for + calls that do not exist before handing its token back + """ + cls = self._status_cls(lambda payload: None) + job = self._job() + job.chunksize = 3 + job.total_calls = 10 + for call_id, expected in (('00000', 3), ('00005', 3), ('00009', 1)): + job.call_id = call_id + assert cls(job, MagicMock()).status['worker_calls'] == expected + class TestRedisMonitor: @@ -2088,8 +2506,7 @@ def test_call_status_publishes_to_every_queue_in_the_chain(self): ) with _client(redis_backend, 'redis_client', client): status = RedisCallStatus(job, MagicMock()) - status.status['type'] = '__init__' - status._publish('{"type": "__init__"}') + status.send_init_event() assert client.llen('lithops-parent') == 1 assert client.llen('lithops-sess-0') == 1 @@ -2298,7 +2715,7 @@ def test_call_status_sends_to_every_queue_in_the_chain(self): ) with _client(sqs_backend, 'sqs_client', client): status = SqsCallStatus(job, MagicMock()) - status._publish('{"type": "__init__"}') + status.send_init_event() urls = [c.kwargs['QueueUrl'] for c in client.send_message.call_args_list] assert urls == ['https://sqs/parent', 'https://sqs/own'] @@ -2405,14 +2822,14 @@ def test_call_status_publishes_to_every_topic_in_the_chain(self): return_value=(publisher, MagicMock()), ): status = GcpPubsubCallStatus(job, MagicMock()) - status._publish('{"type": "__init__"}') + status.send_init_event() topics = [c.args[0] for c in publisher.publish.call_args_list] assert topics == [ 'projects/proj/topics/lithops-parent', 'projects/proj/topics/lithops-sess-0', ] for call in publisher.publish.call_args_list: - assert call.args[1] == b'{"type": "__init__"}' + assert json.loads(call.args[1])['type'] == '__init__' class TestAzureQueueMonitor: @@ -2496,9 +2913,11 @@ def test_call_status_sends_to_every_queue_in_the_chain(self): ) with _client(azure_backend, 'queue_service', service): status = AzureQueueCallStatus(job, MagicMock()) - status._publish('{"type": "__init__"}') - parent.send_message.assert_called_once_with('{"type": "__init__"}') - own.send_message.assert_called_once_with('{"type": "__init__"}') + status.send_init_event() + for queue_client in (parent, own): + queue_client.send_message.assert_called_once() + body = queue_client.send_message.call_args.args[0] + assert json.loads(body)['type'] == '__init__' class TestAzureQueueNames: @@ -2558,12 +2977,467 @@ def test_the_monitor_and_the_workers_agree_on_the_name(self): ) with _client(azure_backend, 'queue_service', service): status = AzureQueueCallStatus(job, MagicMock()) - assert status._targets() == [monitor.queue] + assert [ + azure_queue_name(name) for name in status._targets() + ] == [monitor.queue] assert monitor.queue == azure_queue_name( monitoring_queue_name('SESS-0') ) +def _wait_for(predicate, timeout=5): + deadline = time.time() + timeout + while not predicate() and time.time() < deadline: + time.sleep(0.01) + return predicate() + + +class TestTheNextMapAfterAWait: + """ + A wait() whose futures are all done stops the monitor, and the next map() + is invoked before start() is called for it. Whatever the first workers of + that map report in between has to reach the monitor that tracks them + """ + + def _job_monitor(self, cls, config=None): + storage = MagicMock() + storage.get_storage_config.return_value = {'monitoring_interval': 2} + job_monitor = JobMonitor('sess-0', storage, config=config) + if cls is not None: + job_monitor.MonitorClass = cls + return job_monitor + + def test_the_first_statuses_of_the_next_map_are_not_lost(self): + """ + SQS, Pub/Sub and Azure Queue block in a read that stop() cannot cut + short. The monitor the wait() stopped used to be replaced in + start(), so its last read took the first statuses of the next map, + held them for futures it did not track and went away with them + """ + broker = queue.Queue() + + class LongPoll(PollingMessageMonitor): + backend_name = 'long-poll' + POLL_TIMEOUT = 0.5 + STORAGE_SWEEP_INTERVAL = 0 + + def _receive_messages(self, timeout): + try: + yield broker.get(timeout=timeout) + except queue.Empty: + return + + job_monitor = self._job_monitor(LongPoll) + with patch.object(LongPoll, 'prepare_config', return_value={}): + try: + job_monitor.prepare() + first = FakeFuture('M000', invoked=True) + job_monitor.start([first], job_id='M000', chunksize=1) + broker.put(_status(kind='__end__')[1]) + assert _wait_for(lambda: first.ready) + job_monitor.stop() + stopped = job_monitor.monitor + + job_monitor.prepare() + assert job_monitor.monitor is not stopped + assert not stopped.is_alive() + + # The workers of the next map report before start() + end, _raw = _status(kind='__end__') + end['job_id'] = 'M001' + broker.put(json.dumps(end)) + second = FakeFuture('M001', invoked=True) + job_monitor.start([second], job_id='M001', chunksize=1) + assert _wait_for(lambda: second.ready) + assert not stopped._held_status + finally: + job_monitor.cleanup() + + def test_rabbitmq_declares_the_queue_again_before_the_next_map(self): + """ + Cancelling the consumer of an auto-delete queue deletes it, so the + statuses published before start() declared it again were dropped + by the broker. The queue is declared before the workers are + invoked, and is no longer auto-delete + """ + config = { + 'lithops': {'monitoring': 'rabbitmq'}, + 'rabbitmq': {'amqp_url': 'amqp://guest@localhost'}, + } + pika = rabbitmq_backend.pika + with patch.object(pika, 'URLParameters'), \ + patch.object(pika, 'BlockingConnection') as connection: + job_monitor = self._job_monitor(None, config) + declare = connection.return_value.channel.return_value \ + .queue_declare + job_monitor.prepare() + assert declare.call_count == 1 + job_monitor.stop() + + job_monitor.prepare() + assert declare.call_count == 2 + assert declare.call_args.kwargs['queue'] == 'lithops-sess-0' + assert declare.call_args.kwargs['auto_delete'] is False + assert declare.call_args.kwargs['arguments']['x-expires'] > 0 + + def test_a_status_the_stopped_monitor_held_is_handed_over(self): + class Idle(PollingMessageMonitor): + backend_name = 'idle' + + def _receive_messages(self, timeout): + return [] + + job_monitor = self._job_monitor(Idle) + with patch.object(Idle, 'prepare_config', return_value={}): + try: + job_monitor.prepare() + stopped = job_monitor.monitor + # Read by the last poll of the monitor before it stopped + end, _raw = _status(kind='__end__') + end['job_id'] = 'M001' + stopped._apply_status_message(end) + job_monitor.stop() + + future = FakeFuture('M001', invoked=True) + job_monitor.start([future], job_id='M001', chunksize=1) + assert job_monitor.monitor is not stopped + assert future.ready is True + finally: + job_monitor.cleanup() + + +class TestPartialStatusMessages: + """ + A status that did not fit in a message arrives without what the client + needs to finish the call, and the full one is in the storage + """ + + class FakePoll(PollingMessageMonitor): + backend_name = 'fake' + + def _receive_messages(self, timeout): + return [] + + def _partial(self): + from lithops.monitoring.status import PARTIAL_STATUS_KEY + payload, _raw = _status(kind='__end__') + payload.update({'exception': True, PARTIAL_STATUS_KEY: True}) + return payload + + def test_the_full_status_is_read_from_the_storage(self): + """ + Applied as it came, the future would re-raise from an exc_info that + is not there + """ + storage = MagicMock() + full, _raw = _status(kind='__end__') + full.update({'exception': True, 'exc_info': 'pickled traceback'}) + storage.get_call_status.return_value = full + monitor = self.FakePoll('sess-0', storage, queue.Queue(), {}, False, {}) + future = FakeFuture('M000', invoked=True) + monitor.add_futures([future]) + + monitor._apply_status_message(self._partial()) + + assert future.ready is True + assert future._call_status['exc_info'] == 'pickled traceback' + storage.get_call_status.assert_called_once_with( + 'sess-0', 'M000', '00000' + ) + + def test_a_partial_status_that_arrived_early_is_completed_later(self): + storage = MagicMock() + full, _raw = _status(kind='__end__') + full['result'] = 'inline result' + storage.get_call_status.return_value = full + monitor = self.FakePoll('sess-0', storage, queue.Queue(), {}, False, {}) + + monitor._apply_status_message(self._partial()) + storage.get_call_status.assert_not_called() + + future = FakeFuture('M000', invoked=True) + monitor.add_futures([future]) + assert future.ready is True + assert future._call_status['result'] == 'inline result' + + def test_without_the_storage_copy_the_call_is_left_running(self): + """ + For the storage sweep or the timeout checker to finish, rather than + finished with a status the future cannot read + """ + storage = MagicMock() + storage.get_call_status.return_value = None + monitor = self.FakePoll('sess-0', storage, queue.Queue(), {}, False, {}) + future = FakeFuture('M000', invoked=True) + monitor.add_futures([future]) + + monitor._apply_status_message(self._partial()) + + assert future.ready is False + assert future.running is True + assert future._call_status['type'] == '__init__' + + +class TestTokensOfTheLastChunk: + """ + The last chunk of a job is usually shorter than the chunksize: 10 calls + in chunks of 3 leave a last worker with 1. A token held back for it is + a worker the invoker counts as busy for ever, and once they add up to + max_workers every chunk still queued waits for good + """ + + class FakePoll(PollingMessageMonitor): + backend_name = 'fake' + + def _receive_messages(self, timeout): + return [] + + def _futures(self, total=10): + return [ + FakeFuture('M000', invoked=True, call_id=f'{i:05d}') + for i in range(total) + ] + + def test_the_worker_of_the_last_chunk_frees_its_token(self): + tokens = queue.Queue() + monitor = self.FakePoll('sess-0', None, tokens, {'M000': 3}, True, {}) + monitor.add_futures(self._futures()) + end, _raw = _status(call_id='00009', kind='__end__', chunksize=3) + end.update({'activation_id': 'w4', 'worker_calls': 1}) + + monitor._apply_status_message(end) + + assert tokens.qsize() == 1 + + def test_the_size_of_the_job_frees_it_when_the_worker_does_not_say(self): + """ + A status from a worker that does not report the size of its chunk + is sized from the number of calls of the job, which the invoker + hands the monitor along with its futures + """ + class NotStarted(self.FakePoll): + def start(self): + pass + + storage = MagicMock() + storage.get_storage_config.return_value = {'monitoring_interval': 2} + job_monitor = JobMonitor('sess-0', storage) + job_monitor.MonitorClass = NotStarted + with patch.object(NotStarted, 'prepare_config', return_value={}): + job_monitor.start( + self._futures(), job_id='M000', chunksize=3, + generate_tokens=True, + ) + monitor = job_monitor.monitor + end, _raw = _status(call_id='00009', kind='__end__', chunksize=3) + end['activation_id'] = 'w4' + + monitor._apply_status_message(end) + + assert job_monitor.token_bucket_q.get_nowait() == '#' + assert monitor.job_total_calls == {'M000': 10} + + def test_a_full_chunk_still_waits_for_all_its_calls(self): + tokens = queue.Queue() + monitor = self.FakePoll('sess-0', None, tokens, {'M000': 3}, True, {}) + monitor.job_total_calls = {'M000': 10} + monitor.add_futures(self._futures()) + for call_id in ('00006', '00007'): + end, _raw = _status(call_id=call_id, kind='__end__', chunksize=3) + end['activation_id'] = 'w3' + monitor._apply_status_message(end) + assert tokens.qsize() == 0 + end, _raw = _status(call_id='00008', kind='__end__', chunksize=3) + end['activation_id'] = 'w3' + monitor._apply_status_message(end) + assert tokens.qsize() == 1 + + def test_the_storage_monitor_frees_the_worker_of_the_last_chunk(self): + tokens = queue.Queue() + monitor = StorageMonitor( + 'sess-0', MagicMock(), tokens, {'M000': 3}, True, + {'monitoring_interval': 1}, + ) + monitor.job_total_calls = {'M000': 10} + monitor.add_futures(self._futures()) + last = ('sess-0', 'M000', '00009') + + monitor._generate_tokens({(last, 'w4')}, {last}) + + assert tokens.get_nowait() == '#' + assert tokens.empty() + + def test_a_timed_out_call_hands_its_token_back(self): + """ + A worker that never reports back, because it was killed at the + execution timeout, gave no token back either + """ + tokens = queue.Queue() + monitor = self.FakePoll('sess-0', None, tokens, {'M000': 1}, True, {}) + future = FakeFuture( + 'M000', running=True, execution_timeout=1, activation_id='w1' + ) + future._call_status = {'worker_start_tstamp': time.time() - 100} + monitor.add_futures([future]) + + monitor._future_timeout_checker() + + assert future.ready is True + assert tokens.qsize() == 1 + # The worker was not dead after all, and its __end__ turns up late + end, _raw = _status(kind='__end__') + end['activation_id'] = 'w1' + monitor._apply_status_message(end) + assert tokens.qsize() == 1 + + def test_the_storage_monitor_hands_back_the_token_of_a_timed_out_call( + self, + ): + tokens = queue.Queue() + storage = MagicMock() + storage.get_call_status.return_value = None + monitor = StorageMonitor( + 'sess-0', storage, tokens, {'M000': 2}, True, + {'monitoring_interval': 1}, + ) + first = FakeFuture('M000', invoked=True, call_id='00000') + second = FakeFuture( + 'M000', running=True, call_id='00001', execution_timeout=1, + activation_id='w1', + ) + second._call_status = {'worker_start_tstamp': time.time() - 100} + monitor.add_futures([first, second]) + ids = [('sess-0', 'M000', '00000'), ('sess-0', 'M000', '00001')] + monitor.present_jobs = {'M000'} + + # Both calls started in w1; only the first one ever finished + monitor._generate_tokens({(i, 'w1') for i in ids}, {ids[0]}) + assert tokens.empty() + + monitor._future_timeout_checker([second]) + + assert second.ready is True + assert tokens.get_nowait() == '#' + assert tokens.empty() + + def test_a_nested_status_frees_no_token_of_this_executor(self): + tokens = queue.Queue() + monitor = self.FakePoll('sess-0', None, tokens, {'M000': 1}, True, {}) + nested_id = 'sess-0-A000-00000-1' + monitor.add_futures([ + FakeFuture('M000', invoked=True, executor_id=nested_id) + ]) + end, _raw = _status(kind='__end__') + end['executor_id'] = nested_id + + monitor._apply_status_message(end) + + assert tokens.qsize() == 0 + + +class TestNestedStatusesHeldByTheClient: + """ + A worker that waits on an executor of its own publishes every status of + it to the queue of the client as well, logs and all, and the client + holds them for futures it may never track + """ + + class FakePoll(PollingMessageMonitor): + backend_name = 'fake' + + def _receive_messages(self, timeout): + return [] + + NESTED = 'sess-0-A000-00000-1' + + def _nested_end(self, call_id='00000', **extra): + payload, _raw = _status(call_id=call_id, kind='__end__') + payload['executor_id'] = self.NESTED + payload.update(extra) + return payload + + def _monitor(self): + monitor = self.FakePoll('sess-0', None, queue.Queue(), {}, False, {}) + monitor.add_futures([ + FakeFuture('A000', running=True, execution_timeout=60) + ]) + return monitor + + def test_a_status_is_held_without_its_logs(self): + monitor = self._monitor() + monitor._apply_status_message( + self._nested_end(logs='x' * 100_000, result='nested result') + ) + + ((_arrived, held),) = monitor._held_status.values() + assert 'logs' not in held + + # ...and still finishes the nested future once it is handed back + nested = FakeFuture('M000', running=True, executor_id=self.NESTED) + monitor.add_futures([nested]) + assert nested.ready is True + assert nested._call_status['result'] == 'nested result' + + def test_a_status_too_old_to_match_gives_way(self, monkeypatch): + """ + The future of a nested call comes to light in the status of the call + that returned it, which finishes within its execution timeout + """ + now = [1000.0] + monkeypatch.setattr( + 'lithops.monitoring.monitor.time.time', lambda: now[0] + ) + monitor = self._monitor() + monitor._apply_status_message(self._nested_end('00000')) + + now[0] += 60 + monitor.HELD_STATUS_SLACK + 1 + monitor._apply_status_message(self._nested_end('00001')) + + assert list(monitor._held_status) == [ + (self.NESTED, 'M000', '00001') + ] + + def test_a_status_within_the_execution_timeout_is_kept(self, monkeypatch): + now = [1000.0] + monkeypatch.setattr( + 'lithops.monitoring.monitor.time.time', lambda: now[0] + ) + monitor = self._monitor() + monitor._apply_status_message(self._nested_end('00000')) + now[0] += 60 + monitor._apply_status_message(self._nested_end('00001')) + + nested = FakeFuture( + 'M000', running=True, executor_id=self.NESTED, call_id='00000' + ) + monitor.add_futures([nested]) + assert nested.ready is True + + def test_a_repeated_status_moves_to_the_back_of_the_line( + self, monkeypatch, + ): + """ + The oldest status is the first one held, which a second status of + the same call must not leave at the front with a new arrival time + """ + now = [1000.0] + monkeypatch.setattr( + 'lithops.monitoring.monitor.time.time', lambda: now[0] + ) + monitor = self._monitor() + init = self._nested_end('00000') + init['type'] = '__init__' + monitor._apply_status_message(init) + monitor._apply_status_message(self._nested_end('00001')) + now[0] += 30 + monitor._apply_status_message(self._nested_end('00000')) + + assert list(monitor._held_status) == [ + (self.NESTED, 'M000', '00001'), + (self.NESTED, 'M000', '00000'), + ] + + def _localhost_redis(): try: import redis diff --git a/lithops/tests/test_multiprocessing.py b/lithops/tests/test_multiprocessing.py index b9a77fe9e..67a07f6e9 100644 --- a/lithops/tests/test_multiprocessing.py +++ b/lithops/tests/test_multiprocessing.py @@ -127,21 +127,68 @@ def real_redis(): class FakeFuture: - def __init__(self, value=None, error=False): + """ + A call. Finished unless built ``running``, in which case it finishes + when finish() says so, or when something waits on it without a timeout + """ + + def __init__(self, value=None, error=False, exception=None, running=False): self.executor_id = 'sess-0' self.job_id = 'A000' self.call_id = '00000' - self.done = True - self.error = error - self.success = not error - self.ready = True self.stats = {'worker_exec_time': 0.5} self._value = value + self._exception = exception + self._fails = error or exception is not None + self.done = self.error = self.success = self.ready = False + if not running: + self.finish() + + def finish(self): + self.done = self.ready = True + self.error = self._fails + self.success = not self._fails + + def _set_exception(self): + """ + What FunctionExecutor.wait() does to the futures it gives up on: done, + with no status and no result + """ + self.done = True + self.ready = self.success = self.error = False + self._value = self._exception = None + + def status(self, throw_except=True, internal_storage=None, check_only=False): + if not (self.done or self.success): + assert check_only, 'a real future would block here' + return None + if self.error and throw_except and self._exception is not None: + raise self._exception + return {} def result(self, throw_except=True, internal_storage=None): + self.status(throw_except=throw_except) return self._value +def _fake_wait(futures, timeout=None, throw_except=True, **kwargs): + """ + lithops.wait.wait on fake futures: the calls still running finish while + it waits, unless it was given a timeout, which then runs out + """ + running = [f for f in futures if not (f.success or f.done)] + if running and timeout is not None: + raise TimeoutError( + 'Timeout of {} seconds exceeded waiting for function ' + 'activations to finish'.format(timeout) + ) + for fut in running: + fut.finish() + for fut in futures: + fut.status(throw_except=throw_except) + return list(futures), [] + + class FakeExecutor: """Stand-in for lithops.FunctionExecutor, recording what it was given""" @@ -149,10 +196,15 @@ def __init__(self, **kwargs): self.kwargs = kwargs self.executor_id = 'sess-0' self.invoker = type('I', (), {'max_workers': 7})() + # What lithops.wait.wait is handed, which the fake one reads the + # executor back from + self.internal_storage = types.SimpleNamespace(executor=self) self.futures = [] + self.next_futures = [] self.call_async_calls = [] self.map_calls = [] self.wait_calls = [] + self.lithops_wait_calls = [] self.get_result_calls = [] self.exited = False self.results = None @@ -161,11 +213,18 @@ def __init__(self, **kwargs): def call_async(self, func, data, **kwargs): self.call_async_calls.append((func, data, kwargs)) - return FakeFuture(self._next_value()) + future = self.next_futures.pop(0) if self.next_futures else FakeFuture(self._next_value()) + self.futures.append(future) + return future def map(self, func, iterdata, **kwargs): self.map_calls.append((func, list(iterdata), kwargs)) - return [FakeFuture(self._next_value()) for _ in iterdata] + futures = [FakeFuture(self._next_value()) for _ in iterdata] + self.futures.extend(futures) + return futures + + def _monitor_of(self, futures): + return None def _next_value(self): """Hands out `results` one call at a time, in order""" @@ -175,11 +234,25 @@ def _next_value(self): self._result_index += 1 return value - def wait(self, fs=None, **kwargs): - self.wait_calls.append((fs, kwargs)) - if self.wait_error is not None: - raise self.wait_error - return list(fs or []), [] + def wait(self, fs=None, throw_except=True, timeout=None, **kwargs): + """ + FunctionExecutor.wait(), which takes any exception as the end of the + job: it marks the futures it waited on failed and force-cleans the + data of every job of the executor, results not read yet included + """ + self.wait_calls.append((fs, dict(kwargs, throw_except=throw_except, timeout=timeout))) + futures = list(fs or self.futures) + try: + if self.wait_error is not None: + raise self.wait_error + return _fake_wait(futures, timeout=timeout, throw_except=throw_except) + except Exception: + for fut in futures: + fut._set_exception() + for fut in self.futures: + if not fut.done: + fut._set_exception() + raise def get_result(self, fs=None, **kwargs): self.get_result_calls.append((fs, kwargs)) @@ -191,6 +264,18 @@ def __exit__(self, exc_type, exc_value, traceback): self.exited = True +def _fake_lithops_wait(fs, internal_storage, job_monitor=None, download_results=False, + throw_except=True, timeout=None, **kwargs): + """lithops.wait.wait, for the futures of a FakeExecutor""" + executor = internal_storage.executor + executor.lithops_wait_calls.append((fs, dict( + kwargs, download_results=download_results, throw_except=throw_except, timeout=timeout, + ))) + if executor.wait_error is not None: + raise executor.wait_error + return _fake_wait(fs, timeout=timeout, throw_except=throw_except) + + @pytest.fixture def executor(monkeypatch): """Every FunctionExecutor the package builds becomes the same fake""" @@ -203,6 +288,7 @@ def factory(**kwargs): monkeypatch.setattr('lithops.multiprocessing.pool.FunctionExecutor', factory) monkeypatch.setattr('lithops.multiprocessing.process.FunctionExecutor', factory) + monkeypatch.setattr(mp_util, 'lithops_wait', _fake_lithops_wait) return built @@ -296,6 +382,53 @@ def test_a_reference_must_be_a_key_or_a_list_of_keys(self, redis): with pytest.raises(TypeError, match='referenced must be'): mp_util.RemoteReference(42, client=redis) + def test_an_expired_counter_does_not_take_the_object_with_it(self, redis): + """ + Once the counter had expired, the next owner to go away decremented + it to -1, took itself for the last one and deleted the object under + everybody still using it + """ + from lithops.multiprocessing import Lock + lock = Lock() + in_worker = pickle.loads(pickle.dumps(lock)) + # What the server does once the counter's expiry runs out + redis.delete(lock._ref._rck) + del in_worker + gc.collect() + assert lock.acquire(block=False) is True + + def test_the_counter_lives_as_long_as_the_object_is_used(self, redis): + """ + The object's keys are refreshed on every use but the counter only + when an owner came or went, so a lock in use for longer than + REDIS_EXPIRY_TIME lost its count, and the owners going away could no + longer tell when the last one had + """ + from lithops.multiprocessing import Lock + mp_config.set_parameter(mp_config.REDIS_EXPIRY_TIME, 10) + lock = Lock() + in_worker = pickle.loads(pickle.dumps(lock)) + for _ in range(10): + redis.advance(4) + with in_worker: + pass + assert lock._ref.refcount() == 2 + del in_worker + gc.collect() + assert lock._ref.refcount() == 1 + assert lock.acquire(block=False) is True + + def test_a_queue_in_use_keeps_its_counter(self, redis): + from lithops.multiprocessing import Queue + mp_config.set_parameter(mp_config.REDIS_EXPIRY_TIME, 10) + queue = Queue() + in_worker = pickle.loads(pickle.dumps(queue)) + for n in range(10): + redis.advance(4) + in_worker.put(n) + assert queue.get() == n + assert queue._ref.refcount() == 2 + class TestContext: @@ -487,6 +620,45 @@ def test_a_pool_gives_its_executor_back(self, executor): pass assert executor[0].exited + def test_close_and_join_run_the_callbacks(self, executor): + """ + The standard library idiom: submit with a callback, close(), join(), + and read what the callbacks collected. They used to run only from + get(), so nothing was collected, and every get() ran them again + """ + from lithops.multiprocessing import Pool + pool = Pool(processes=2) + executor[0].results = [3, 5] + collected = [] + + def slow_append(value): + time.sleep(0.2) + collected.append(value) + + applied = pool.apply_async(abs, (-3,), callback=slow_append) + mapped = pool.map_async(abs, [-5], callback=slow_append) + pool.close() + pool.join() + assert sorted(collected, key=repr) == [3, [5]] + assert applied.get() == 3 + assert mapped.get() == [5] + assert len(collected) == 2 + + def test_close_and_join_run_the_error_callback(self, executor): + from lithops.multiprocessing import Pool + pool = Pool(processes=1) + error = ValueError('bad input') + executor[0].next_futures.append(FakeFuture(exception=error)) + errors = [] + result = pool.apply_async(int, ('x',), error_callback=errors.append) + pool.close() + pool.join() + assert errors == [error] + for _ in range(2): + with pytest.raises(ValueError, match='bad input'): + result.get() + assert errors == [error] + class TestApplyResult: @@ -518,7 +690,8 @@ def test_ready_once_the_call_reported_back(self, executor): fake = FakeExecutor() finished = FakeFuture() finished.done = False - finished.success = True + finished.success = False + finished.ready = True result = self._result(fake, [finished]) assert result.ready() is True @@ -558,7 +731,7 @@ def test_the_shape_of_a_result_does_not_depend_on_later_calls(self, executor): def test_wait_forwards_the_timeout(self, executor): result = self._result(FakeExecutor()) result.wait(timeout=5) - assert result._executor.wait_calls[0][1]['timeout'] == 5 + assert result._executor.lithops_wait_calls[0][1]['timeout'] == 5 def test_a_timeout_raises_the_multiprocessing_error(self, executor): """ @@ -584,6 +757,113 @@ def test_a_wait_that_timed_out_does_not_poison_get(self, executor): fake.wait_error = None assert result.get() == 7 + def test_get_raises_when_the_result_cannot_be_downloaded(self, executor, monkeypatch): + """ + wait(..., download_results=True, throw_except=False) used to mark a + missing output as Error and hand None back, so get() returned None + with successful() False and no exception + """ + from lithops.multiprocessing.pool import ApplyResult + + class MissingOutput: + def __init__(self): + self.success = self.done = self.ready = self.error = False + self._output = None + + def result(self, throw_except=True, internal_storage=None, **kwargs): + if self.done: + return self._output + if not throw_except: + self.error = self.success = self.done = True + return None + raise Exception('Unable to get the result from call 0') + + def status(self, throw_except=True, internal_storage=None, **kwargs): + return {} + + def wait(fs, internal_storage, job_monitor, download_results, + throw_except, timeout): + for item in fs: + if download_results: + item.result( + throw_except=throw_except, + internal_storage=internal_storage, + ) + + monkeypatch.setattr('lithops.multiprocessing.util.lithops_wait', wait) + executor_fake = types.SimpleNamespace(internal_storage=None) + executor_fake._monitor_of = lambda fs: None + result = ApplyResult(executor_fake, [MissingOutput()], None, None) + with pytest.raises(Exception, match='Unable to get the result'): + result.get() + + def test_get_after_terminate_does_not_block_a_callback_result(self, executor): + """ + terminate() used to return from the handler before the event was + set, so get() with a callback blocked forever + """ + from lithops.multiprocessing import TimeoutError as MpTimeoutError + from lithops.multiprocessing.pool import ApplyResult + + pending = FakeFuture(running=True) + cancelled = threading.Event() + cancelled.set() + result = ApplyResult( + FakeExecutor(), [pending], lambda value: None, None, + cancelled=cancelled, + ) + result._handler.join(3) + assert not result._handler.is_alive() + assert result.ready() + with pytest.raises(MpTimeoutError, match='terminated'): + result.get() + + def test_a_get_that_timed_out_leaves_the_call_to_finish(self, executor): + """ + FunctionExecutor.wait() takes a timeout as the end of the job and + marks the call failed: the result then said it was ready, and the + get() made once the call had finished came back with None + """ + from lithops.multiprocessing import Pool, TimeoutError as MpTimeoutError + pool = Pool(processes=1) + running = FakeFuture(42, running=True) + executor[0].next_futures.append(running) + result = pool.apply_async(abs, (-42,)) + with pytest.raises(MpTimeoutError): + result.get(timeout=5) + assert result.ready() is False + running.finish() + assert result.ready() is True + assert result.get() == 42 + + def test_a_call_that_fails_leaves_the_other_results_alone(self, executor): + """ + FunctionExecutor.wait() force-cleans the data of every job of the + executor when a call raises, so the results still on their way were + lost along with the one that failed + """ + from lithops.multiprocessing import Pool + pool = Pool(processes=2) + other_call = FakeFuture(7, running=True) + executor[0].next_futures += [FakeFuture(exception=ValueError('bad input')), other_call] + failing = pool.apply_async(int, ('x',)) + other = pool.apply_async(abs, (-7,)) + with pytest.raises(ValueError, match='bad input'): + failing.get() + assert other.ready() is False + other_call.finish() + assert other.get() == 7 + + def test_the_callback_runs_once_whatever_get_is_called(self, executor): + from lithops.multiprocessing import Pool + pool = Pool(processes=1) + executor[0].results = [4] + seen = [] + result = pool.apply_async(abs, (-4,), callback=seen.append) + assert result.get(timeout=5) == 4 + assert result.get() == 4 + assert seen == [4] + class TestIMapIterator: @@ -718,14 +998,62 @@ def test_join_waits_for_the_call(self, executor, redis): proc = Process(target=_double, args=(1,)) proc.start() proc.join() - assert executor[0].wait_calls + assert executor[0].lithops_wait_calls def test_join_forwards_the_timeout(self, executor, redis): from lithops.multiprocessing import Process proc = Process(target=_double, args=(1,)) proc.start() proc.join(timeout=5) - assert executor[0].wait_calls[0][1].get('timeout') == 5 + assert executor[0].lithops_wait_calls[0][1].get('timeout') == 5 + + def test_join_with_a_timeout_leaves_a_running_process_alone(self, executor, redis, monkeypatch): + """ + The standard library's join(timeout) returns None once the timeout + is up, and the process carries on. FunctionExecutor.wait() took the + timeout as the end of the job instead: join() raised TimeoutError + and the call was marked failed, so the next join() had nothing left + to wait for + """ + from lithops.multiprocessing import Process + running = FakeFuture(42, running=True) + monkeypatch.setattr(FakeExecutor, 'call_async', lambda self, func, data, **kwargs: running) + proc = Process(target=_double, args=(21,)) + proc.start() + assert proc.join(timeout=5) is None + assert not running.done + assert proc.join() is None + assert running.done and not running.error + assert [kwargs['timeout'] for _, kwargs in executor[0].lithops_wait_calls] == [5, None] + + def test_join_does_not_treat_a_storage_timeout_as_finished( + self, executor, redis, monkeypatch + ): + """ + socket.timeout is a TimeoutError. join() with no timeout used to + catch it and return, as if the process had finished + """ + from lithops.multiprocessing import Process + running = FakeFuture(running=True) + monkeypatch.setattr( + FakeExecutor, 'call_async', + lambda self, func, data, **kwargs: running, + ) + proc = Process(target=_double, args=(21,)) + proc.start() + executor[0].wait_error = TimeoutError('socket timed out') + with pytest.raises(TimeoutError, match='socket timed out'): + proc.join() + assert not running.done + + def test_join_raises_what_the_target_raised(self, executor, redis, monkeypatch): + from lithops.multiprocessing import Process + failed = FakeFuture(exception=ValueError('bad input')) + monkeypatch.setattr(FakeExecutor, 'call_async', lambda self, func, data, **kwargs: failed) + proc = Process(target=_double, args=('x',)) + proc.start() + with pytest.raises(ValueError, match='bad input'): + proc.join() def test_the_unsupported_api_says_so(self, executor, redis): from lithops.multiprocessing import Process @@ -821,6 +1149,49 @@ def test_a_queue_survives_being_pickled(self, redis): assert queue.get() == 'from the worker' assert restored._maxsize == 3 + @pytest.mark.parametrize('queue_type', ['Queue', 'SimpleQueue']) + @pytest.mark.parametrize('get', [ + pytest.param(lambda q: q.get_nowait(), id='get_nowait'), + pytest.param(lambda q: q.get(timeout=0.5), id='get_with_timeout'), + ]) + def test_a_get_that_loses_the_last_item_to_another_consumer_does_not_block( + self, redis, monkeypatch, queue_type, get): + """ + Two consumers could both see the last item before either took it, + and the one that lost the race blocked in BLPOP for ever instead of + raising Empty. Here the other consumer, a worker holding a copy of + the queue, takes the item right after this one has looked + """ + import lithops.multiprocessing as mp + from queue import Empty + queue = getattr(mp, queue_type)() + in_worker = pickle.loads(pickle.dumps(queue)) + queue.put('last') + + taken_by_worker = [] + llen = redis.llen + + def worker_takes_it_after_a_look(key): + length = llen(key) + if length and not taken_by_worker: + taken_by_worker.append(in_worker.get()) + return length + + monkeypatch.setattr(redis, 'llen', worker_takes_it_after_a_look) + outcome = [] + + def consume(): + try: + outcome.append(get(queue)) + except Empty: + outcome.append(Empty) + + consumer = threading.Thread(target=consume, daemon=True) + consumer.start() + consumer.join(2) + assert not consumer.is_alive(), 'the get blocked' + assert (outcome + taken_by_worker).count('last') == 1 + class TestSimpleQueue: @@ -883,6 +1254,40 @@ def test_handle_pairs_are_two_ends_of_one_id(self): assert connection.get_subhandle(a) == b assert connection.get_subhandle(b) == a + def test_recv_bytes_within_returns_none_when_nothing_is_ready(self): + from lithops.multiprocessing.connection import _ConnectionBase + + class Conn(_ConnectionBase): + def _poll(self, timeout): + return False + + def _recv_bytes(self, maxlength=None): + raise AssertionError('must not read') + + def _close(self, _close=None): + self._handle = None + + conn = Conn(1, readable=True, writable=False) + assert conn.recv_bytes_within(0) is None + conn.close() + + def test_recv_bytes_within_reads_when_ready(self): + from lithops.multiprocessing.connection import _ConnectionBase + + class Conn(_ConnectionBase): + def _poll(self, timeout): + return True + + def _recv_bytes(self, maxlength=None): + return b'x' + + def _close(self, _close=None): + self._handle = None + + conn = Conn(1, readable=True, writable=False) + assert conn.recv_bytes_within(1) == b'x' + conn.close() + def test_an_unknown_connection_type_is_rejected(self): from lithops.multiprocessing import connection with pytest.raises(Exception, match='Unknown connection type'): @@ -962,6 +1367,38 @@ def test_closing_one_end_leaves_the_shared_client_usable(self, redis): other_left.send('still working') assert other_right.recv() == 'still working' + def test_closing_a_listener_leaves_the_shared_client_usable(self, redis): + """ + The listener closed the process-wide client as well as its own + subscription, which broke every other connection of the process + """ + from lithops.multiprocessing import Pipe + from lithops.multiprocessing.connection import Listener + left, right = Pipe() + listener = Listener(('127.0.0.1', 6000)) + listener.close() + assert redis.closed is False + left.send('still working') + assert right.recv() == 'still working' + Pipe() + + def test_the_message_list_of_a_pipe_expires(self, redis): + """ + The expiry was set once, before the first push, when the list did + not exist yet and EXPIRE does nothing: the messages of a pipe that + was dropped half read stayed in Redis for ever. Redis also deletes + the list, expiry and all, every time the reader drains it + """ + from lithops.multiprocessing import Pipe + expiry = mp_config.get_parameter(mp_config.REDIS_EXPIRY_TIME) + left, right = Pipe() + left.send('first') + assert redis.expiries.get(right._handle) == expiry + assert right.recv() == 'first' + assert right._handle not in redis.expiries + left.send('second') + assert redis.expiries.get(right._handle) == expiry + class TestSemLock: @@ -1081,6 +1518,68 @@ def test_a_condition_survives_being_pickled(self, redis): restored = pickle.loads(pickle.dumps(cond)) assert restored._notify_handle == cond._notify_handle + def test_notify_wakes_as_many_waiters_as_asked(self, redis): + """threading.Condition.notify(n) wakes up to n waiters""" + from lithops.multiprocessing import Condition + cond = Condition() + woken = [] + + def waiter(name): + with cond: + if cond.wait(timeout=5): + woken.append(name) + + waiters = [threading.Thread(target=waiter, args=(n,), daemon=True) for n in range(3)] + for thread in waiters: + thread.start() + deadline = time.monotonic() + 5 + while redis.llen(cond._notify_handle) < 3 and time.monotonic() < deadline: + time.sleep(0.01) + + with cond: + cond.notify(2) + deadline = time.monotonic() + 5 + while len(woken) < 2 and time.monotonic() < deadline: + time.sleep(0.01) + time.sleep(0.1) + assert len(woken) == 2 + + with cond: + cond.notify() + for thread in waiters: + thread.join(5) + assert sorted(woken) == [0, 1, 2] + + def test_a_timed_out_wait_does_not_consume_the_next_notify(self, redis): + """ + A waiter that gives up has to leave the notify list. The next + notify pops the oldest handle, and a dead one spends that wakeup + on a list nobody is blocked on + """ + from lithops.multiprocessing import Condition + + cond = Condition() + with cond: + assert cond.wait(timeout=0.05) is False + assert redis.llen(cond._notify_handle) == 0 + + woken = threading.Event() + + def waiter(): + with cond: + if cond.wait(timeout=2): + woken.set() + + thread = threading.Thread(target=waiter) + thread.start() + deadline = time.monotonic() + 2 + while time.monotonic() < deadline and redis.llen(cond._notify_handle) == 0: + time.sleep(0.01) + with cond: + cond.notify() + thread.join(timeout=2) + assert woken.is_set() + def _notify(cond): with cond: @@ -1192,6 +1691,39 @@ def test_the_typecode_table_covers_the_standard_codes(self): assert sharedctypes.typecode_to_type['i'] is ctypes.c_int assert sharedctypes.typecode_to_type['d'] is ctypes.c_double + def test_indexing_past_either_end_raises_index_error(self, redis): + """ + What a ctypes array raises, and what code that walks an array by + index until IndexError relies on. It used to be a TypeError from + taking the length of the nil LINDEX answers with + """ + from lithops.multiprocessing import Array, RawArray + native = (ctypes.c_int * 3)(1, 2, 3) + for shared in (RawArray('i', [1, 2, 3]), Array('i', [1, 2, 3])): + assert shared[-1] == native[-1] == 3 + for index in (3, -4): + with pytest.raises(IndexError): + native[index] + with pytest.raises(IndexError): + shared[index] + with pytest.raises(IndexError): + native[index] = 0 + with pytest.raises(IndexError): + shared[index] = 0 + with pytest.raises(IndexError): + Array('c', b'abc')[3] + + def test_a_value_in_use_keeps_its_reference_count(self, redis): + """The count lives as long as the value is written, which refreshes it""" + from lithops.multiprocessing import Value + mp_config.set_parameter(mp_config.REDIS_EXPIRY_TIME, 10) + value = Value('i', 0) + in_worker = pickle.loads(pickle.dumps(value)) + for n in range(10): + redis.advance(4) + in_worker.value = n + assert value._ref.refcount() == 2 + class TestPackageSurface: @@ -1514,6 +2046,29 @@ def test_releasing_an_rlock_that_is_not_held_raises(self, redis): with pytest.raises(AssertionError, match='not owned'): RLock().release() + def test_another_thread_cannot_reenter_an_rlock(self, redis): + """ + Re-entry is the thread that already holds the lock, not whichever + thread in the process looks at it. A second thread that walks in + shares the critical section with the holder + """ + from lithops.multiprocessing import RLock + + lock = RLock() + assert lock.acquire() is True + other = {} + + def try_acquire(): + other['got'] = lock.acquire(timeout=0.2) + + thread = threading.Thread(target=try_acquire) + thread.start() + thread.join(timeout=2) + try: + assert other['got'] is False + finally: + lock.release() + def test_a_bounded_semaphore_rejects_an_extra_release(self, redis): """ A bounded semaphore that silently swallows an over-release is not @@ -1541,6 +2096,40 @@ def test_releasing_a_lock_that_was_never_held_raises(self, redis): with pytest.raises(ValueError, match='released too many times'): Lock().release() + def test_a_released_lock_keeps_an_expiry(self, redis): + """ + Taking the only token empties the list, and Redis deletes an empty + list together with its expiry. The release pushes the token into a + new key that has none, so every lock used once stayed on the server + for ever + """ + from lithops.multiprocessing import Lock + from lithops.multiprocessing import config as mp_config + + lock = Lock() + lock.acquire() + assert lock._name not in redis.lists + lock.release() + assert redis.expiries.get(lock._name) == mp_config.get_parameter( + mp_config.REDIS_EXPIRY_TIME + ) + + def test_acquire_refreshes_the_expiry_of_a_semaphore(self, redis): + """ + A semaphore with tokens left keeps its key while some are taken. + Its expiry, set once at creation, has to move with use, or a + semaphore in use past it loses the tokens still in the list + """ + from lithops.multiprocessing import Semaphore + from lithops.multiprocessing import config as mp_config + + sem = Semaphore(2) + redis.expire(sem._name, 10) + assert sem.acquire() is True + assert redis.expiries[sem._name] == mp_config.get_parameter( + mp_config.REDIS_EXPIRY_TIME + ) + class TestBlpopTimeoutFallback: """ @@ -1988,6 +2577,38 @@ def test_multiplying_in_place(self, real_redis): proxy *= 2 assert proxy.tolist() == [1, 2, 1, 2] + def test_a_long_list_can_be_repeated_copied_and_extended_with(self, real_redis): + """ + The server-side extend unpacked every value onto the Lua stack, which + holds about 8000, so past that l *= n, copying a list and extending + one with another raised "too many results to unpack" + """ + plain = list(range(10000)) + proxy = self._list(plain) + proxy *= 2 + assert len(proxy) == 20000 + assert self._list(proxy).tolist() == plain * 2 + other = self._list([-1]) + other.extend(proxy) + assert len(other) == 20001 + assert proxy.copy_proxy()[-1] == plain[-1] + + def test_using_a_list_refreshes_its_reference_count(self, real_redis): + """ + The object's keys are refreshed on every use, and the count has to + live as long as they do: an owner going away after it had expired + took the list with it + """ + proxy = self._list([1]) + rck = proxy._ref._rck + real_redis.expire(rck, 5) + proxy.append(2) + assert real_redis.ttl(rck) > 5 + real_redis.expire(rck, 5) + proxy.insert(0, 0) + assert real_redis.ttl(rck) > 5 + assert proxy.tolist() == [0, 1, 2] + def test_a_list_built_from_another_proxy_gets_an_expiry(self, real_redis): """The Lua extend only RPUSHed, so the key never expired""" source = self._list([1, 2]) diff --git a/lithops/tests/test_standalone.py b/lithops/tests/test_standalone.py index 586db67a4..f52e22308 100644 --- a/lithops/tests/test_standalone.py +++ b/lithops/tests/test_standalone.py @@ -137,6 +137,11 @@ def test_container_runtime_detects_docker_tags(self): assert is_container_runtime('python:3.12') is True assert is_container_runtime('lithops/python:3.12') is True + def test_container_runtime_keeps_suffixed_interpreters_native(self): + for runtime in ('python3.13t', 'python3.12d', 'python3-intel64'): + assert is_container_runtime(runtime) is False, runtime + assert is_container_runtime('registry/python') is True + def test_worker_setup_script_uses_native_python(self): script = get_worker_setup_script( {'backend': 'vm', 'runtime': 'python3', 'use_gpu': False, 'vm': {}}, diff --git a/lithops/tests/test_storage_layer.py b/lithops/tests/test_storage_layer.py index 1002e9cee..57e26d4e0 100644 --- a/lithops/tests/test_storage_layer.py +++ b/lithops/tests/test_storage_layer.py @@ -264,6 +264,18 @@ def test_get_job_status_lists_per_job_when_job_ids_given(self): 'storage', f'{JOBS_PREFIX}/{create_job_key("sess-0", "M000")}' ) + def test_get_job_status_does_not_list_when_job_ids_is_empty(self): + """ + After wait() drops the finished futures the monitor stays up with + no jobs. Falling through to the executor prefix would LIST every + leftover job and the function pickle on every poll + """ + internal = _bare_internal() + running, done = internal.get_job_status('sess-0', job_ids=set()) + assert running == set() + assert done == set() + internal.storage.list_keys.assert_not_called() + def test_get_call_status_and_output_missing_are_none(self): internal = _bare_internal() internal.storage.get_object.side_effect = StorageNoSuchKeyError('b', 'k') diff --git a/lithops/tests/test_telemetry.py b/lithops/tests/test_telemetry.py index f3ef63eef..b0b49e24f 100644 --- a/lithops/tests/test_telemetry.py +++ b/lithops/tests/test_telemetry.py @@ -94,6 +94,10 @@ def _future(**attrs): runtime_memory=512, _host_status_done_tstamp=None, _status_query_count=3, + running=False, + ready=False, + success=False, + done=False, ) defaults.update(attrs) return SimpleNamespace(**defaults) @@ -788,7 +792,7 @@ def test_an_unattached_monitor_is_safe(self): ) assert monitor.telemetry is NOOP - future = MagicMock() + future = MagicMock(running=True, ready=False, success=False, done=False) monitor._mark_ready(future, {}) future._set_ready.assert_called_once() diff --git a/lithops/tests/test_worker.py b/lithops/tests/test_worker.py index b57a723dd..519316ab6 100644 --- a/lithops/tests/test_worker.py +++ b/lithops/tests/test_worker.py @@ -102,6 +102,25 @@ def _boom(x): raise ValueError('nope') +def _exits(x): + sys.exit(3) + + +def _interrupted(x): + raise KeyboardInterrupt() + + +class _UnpickleableError(Exception): + """An exception instance cloudpickle cannot round-trip""" + + def __reduce__(self): + raise TypeError('cannot pickle') + + +def _raise_unpickleable(x): + raise _UnpickleableError('lost') + + def _obj_fn(obj): return 1 @@ -452,11 +471,15 @@ def test_keeps_existing_activation_id(self, tmp_path, monkeypatch): class TestRunTask: - def _patch_run(self, task, jrp, handler_conn, stats_text=None): + def _patch_run(self, task, jrp, handler_conn, stats_text=None, + jobrunner_conn=None, status=None): + if jobrunner_conn is None: + jobrunner_conn = MagicMock() if stats_text is not None: with open(task.stats_file, 'w') as f: f.write(stats_text) - status = MagicMock() + if status is None: + status = MagicMock() cpu = {'usage': [1], 'system': 0.1, 'user': 0.2} net = {'sent': 3, 'recv': 4} mem = {'rss': 5, 'vms': 6, 'uss': 7} @@ -465,7 +488,7 @@ def _patch_run(self, task, jrp, handler_conn, stats_text=None): monitor.get_network_io.return_value = net monitor.get_memory_info.return_value = mem ctx = MagicMock() - ctx.Pipe.return_value = (handler_conn, MagicMock()) + ctx.Pipe.return_value = (handler_conn, jobrunner_conn) ctx.Process.return_value = jrp with patch('lithops.worker.handler.setup_lithops_logger'): with patch( @@ -540,11 +563,73 @@ def _run_without_completion(self, task, exitcode): conn.poll.return_value = False return self._patch_run(task, jrp, conn) - def _exc_of(self, status): + def _exc_info_of(self, status): pickled = { c.args[0]: c.args[1] for c in status.add.call_args_list }['exc_info'] - return pickle.loads(ast.literal_eval(pickled))[0] + return pickle.loads(ast.literal_eval(pickled)) + + def _exc_of(self, status): + return self._exc_info_of(status)[0] + + def test_worker_failures_carry_the_handler_marker(self, tmp_path): + """ + The client drops the traceback of an exception whose first argument + is 'HANDLER' and prints its message on one line. Without the marker + a timed out call prints a traceback into the handler instead + """ + task = _task(execution_timeout=7) + task.log_stream = MagicMock() + task.log_file = str(tmp_path / 'execution.log') + task.stats_file = str(tmp_path / 'missing.txt') + jrp = MagicMock() + jrp.is_alive.return_value = True + timeout = self._exc_info_of(self._patch_run(task, jrp, MagicMock())) + assert timeout[0] is TimeoutError + assert timeout[1].args == ( + 'HANDLER', + 'Function exceeded maximum time of 7 seconds and was killed', + ) + + exitcodes = [3] + if is_unix_system(): + exitcodes.append(-signal.SIGKILL) + for exitcode in exitcodes: + exc = self._exc_info_of( + self._run_without_completion(task, exitcode) + )[1] + assert exc.args[0] == 'HANDLER', exitcode + assert exc.args[1] == handler_module._jobrunner_death_reason( + exitcode + ) + + def test_a_failed_start_report_still_waits_for_the_function( + self, tmp_path + ): + """ + The init event is sent once the JobRunner runs. When sending it + fails, say the status object cannot be written to storage, the call + used to be reported as failed while the JobRunner kept running, + never joined, next to the following task of the worker + """ + task = _task() + task.log_stream = MagicMock() + task.log_file = str(tmp_path / 'execution.log') + task.stats_file = str(tmp_path / 'job_stats.txt') + jrp = MagicMock() + jrp.is_alive.return_value = False + conn = MagicMock() + conn.poll.return_value = True + status = MagicMock() + status.send_init_event.side_effect = OSError('No space left on device') + self._patch_run( + task, jrp, conn, 'func_result_size 0\n', status=status + ) + jrp.join.assert_called_once_with(task.execution_timeout) + added = {c.args[0]: c.args[1] for c in status.add.call_args_list} + assert 'exception' not in added + assert added['func_result_size'] == 0 + status.send_finish_event.assert_called_once() @pytest.mark.skipif( not is_unix_system(), reason='there is no SIGKILL on Windows' @@ -641,6 +726,51 @@ def test_does_not_mutate_extra_env_with_session_id(self, tmp_path): assert SESSION_ID_ENV not in extra assert 'LITHOPS_CONFIG' not in extra + def test_closes_both_ends_of_the_jobrunner_pipe(self, tmp_path): + """ + One worker process runs every call of its chunk. The pipe opened + for each JobRunner is closed when the call ends, not left to the + garbage collector + """ + task = _task() + task.log_stream = MagicMock() + task.log_file = str(tmp_path / 'execution.log') + task.stats_file = str(tmp_path / 'job_stats.txt') + (tmp_path / 'execution.log').write_bytes(b'log') + jrp = MagicMock() + jrp.is_alive.return_value = False + handler_conn = MagicMock() + handler_conn.poll.return_value = True + jobrunner_conn = MagicMock() + self._patch_run(task, jrp, handler_conn, jobrunner_conn=jobrunner_conn) + handler_conn.close.assert_called_once() + jobrunner_conn.close.assert_called_once() + + def test_closes_the_pipe_when_the_finish_event_fails(self, tmp_path): + """ + Reporting the finish goes over the network and can raise. The pipe + is closed all the same + """ + task = _task() + task.log_stream = MagicMock() + task.log_file = str(tmp_path / 'execution.log') + task.stats_file = str(tmp_path / 'job_stats.txt') + (tmp_path / 'execution.log').write_bytes(b'log') + jrp = MagicMock() + jrp.is_alive.return_value = False + handler_conn = MagicMock() + handler_conn.poll.return_value = True + jobrunner_conn = MagicMock() + status = MagicMock() + status.send_finish_event.side_effect = ConnectionError('broker gone') + with pytest.raises(ConnectionError): + self._patch_run( + task, jrp, handler_conn, + jobrunner_conn=jobrunner_conn, status=status, + ) + handler_conn.close.assert_called_once() + jobrunner_conn.close.assert_called_once() + class TestJobRunnerDeathReason: """ @@ -1227,6 +1357,47 @@ def test_run_exception_records_exc_info(self): assert 'exc_info' in text jr.jobrunner_conn.send.assert_called_with('Finished') + def _reported_exception(self): + stats = {} + for line in open(self.stats).read().splitlines(): + key, value = line.split(' ', 1) + stats[key] = value + assert stats.get('exception') == 'True' + return pickle.loads(ast.literal_eval(stats['exc_info']))[1] + + def test_sys_exit_in_the_function_is_reported_as_its_exception(self): + """ + A SystemExit used to escape run(): the call was reported as done + with no func_result_size, and the client crashed on a KeyError + instead of re-raising what the function did + """ + jr = self._runner(_exits, {'x': 1}) + jr.run() + exc = self._reported_exception() + assert isinstance(exc, SystemExit) + assert exc.args == (3,) + jr.jobrunner_conn.send.assert_called_with('Finished') + + def test_keyboard_interrupt_in_the_function_is_reported(self): + jr = self._runner(_interrupted, {'x': 1}) + jr.run() + assert isinstance(self._reported_exception(), KeyboardInterrupt) + jr.jobrunner_conn.send.assert_called_with('Finished') + + def test_an_unpickleable_exception_is_still_reported(self): + """ + The fallback for an exception that will not pickle has to pickle. + Putting the traceback object in that payload raises again, run() + dies, and the call is reported as a success with no result + """ + jr = self._runner(_raise_unpickleable, {'x': 1}) + jr.run() + text = open(self.stats).read() + assert 'exception True' in text + assert 'exc_pickle_fail True' in text + assert 'exc_info' in text + jr.jobrunner_conn.send.assert_called_with('Finished') + def test_fill_optional_args_id_and_storage(self): jr = self._runner(_echo, {'x': 1}, call_id='00007') data = {'x': 1} diff --git a/lithops/worker/handler.py b/lithops/worker/handler.py index c3d66df03..661c4b69b 100644 --- a/lithops/worker/handler.py +++ b/lithops/worker/handler.py @@ -514,6 +514,8 @@ def run_task(task: SimpleNamespace) -> None: ) job_interrupted = False + handler_conn = None + jobrunner_conn = None try: handler_conn, jobrunner_conn = _MP_CTX.Pipe() @@ -538,8 +540,14 @@ def run_task(task: SimpleNamespace) -> None: # keeps the one-off cost of opening the monitoring client off the # critical path: the first call of a worker pays for a connection # (some 13 ms for AMQP, then kept for the whole process) while the - # function is already running, instead of delaying its start - call_status.send_init_event() + # function is already running, instead of delaying its start. + # The event is informational and the finish event reports the call + # all the same, so failing to send it must not abandon a JobRunner + # that is already running + try: + call_status.send_init_event() + except Exception as e: + logger.warning(f'Could not report the start of the call: {e}') jrp.join(task.execution_timeout) sys_monitor.stop() @@ -555,6 +563,7 @@ def run_task(task: SimpleNamespace) -> None: # cannot be terminated. It is left behind on purpose pass raise TimeoutError( + 'HANDLER', f'Function exceeded maximum time of {task.execution_timeout} ' f'seconds and was killed' ) @@ -573,8 +582,8 @@ def run_task(task: SimpleNamespace) -> None: f'process, which exited with code {exitcode}: {reason}' ) if _SIGKILL is not None and exitcode == -_SIGKILL: - raise MemoryError(reason) - raise RuntimeError(reason) + raise MemoryError('HANDLER', reason) + raise RuntimeError('HANDLER', reason) _add_task_stats(call_status, task.stats_file) @@ -589,10 +598,24 @@ def run_task(task: SimpleNamespace) -> None: for key in injected_env: os.environ.pop(key, None) - # An interrupted job is not reported: the client is gone anyway - if not job_interrupted: - call_status.add('worker_end_tstamp', time.time()) - _add_logs(call_status, task) - call_status.send_finish_event() + try: + # An interrupted job is not reported: the client is gone anyway + if not job_interrupted: + call_status.add('worker_end_tstamp', time.time()) + _add_logs(call_status, task) + call_status.send_finish_event() + finally: + # One worker process runs every call of the chunk, each with a + # pipe of its own. Closed here rather than whenever the garbage + # collector reaches them, which a reference cycle can delay + for conn in (handler_conn, jobrunner_conn): + if conn is None: + continue + try: + conn.close() + except Exception: + logger.debug( + 'Could not close a JobRunner pipe', exc_info=True + ) logger.info("Finished") diff --git a/lithops/worker/jobrunner.py b/lithops/worker/jobrunner.py index 5ec190c7d..7a0dcc1ec 100644 --- a/lithops/worker/jobrunner.py +++ b/lithops/worker/jobrunner.py @@ -320,14 +320,19 @@ def _write_exception(self) -> None: except Exception as pickle_exception: # Shockingly often, modules like subprocess don't properly call # the base Exception.__init__, which results in them being - # unpickleable. Report the pieces that do pickle instead of - # losing the exception altogether + # unpickleable. The traceback object holds that same exception, + # so it does not pickle either. The text of the stack is what + # the client can keep self.stats.write("exc_pickle_fail", True) + message = str(exc_value) + frames = ''.join(traceback.format_tb(exc_traceback)) + if frames: + message = f'{message}\n{frames}' pickled_exc = pickle.dumps({ 'exc_type': str(exc_type), - 'exc_value': str(exc_value), - 'exc_traceback': exc_traceback, - 'pickle_exception': pickle_exception, + 'exc_value': message, + 'exc_traceback': None, + 'pickle_exception': str(pickle_exception), }) pickle.loads(pickled_exc) @@ -387,7 +392,11 @@ def run(self) -> None: ) pending_output = self._write_result(result) - except Exception: + except (Exception, SystemExit, KeyboardInterrupt): + # A sys.exit() or a KeyboardInterrupt raised by the function ends + # the function, not the worker, so it is reported like any other + # exception, as concurrent.futures does. Otherwise the call looks + # successful but has no result and no stats to read it from self._write_exception() finally: