From d26c948c5fa6b457b10ed8bc460c6528c01dcae6 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Tue, 20 Oct 2026 16:10:53 -0700 Subject: [PATCH 01/12] docs(microvm-worker): a throttle usually ends as unknown The docs said that a first-attempt throttle or a clock offset is the normal case for a suspend refused for now. A probe of the default client showed otherwise. 1. The default client uses botocore's standard retry mode with 3 attempts. 2. That mode retries ThrottlingException. A 429 on every attempt ends with RetryAttempts 2. 3. An error after a retry is an unknown outcome. So a throttle from the default client usually ends as unknown, with the 30-second refusal. 4. botocore retries no signature or token error, also when the server's Date header is 10 minutes ahead. These errors end with RetryAttempts 0, so they stay refused for now. The README and the docstrings now state this. The create_microvms_client doc states that a client that retries must report RetryAttempts on its error. Without it, a retried throttle counts as a first attempt. A new test pins the default client's retries for these four errors. --- .../README.md | 6 +- .../self_suspend.py | 27 ++++-- .../worker.py | 17 +++- .../tests/lifecycle_hooks_test.py | 2 +- .../tests/self_suspend_test.py | 87 +++++++++++++++++++ 5 files changed, 126 insertions(+), 13 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md index 34b927ec2..f75b541f9 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md @@ -110,14 +110,14 @@ A session's run hook payload can set `autoSuspendIdleSeconds`. The session sets 4. From the moment the idle time ends, the worker answers every job with HTTP 503 and does not start it. A job accepted then would freeze with the MicroVM, and nothing would resume it. After a 503, the durable function checks the state, resumes the MicroVM, and delivers the job again. 5. The refusal ends when the `resume` lifecycle hook arrives, or 30 seconds after the call returned, if no hook arrives. The idle time then starts again. At most one call runs at a time. A `resume` hook that arrives during the call ends the refusal at once, and the next idle time starts when the call ends. So enable the `resume` hook in the image. Without it, the first job after a resume can wait a little over 30 seconds: the 30 seconds, plus up to 4 seconds until the durable function's next delivery attempt. A test measured 32 seconds. 6. A call that the service rejected on its first attempt, such as `AccessDeniedException` for a missing permission, is logged as a warning, and the MicroVM keeps running. Missing credentials count as a rejection, because the call sends no request. The worker accepts jobs again at once and does not retry the call. The next job that ends starts the idle time again. -7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers a throttle, expired credentials, and a clock offset, whatever the HTTP status. The service answers these before it acts. The idle time then starts again, so the worker tries the call again. The JavaScript worker decides these cases by HTTP status. -8. A call whose outcome is unknown is handled like a successful call, because the service may have suspended the MicroVM anyway. This covers a timeout, a conflict, a server error, and a dropped connection. An error after botocore retried an earlier attempt also counts as unknown, because the earlier attempt may have suspended the MicroVM. botocore retries a throttle, so a throttle usually ends here. The refusal continues until the `resume` hook or the 30-second limit. The idle time then starts again, so the worker tries the call again. +7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker decides these cases by HTTP status. +8. A call whose outcome is unknown is handled like a successful call, because the service may have suspended the MicroVM anyway. This covers a timeout, a conflict, a server error, and a dropped connection. An error after botocore retried an earlier attempt also counts as unknown, because the earlier attempt may have suspended the MicroVM. The default client uses botocore's standard retry mode with 3 attempts, and that mode retries a throttle. So a throttle usually ends here. The refusal continues until the `resume` hook or the 30-second limit. The idle time then starts again, so the worker tries the call again. `worker.close()` stops the idle time. A closed worker never suspends its MicroVM again. A refusal that is already running still ends on the `resume` hook or after 30 seconds. The worker counts only jobs. It cannot see background threads or processes, or inbound traffic that is not a job. A session with such work leaves `auto_suspend_on_idle` off, and the payload then has no `autoSuspendIdleSeconds`. -The worker creates a `lambda-microvms` client for each suspend, and closes it after the call. Pass `create_microvms_client` to provide the client. The worker never closes a client that it returns. +The worker creates a `lambda-microvms` client for each suspend, and closes it after the call. Pass `create_microvms_client` to provide the client. The worker never closes a client that it returns. A client that retries must report its retries in `ResponseMetadata.RetryAttempts` of the error that it raises, as botocore does. The worker otherwise counts a retried call as a first attempt. An earlier attempt of that call may have suspended the MicroVM. So a retried throttle would count as refused for now, and the worker would accept a job that then freezes with the MicroVM. ## Suspend and terminate hooks diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py index 5da5caf7c..b77b9fb6e 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py @@ -74,8 +74,15 @@ class SuspendOutcome(Enum): """The service did nothing, and a later call would most likely fail the same way, for example for a missing permission.""" REFUSED_FOR_NOW = "refused_for_now" - """The service did nothing, and a later call can succeed: a throttle, - expired credentials, or a clock offset.""" + """The service did nothing on the call's first and only attempt, and a + later call can succeed. + + Examples are expired credentials and a signature error, with or without + a clock offset. botocore retries none of these, so they keep this + outcome. The default client retries a throttle. So a throttle usually + ends as :attr:`UNKNOWN`. A throttle has this outcome only when it + reaches the worker without a retry, for example from a caller's client + that does not retry it.""" UNKNOWN = "unknown" """The service may have suspended the MicroVM.""" @@ -93,6 +100,12 @@ def create_microvms_client(region: str) -> LambdaMicrovmsClient: Each call gets its own session, because boto3's default session is not safe to use from several threads at once. + + The client uses botocore's standard retry mode with 3 attempts. That + mode retries a throttle error code, such as ``ThrottlingException``, a + 5xx answer, and a connection error. It retries no credential or + signature error, also with a clock offset. Each error reports the + retries in ``ResponseMetadata.RetryAttempts``. """ return boto3.session.Session().client( "lambda-microvms", @@ -165,16 +178,20 @@ def classify_suspend_error(error: BaseException) -> SuspendOutcome: 1. A botocore retry inside the call means that an earlier attempt may have suspended the MicroVM before its answer was lost. So any error - after a retry is :attr:`SuspendOutcome.UNKNOWN`. + after a retry is :attr:`SuspendOutcome.UNKNOWN`. The default client + retries a throttle. So a throttle from it usually ends here. 2. Missing credentials stop the call before any request. They are :attr:`SuspendOutcome.REJECTED`, as in the JavaScript worker. 3. A known rejection code is :attr:`SuspendOutcome.REJECTED`. 4. A conflict is :attr:`SuspendOutcome.UNKNOWN`, whatever its status. It can mean that the MicroVM is already suspending. - 5. A throttle, expired credentials, or a clock offset on the first + 5. Expired credentials, a signature error, or a throttle on the first attempt is :attr:`SuspendOutcome.REFUSED_FOR_NOW`, whatever its status. The service answers them before it acts, and a later call can - succeed. Some services answer a throttle with HTTP 400. + succeed. Some services answer a throttle with HTTP 400. botocore + retries no credential or signature error, also with a clock offset. + So these errors reach this rule. A throttle reaches it only from a + client that did not retry it. 6. Any other 4xx answer except 408, 409, and 429 is :attr:`SuspendOutcome.REJECTED`. A 429 is :attr:`SuspendOutcome.REFUSED_FOR_NOW`. diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py index b2bc3a54b..df7a3828a 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py @@ -298,9 +298,12 @@ class MicrovmWorkerListener: for a missing permission, ends the refusal at once. The MicroVM keeps running, and the listener does not retry the call until a job ends. 7. A call that the service refused for now on its first attempt, such - as a throttle, expired credentials, or a clock offset, ends the - refusal at once too. The idle time then starts again, so the listener - tries the call again. + as expired credentials or a signature error, ends the refusal at + once too. The idle time then starts again, so the listener tries the + call again. The default client retries a throttle. So a throttle + from it usually ends as an unknown outcome, as in item 8. A throttle + is refused for now only from a caller's client that does not retry + it. 8. A call whose outcome is unknown, such as a timeout, a conflict, a server error, or an error after a retried attempt, is handled like a successful call. The service may have suspended the MicroVM anyway. @@ -451,7 +454,13 @@ def create( idle, once per suspend. It never closes a client that this function returns. Defaults to a client of its own per suspend, from the default credential chain. The listener - closes that client after the call. + closes that client after the call. A client that retries + must report its retries in ``ResponseMetadata.RetryAttempts`` + of the error that it raises. The listener otherwise counts a + retried call as a first attempt. An earlier attempt of that + call may have suspended the MicroVM. A retried throttle would + then count as refused for now, and the listener would accept + a job that then freezes with the MicroVM. heartbeat_interval_seconds: The heartbeat interval. Defaults to a third of the job's heartbeat timeout, at most 15 minutes. It is cut to a third of the job's heartbeat timeout. diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index 5227a7665..1d5f4a838 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -914,7 +914,7 @@ def test_accepts_jobs_at_once_after_a_rejection( suspend_error("ExpiredTokenException", 403), suspend_error("SignatureDoesNotMatch", 403), ], - ids=["throttle", "throttle-400", "expired-token", "clock-offset"], + ids=["throttle", "throttle-400", "expired-token", "signature-error"], ) def test_accepts_jobs_at_once_and_retries_after_a_refusal_for_now( start: Any, logger: Any, failure: BaseException diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/self_suspend_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/self_suspend_test.py index 77b5f12aa..671e89137 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/self_suspend_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/self_suspend_test.py @@ -5,21 +5,25 @@ from __future__ import annotations +import json import socket import threading import time +from email.utils import formatdate from typing import Any from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer import boto3 import pytest +from botocore.awsrequest import AWSResponse, HTTPHeaders from botocore.config import Config from botocore.exceptions import ( ClientError, EndpointConnectionError, NoCredentialsError, ) +from botocore.retries.standard import ExponentialBackoff from aws_durable_execution_sdk_python_microvm_worker.self_suspend import ( SUSPEND_CALL_TIMEOUT_SECONDS, @@ -170,6 +174,89 @@ def test_the_default_client_ends_a_read_at_the_call_timeout() -> None: client.close() +class _Body: + def __init__(self, data: bytes) -> None: + self._data = data + + def stream(self, **_: Any) -> Any: + yield self._data + + +def _answer_every_attempt( + client: Any, status: int, code: str, **headers: str +) -> list[int]: + """Answer each attempt of the client with one error, instead of HTTP. + + botocore's retry handler still runs on each answer, because a + ``before-send`` handler replaces only the send. Returns the attempt + list, which grows by one per attempt. + """ + attempts: list[int] = [] + answer_headers = HTTPHeaders() + answer_headers["Content-Type"] = "application/json" + answer_headers["x-amzn-ErrorType"] = code + for name, value in headers.items(): + answer_headers[name] = value + + def send(**_: Any) -> AWSResponse: + attempts.append(1) + return AWSResponse( + "https://lambda-microvms.us-east-1.amazonaws.com", + status, + answer_headers, + _Body(json.dumps({"message": f"{code} message"}).encode()), + ) + + client.meta.events.register("before-send.lambda-microvms.SuspendMicrovm", send) + return attempts + + +@pytest.mark.parametrize( + ("status", "code", "headers", "attempts", "outcome"), + [ + # A throttle is retried. So its error reports 2 retries, and an + # earlier attempt may have reached the service. + (429, "ThrottlingException", {}, 3, SuspendOutcome.UNKNOWN), + # A signature error with a clock offset is not retried. botocore does + # not correct the clock from the server's Date header. + ( + 403, + "InvalidSignatureException", + {"Date": formatdate(time.time() + 600, usegmt=True)}, + 1, + SuspendOutcome.REFUSED_FOR_NOW, + ), + (403, "InvalidSignatureException", {}, 1, SuspendOutcome.REFUSED_FOR_NOW), + (403, "ExpiredTokenException", {}, 1, SuspendOutcome.REFUSED_FOR_NOW), + ], + ids=["throttle", "signature-clock-offset", "signature-mismatch", "expired-token"], +) +def test_the_default_client_retries_a_throttle_and_no_signature_or_token_error( + credentials: None, + monkeypatch: pytest.MonkeyPatch, + status: int, + code: str, + headers: dict[str, str], + attempts: int, + outcome: SuspendOutcome, +) -> None: + # No backoff, so that the retries do not slow the test. + monkeypatch.setattr(ExponentialBackoff, "delay_amount", lambda self, context: 0) + client = create_microvms_client("us-east-1") + try: + sent = _answer_every_attempt(client, status, code, **headers) + + with pytest.raises(ClientError) as raised: + suspend_microvm(client, "mvm-1", 5.0) + + assert len(sent) == attempts + metadata = raised.value.response["ResponseMetadata"] + assert metadata["RetryAttempts"] == attempts - 1 + assert classify_suspend_error(raised.value) is outcome + finally: + client.close() + + class _SilentService: """A local HTTP service that accepts connections and never answers, and records when each attempt arrives.""" From f65bc38edbbfdde9e65c26784a7cf461c89ea477 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Tue, 20 Oct 2026 16:26:21 -0700 Subject: [PATCH 02/12] fix(microvm-worker): wait at least 30 s after a suspend refused for now After a suspend refused for now, the worker started the idle time again at once. Some of these errors repeat on every call. A wrong secret key gives a signature error on every call. A static session token gives ExpiredTokenException on every call after it expires. So an idle MicroVM made one SuspendMicrovm call per idle time, without a bound. With a 0.0001-second idle time, a probe counted 15 calls and 30 log lines in 3 seconds. The restart after a refusal for now now waits max(idle time, 30 s). The 30 s is SUSPEND_GRACE_SECONDS. The probe now counts 1 call in 3 seconds for each idle time. 1. The refused branch asks for the idle time with after_refusal=True. 2. The call is still counted as running at that point. So the request waits in _idle_after_call, and _idle_after_call_floor records the floor. 3. Each later request during the same call overwrites the floor. So the latest request decides. 4. A resume hook during the call comes before the refused outcome. So the floor applies. A job that ends after the outcome writes False. So the normal idle time applies. 5. Every other start, such as a job end or a resume hook after the refusal, uses the normal idle time. The warning is still logged once per refused call. The JavaScript worker (#1040) is being changed to the same rule. --- .../README.md | 2 +- .../worker.py | 51 +++++-- .../tests/lifecycle_hooks_test.py | 142 +++++++++++++++++- 3 files changed, 176 insertions(+), 19 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md index f75b541f9..7b24951ac 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md @@ -110,7 +110,7 @@ A session's run hook payload can set `autoSuspendIdleSeconds`. The session sets 4. From the moment the idle time ends, the worker answers every job with HTTP 503 and does not start it. A job accepted then would freeze with the MicroVM, and nothing would resume it. After a 503, the durable function checks the state, resumes the MicroVM, and delivers the job again. 5. The refusal ends when the `resume` lifecycle hook arrives, or 30 seconds after the call returned, if no hook arrives. The idle time then starts again. At most one call runs at a time. A `resume` hook that arrives during the call ends the refusal at once, and the next idle time starts when the call ends. So enable the `resume` hook in the image. Without it, the first job after a resume can wait a little over 30 seconds: the 30 seconds, plus up to 4 seconds until the durable function's next delivery attempt. A test measured 32 seconds. 6. A call that the service rejected on its first attempt, such as `AccessDeniedException` for a missing permission, is logged as a warning, and the MicroVM keeps running. Missing credentials count as a rejection, because the call sends no request. The worker accepts jobs again at once and does not retry the call. The next job that ends starts the idle time again. -7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker decides these cases by HTTP status. +7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. That idle time lasts at least 30 seconds, also when `autoSuspendIdleSeconds` is shorter. The same error can repeat on every call, for example with a wrong secret key or an expired session token from environment variables. So the worker makes at most one call per 30 seconds while the error lasts, and logs one warning per call. A job that ends after the refusal, or a `resume` hook after it, starts the normal idle time instead. A `resume` hook during the call does not, because the refused outcome arrives after the hook. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker decides these cases by HTTP status. 8. A call whose outcome is unknown is handled like a successful call, because the service may have suspended the MicroVM anyway. This covers a timeout, a conflict, a server error, and a dropped connection. An error after botocore retried an earlier attempt also counts as unknown, because the earlier attempt may have suspended the MicroVM. The default client uses botocore's standard retry mode with 3 attempts, and that mode retries a throttle. So a throttle usually ends here. The refusal continues until the `resume` hook or the 30-second limit. The idle time then starts again, so the worker tries the call again. `worker.close()` stops the idle time. A closed worker never suspends its MicroVM again. A refusal that is already running still ends on the `resume` hook or after 30 seconds. diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py index df7a3828a..da1d6fa65 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py @@ -300,10 +300,14 @@ class MicrovmWorkerListener: 7. A call that the service refused for now on its first attempt, such as expired credentials or a signature error, ends the refusal at once too. The idle time then starts again, so the listener tries the - call again. The default client retries a throttle. So a throttle - from it usually ends as an unknown outcome, as in item 8. A throttle - is refused for now only from a caller's client that does not retry - it. + call again. That idle time lasts at least 30 seconds, because the + same error can repeat on every call, for example with a wrong secret + key. A job that ends after the refusal, or a ``resume`` hook after + it, starts the normal idle time instead. A ``resume`` hook during the + call does not, because the refused outcome arrives after the hook. + The default client retries a throttle. So a throttle from it usually + ends as an unknown outcome, as in item 8. A throttle is refused for + now only from a caller's client that does not retry it. 8. A call whose outcome is unknown, such as a timeout, a conflict, a server error, or an error after a retried attempt, is handled like a successful call. The service may have suspended the MicroVM anyway. @@ -410,6 +414,12 @@ def __init__( # flight, for example after a resume hook during the call. The idle # time then starts when the call ends. self._idle_after_call = False + # Written each time _idle_after_call is set, and read when the call + # ends. True when the latest request to start the idle time during + # the call came from a call refused for now. That idle time then + # lasts at least SUSPEND_GRACE_SECONDS. A later request during the + # same call, such as a job that ends, writes False. + self._idle_after_call_floor = False # Run hook jobs that arrived during a refusal. The durable function # cannot deliver a run hook job again. So the listener starts it when # the refusal ends, instead of refusing it. @@ -1293,9 +1303,16 @@ def _reporter_for(self, callback_id: str, region: str) -> CallbackReporter: callback_id, self._create_client(region), logger=self._logger ) - def _start_idle_time(self) -> None: + def _start_idle_time(self, *, after_refusal: bool = False) -> None: """Start the idle time, when the session asked for it and no job runs. + ``after_refusal`` marks the restart after a call refused for now. + That idle time lasts at least :data:`SUSPEND_GRACE_SECONDS`. A + persistent error, such as a wrong secret key, is refused for now on + every call. Without the floor, a tiny idle time would repeat the + call as fast as the client can make it. Every other start uses the + session's idle time. + The caller holds the lock. """ self._stop_idle_time() @@ -1311,13 +1328,18 @@ def _start_idle_time(self) -> None: if self._suspend_calls: # A second call could start while the first one runs. The first # call's grace period could then end the refusal while the second - # call can still freeze the MicroVM. + # call can still freeze the MicroVM. The latest request decides + # the floor. self._idle_after_call = True + self._idle_after_call_floor = after_refusal return + idle_seconds = auto_suspend.idle_seconds + if after_refusal: + idle_seconds = max(idle_seconds, SUSPEND_GRACE_SECONDS) generation = self._idle_generation try: self._cancel_idle_timer = _start_timer( - auto_suspend.idle_seconds, lambda: self._idle_time_ended(generation) + idle_seconds, lambda: self._idle_time_ended(generation) ) except Exception as error: # noqa: BLE001 # Without a timer thread, the MicroVM keeps running until a job @@ -1396,12 +1418,12 @@ def _end_own_refusal( def _suspend_call_ended(self) -> None: """Count a SuspendMicrovm call as ended, and start the idle time that - a resume hook or a job asked for during it. The caller holds the - lock.""" + a resume hook, a job, or a refusal for now asked for during it. The + caller holds the lock.""" self._suspend_calls -= 1 if self._idle_after_call: self._idle_after_call = False - self._start_idle_time() + self._start_idle_time(after_refusal=self._idle_after_call_floor) self._changed.notify_all() def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: @@ -1448,7 +1470,8 @@ def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: self._logger.warning( "could not suspend the idle MicroVM, because the " "service refused the call for now. It keeps running, " - "and the worker tries again after the next idle time.", + "and the worker tries again after the next idle time, " + "at least 30 seconds.", extra={**fields, "error": describe(error)}, ) # The service did nothing. So jobs can run again at once. A @@ -1460,9 +1483,11 @@ def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: deferred = self._stop_refusing() # A rejection, such as a missing permission, is not # retried until a job ends. A refusal for now is - # retried after the next idle time. + # retried after the next idle time. That idle time + # lasts at least 30 seconds, because the same error + # can repeat on every call. if outcome is SuspendOutcome.REFUSED_FOR_NOW: - self._start_idle_time() + self._start_idle_time(after_refusal=True) self._launch_deferred(deferred) return # A timeout, a conflict, a server error, or an error after a diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index 1d5f4a838..e37236b6b 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -934,21 +934,153 @@ def test_accepts_jobs_at_once_and_retries_after_a_refusal_for_now( assert h.microvms.suspended == ["mvm-1", "mvm-1"] -def test_retries_a_refusal_for_now_one_idle_time_later_without_a_job( +@pytest.mark.parametrize( + ("idle", "wait"), + [(1.0, GRACE), (IDLE, GRACE), (45.0, 45.0)], + ids=["idle-1s", "idle-10s", "idle-45s"], +) +def test_retries_a_refusal_for_now_after_the_idle_time_or_30_seconds_if_longer( + start: Any, logger: Any, idle: float, wait: float +) -> None: + # A wrong secret key gives the same error on every call. Without the + # floor, a 1-second idle time made one call per second. + h = start() + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + + h.run_hook(idle) + h.advance(idle) + assert h.microvms.suspended == ["mvm-1"] + assert h.job("cb-1") == 202 + h.finish_job("cb-1") + # The job restarted the normal idle time. So the next call comes one + # idle time after it, and the floor applies to the restart after it. + h.advance(idle) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + + h.advance(wait - 0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1", "mvm-1"] + # One warning per refusal. + refusals = [m for m in logger.messages("warning") if "for now" in m] + assert len(refusals) == 3 + + +def test_makes_one_call_per_30_seconds_while_a_refusal_for_now_persists( start: Any, ) -> None: h = start() - h.microvms.failure = suspend_error("ThrottlingException", 429) + h.microvms.failure = suspend_error("ExpiredTokenException", 403) - h.run_hook(IDLE) - h.advance(IDLE) - h.advance(IDLE - 0.001) + h.run_hook(1.0) + h.advance(1.0) + for _ in range(4): + h.advance(GRACE) + + assert h.microvms.suspended == ["mvm-1"] * 5 + + +def test_a_job_that_ends_after_a_refusal_for_now_restarts_the_normal_idle_time( + start: Any, +) -> None: + h = start() + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + + h.run_hook(1.0) + h.advance(1.0) + h.advance(5.0) + assert h.job("cb-1") == 202 + h.finish_job("cb-1") + h.advance(1.0 - 0.001) + assert h.microvms.suspended == ["mvm-1"] + + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + + +def test_a_resume_hook_after_a_refusal_for_now_restarts_the_normal_idle_time( + start: Any, +) -> None: + h = start() + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + + h.run_hook(1.0) + h.advance(1.0) + h.advance(5.0) + assert h.hook("resume") == 200 + h.advance(1.0 - 0.001) assert h.microvms.suspended == ["mvm-1"] h.advance(0.001) assert h.microvms.suspended == ["mvm-1", "mvm-1"] +def test_waits_30_seconds_after_a_refusal_for_now_that_follows_a_resume_hook( + start: Any, +) -> None: + # The resume hook asks for the idle time while the call runs. The call + # then ends refused for now. That outcome is the later request, so the + # floor applies. + h = start() + h.microvms.hold = True + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + + h.run_hook(1.0) + h.advance(1.0) + assert eventually(lambda: h.microvms.suspended == ["mvm-1"]) + assert h.hook("resume") == 200 + h.microvms.hold = False + h.microvms.finish() + h.settle() + h.advance(GRACE - 0.001) + assert h.microvms.suspended == ["mvm-1"] + + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + + +class _ClosingClient(FakeMicrovmsClient): + """A default client whose ``close()`` waits until the test releases it. + + The call is still counted as running during ``close()``. So a request to + start the idle time then waits for the call to end. + """ + + def __init__(self) -> None: + super().__init__() + self.closing = threading.Event() + self.release_close = threading.Event() + + def close(self) -> None: + self.closing.set() + self.release_close.wait(WAIT) + super().close() + + +def test_a_job_that_ends_before_a_refused_call_has_ended_uses_the_normal_idle_time( + start: Any, monkeypatch: pytest.MonkeyPatch +) -> None: + client = _ClosingClient() + client.failure = suspend_error("InvalidSignatureException", 403) + monkeypatch.setattr(worker_module, "create_microvms_client", lambda r: client) + h = start(create_microvms_client=None) + + h.run_hook(1.0) + h.timers.advance(1.0) + # The refusal has ended. The call is still closing its client. + assert client.closing.wait(WAIT) + assert h.job("cb-1") == 202 + h.finish_job("cb-1") + client.release_close.set() + h.settle() + + # The job ended after the refusal. So the normal idle time applies. + h.advance(1.0 - 0.001) + assert client.suspended == ["mvm-1"] + h.advance(0.001) + assert client.suspended == ["mvm-1", "mvm-1"] + + def test_keeps_a_hook_refusal_after_a_refusal_for_now_of_the_own_call( start: Any, ) -> None: From 3317c844cd0b570ecdc951b58ff182ae7b13f0d8 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Tue, 20 Oct 2026 19:14:36 -0700 Subject: [PATCH 03/12] fix(microvm-worker): state the real wait after a refusal The warning for a suspend refused for now said that the worker tries again after the next idle time, "at least 30 seconds". That promise was false in two cases. 1. A suspend hook can arrive during the call. The hook's refusal of jobs then stays, and the worker sets no 30-second floor. The worker still logged the same warning. 2. A job that ends after the refusal, or a resume hook after it, starts the normal idle time. So the next call can come sooner than 30 s. The worker now checks the suspend hook count first, and then logs one of two warnings. - Without a suspend hook during the call, the warning says that the next idle time lasts at least 30 seconds, unless a job or a resume hook starts the idle time again. - With a suspend hook during the call, the warning says that the hook's refusal stays. That refusal ends when the resume hook arrives, or 30 seconds after the suspend hook. The idle time then starts again. The tests now assert both texts in full. The JavaScript worker (#1040) is being changed to the same wording. --- .../worker.py | 35 ++++++++++++++----- .../tests/lifecycle_hooks_test.py | 16 +++++++-- 2 files changed, 40 insertions(+), 11 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py index da1d6fa65..0a688b5ec 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py @@ -1466,20 +1466,13 @@ def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: "MicroVM image in its execution role.", extra={**fields, "error": describe(error)}, ) - else: - self._logger.warning( - "could not suspend the idle MicroVM, because the " - "service refused the call for now. It keeps running, " - "and the worker tries again after the next idle time, " - "at least 30 seconds.", - extra={**fields, "error": describe(error)}, - ) # The service did nothing. So jobs can run again at once. A # suspend hook that arrived since the idle time ended means # that the MicroVM is suspending anyway, so its refusal stays. with self._lock: deferred = [] - if self._suspend_hooks == hooks_before: + hook_arrived = self._suspend_hooks != hooks_before + if not hook_arrived: deferred = self._stop_refusing() # A rejection, such as a missing permission, is not # retried until a job ends. A refusal for now is @@ -1488,6 +1481,30 @@ def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: # can repeat on every call. if outcome is SuspendOutcome.REFUSED_FOR_NOW: self._start_idle_time(after_refusal=True) + if outcome is SuspendOutcome.REFUSED_FOR_NOW: + if hook_arrived: + # The hook's refusal stays, so no 30-second floor + # applies. The idle time starts when that refusal + # ends. + self._logger.warning( + "could not suspend the idle MicroVM, because the " + "service refused the call for now. A suspend hook " + "arrived during the call, so its refusal of jobs " + "stays. That refusal ends when the resume hook " + "arrives, or 30 seconds after the suspend hook. " + "The idle time then starts again.", + extra={**fields, "error": describe(error)}, + ) + else: + self._logger.warning( + "could not suspend the idle MicroVM, because the " + "service refused the call for now. It keeps " + "running, and the worker tries again after the " + "next idle time. That idle time lasts at least 30 " + "seconds, unless a job or a resume hook starts the " + "idle time again.", + extra={**fields, "error": describe(error)}, + ) self._launch_deferred(deferred) return # A timeout, a conflict, a server error, or an error after a diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index e37236b6b..3a734e31b 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -924,7 +924,12 @@ def test_accepts_jobs_at_once_and_retries_after_a_refusal_for_now( h.run_hook(IDLE) h.advance(IDLE) - assert "refused the call for now" in logger.messages("warning")[0] + assert logger.messages("warning")[0] == ( + "could not suspend the idle MicroVM, because the service refused the " + "call for now. It keeps running, and the worker tries again after the " + "next idle time. That idle time lasts at least 30 seconds, unless a job " + "or a resume hook starts the idle time again." + ) assert h.job("cb-1") == 202 h.finish_job("cb-1") @@ -1082,7 +1087,7 @@ def test_a_job_that_ends_before_a_refused_call_has_ended_uses_the_normal_idle_ti def test_keeps_a_hook_refusal_after_a_refusal_for_now_of_the_own_call( - start: Any, + start: Any, logger: Any ) -> None: h = start() h.microvms.hold = True @@ -1096,6 +1101,13 @@ def test_keeps_a_hook_refusal_after_a_refusal_for_now_of_the_own_call( h.settle() assert h.job("cb-1") == 503 + # No 30-second floor applies, so the warning does not promise one. + assert logger.messages("warning") == [ + "could not suspend the idle MicroVM, because the service refused the " + "call for now. A suspend hook arrived during the call, so its refusal " + "of jobs stays. That refusal ends when the resume hook arrives, or 30 " + "seconds after the suspend hook. The idle time then starts again." + ] def test_keeps_refusing_jobs_until_a_call_past_its_deadline_has_ended( From b06e181065e7f30f2935c3a54a211ac158e3cf5d Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Tue, 20 Oct 2026 19:14:45 -0700 Subject: [PATCH 04/12] test(microvm-worker): cover a job during a refused call Two paths had no test. A probe in review showed the right behavior for both. 1. A resume hook arrives during the call, and a job starts. The call ends refused for now while the job runs. The job ends after the call. The worker makes no call while the job runs. It makes one call one normal idle time after the job ends. 2. A resume hook arrives during the call. A job starts and ends during the call. The call then ends refused for now. The refused outcome is the later request to start the idle time. So the 30-second floor applies. --- .../tests/lifecycle_hooks_test.py | 56 +++++++++++++++++++ 1 file changed, 56 insertions(+) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index 3a734e31b..648b8d9c3 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -1044,6 +1044,62 @@ def test_waits_30_seconds_after_a_refusal_for_now_that_follows_a_resume_hook( assert h.microvms.suspended == ["mvm-1", "mvm-1"] +def test_uses_the_normal_idle_time_after_a_job_that_ran_across_the_refused_call( + start: Any, +) -> None: + # A resume hook during the call lets a job start. The call ends refused + # for now while the job runs. The job ends after the call. So the job's + # end is the latest restart, and the normal idle time applies. + h = start() + h.microvms.hold = True + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + + h.run_hook(1.0) + h.advance(1.0) + assert eventually(lambda: h.microvms.suspended == ["mvm-1"]) + assert h.hook("resume") == 200 + assert h.job("cb-1") == 202 + assert eventually(lambda: h.started("cb-1")) + h.microvms.hold = False + h.microvms.finish() + h.settle() + + # No call while the job runs. + h.advance(GRACE * 2) + assert h.microvms.suspended == ["mvm-1"] + + h.finish_job("cb-1") + h.advance(1.0 - 0.001) + assert h.microvms.suspended == ["mvm-1"] + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + + +def test_waits_30_seconds_after_a_refusal_for_now_that_follows_a_job_end( + start: Any, +) -> None: + # A job starts and ends during the call. The call then ends refused for + # now. That outcome is the later request, so the floor applies. + h = start() + h.microvms.hold = True + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + + h.run_hook(1.0) + h.advance(1.0) + assert eventually(lambda: h.microvms.suspended == ["mvm-1"]) + assert h.hook("resume") == 200 + assert h.job("cb-1") == 202 + h.finish_job("cb-1") + h.microvms.hold = False + h.microvms.finish() + h.settle() + h.advance(GRACE - 0.001) + assert h.microvms.suspended == ["mvm-1"] + + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + + class _ClosingClient(FakeMicrovmsClient): """A default client whose ``close()`` waits until the test releases it. From 8ed63d31e6b7cfd18a74e73c706a5f1a5f603eee Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Tue, 20 Oct 2026 19:14:45 -0700 Subject: [PATCH 05/12] docs(microvm-worker): correct the refused-for-now notes 1. README item 7 said that the JavaScript worker decides these cases by HTTP status. The JavaScript worker checks the error name first, as this worker does. The two differ in the default client. The JavaScript client retries a clock-skew error. So there, a clock-skew error usually ends as an unknown outcome. 2. README item 7 said that the worker makes at most one call per 30 seconds while the error lasts. A job that ends restarts the normal idle time. So the limit holds only while no job ends and no lifecycle hook arrives. The sentence now states that condition. 3. README item 7 said that only a resume hook during the call keeps the floor. A job that ends during the call keeps it too, because the refused outcome arrives after the job's end. The sentence now names both. 4. The create_microvms_client docstring said that each error reports its retries in ResponseMetadata.RetryAttempts. Only a ClientError carries ResponseMetadata. The docstring now says ClientError. --- .../aws-durable-execution-sdk-python-microvm-worker/README.md | 2 +- .../self_suspend.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md index 7b24951ac..d0c0383e2 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md @@ -110,7 +110,7 @@ A session's run hook payload can set `autoSuspendIdleSeconds`. The session sets 4. From the moment the idle time ends, the worker answers every job with HTTP 503 and does not start it. A job accepted then would freeze with the MicroVM, and nothing would resume it. After a 503, the durable function checks the state, resumes the MicroVM, and delivers the job again. 5. The refusal ends when the `resume` lifecycle hook arrives, or 30 seconds after the call returned, if no hook arrives. The idle time then starts again. At most one call runs at a time. A `resume` hook that arrives during the call ends the refusal at once, and the next idle time starts when the call ends. So enable the `resume` hook in the image. Without it, the first job after a resume can wait a little over 30 seconds: the 30 seconds, plus up to 4 seconds until the durable function's next delivery attempt. A test measured 32 seconds. 6. A call that the service rejected on its first attempt, such as `AccessDeniedException` for a missing permission, is logged as a warning, and the MicroVM keeps running. Missing credentials count as a rejection, because the call sends no request. The worker accepts jobs again at once and does not retry the call. The next job that ends starts the idle time again. -7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. That idle time lasts at least 30 seconds, also when `autoSuspendIdleSeconds` is shorter. The same error can repeat on every call, for example with a wrong secret key or an expired session token from environment variables. So the worker makes at most one call per 30 seconds while the error lasts, and logs one warning per call. A job that ends after the refusal, or a `resume` hook after it, starts the normal idle time instead. A `resume` hook during the call does not, because the refused outcome arrives after the hook. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker decides these cases by HTTP status. +7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. That idle time lasts at least 30 seconds, also when `autoSuspendIdleSeconds` is shorter. The same error can repeat on every call, for example with a wrong secret key or an expired session token from environment variables. So while no job ends and no lifecycle hook arrives, the worker makes at most one call per 30 seconds, and logs one warning per call. A job that ends after the refusal, or a `resume` hook after it, starts the normal idle time instead. A `resume` hook or a job that ends during the call does not shorten the idle time after the refusal, because the refused outcome arrives after it. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker classifies these errors the same way. Its default client retries a clock-skew error. So there, a clock-skew error usually ends as an unknown outcome. 8. A call whose outcome is unknown is handled like a successful call, because the service may have suspended the MicroVM anyway. This covers a timeout, a conflict, a server error, and a dropped connection. An error after botocore retried an earlier attempt also counts as unknown, because the earlier attempt may have suspended the MicroVM. The default client uses botocore's standard retry mode with 3 attempts, and that mode retries a throttle. So a throttle usually ends here. The refusal continues until the `resume` hook or the 30-second limit. The idle time then starts again, so the worker tries the call again. `worker.close()` stops the idle time. A closed worker never suspends its MicroVM again. A refusal that is already running still ends on the `resume` hook or after 30 seconds. diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py index b77b9fb6e..6bb5d8b88 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py @@ -104,7 +104,7 @@ def create_microvms_client(region: str) -> LambdaMicrovmsClient: The client uses botocore's standard retry mode with 3 attempts. That mode retries a throttle error code, such as ``ThrottlingException``, a 5xx answer, and a connection error. It retries no credential or - signature error, also with a clock offset. Each error reports the + signature error, also with a clock offset. Each ``ClientError`` reports the retries in ``ResponseMetadata.RetryAttempts``. """ return boto3.session.Session().client( From 020d68ba96d65bbfdc5ac13a84283899ff700664 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Tue, 20 Oct 2026 19:28:19 -0700 Subject: [PATCH 06/12] docs(microvm-worker): name a job end in the listener Item 7 of the listener docstring named only a resume hook during the refused call. The README also names a job that ends during the call. Both keep the 30-second wait, because the refused outcome arrives after them. So the docstring now names both. --- .../worker.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py index 0a688b5ec..3f16d1af1 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py @@ -303,8 +303,9 @@ class MicrovmWorkerListener: call again. That idle time lasts at least 30 seconds, because the same error can repeat on every call, for example with a wrong secret key. A job that ends after the refusal, or a ``resume`` hook after - it, starts the normal idle time instead. A ``resume`` hook during the - call does not, because the refused outcome arrives after the hook. + it, starts the normal idle time instead. A ``resume`` hook or a job + that ends during the call does not, because the refused outcome + arrives after it. The default client retries a throttle. So a throttle from it usually ends as an unknown outcome, as in item 8. A throttle is refused for now only from a caller's client that does not retry it. From 833b32ae54f1894374a4c21afac00d18509b36de Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Wed, 21 Oct 2026 21:57:28 -0700 Subject: [PATCH 07/12] test(microvm-worker): wait for the lock in settle The settle helper waited until no SuspendMicrovm call ran. It read the call count without the listener lock. 1. The call's thread lowers the count and then starts the idle time. Both steps run in one locked block. 2. So a reader without the lock can see the lower count before the idle timer exists. 3. settle then returned. The next advance moved the fake clock first. 4. A timer created after that move was due later by the amount of the move. So a test could see no call where it expected one. A 20 ms sleep between the two steps made 14 tests fail. settle now takes the listener lock after its wait, as finish_job does. With the same sleep, every test passes. --- .../tests/lifecycle_hooks_test.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index 648b8d9c3..fc4e6d71b 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -416,6 +416,12 @@ def finish_job(self, callback_id: str) -> None: def settle(self) -> None: """Wait until no SuspendMicrovm call runs.""" assert eventually(lambda: self.listener._suspend_calls == 0) # noqa: SLF001 + # The call's thread lowers the count and starts the idle time in one + # locked block. The check above reads without the lock, so it can see + # the lower count first. Taking the lock waits for the rest of the + # block. + with self.listener._lock: # noqa: SLF001 + pass def advance(self, seconds: float) -> None: """Advance the clock, and let a suspend call that it started end.""" From dadacce7c8df98cb984bbae1eccc22c028e79c25 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Wed, 21 Oct 2026 21:57:54 -0700 Subject: [PATCH 08/12] fix(microvm-worker): match the JS suspend warnings The worker logs a warning when its own SuspendMicrovm call fails. The service can reject the call, refuse it for now, or leave its outcome unknown. Some of these texts were false in rare sequences. 1. A suspend hook can arrive during the call, and its refusal can end before the call ends. A resume hook ends it, or its 30 seconds end. A refusal for now still logged that the hook's refusal stays. Jobs got HTTP 202. 2. A suspend hook alone can arrive during a rejected call. Its refusal then stays. The rejection still logged "It keeps running". Jobs got HTTP 503. 3. A terminate hook can arrive during the call. The worker then never calls again, and it refuses jobs for good. Each of the three texts still said that the worker goes on as before. 4. close() can come during the call. The worker then never calls again. The refusal for now still logged that it tries again. A new function _failed_call_warning chooses the text. Its conditions, their order, and its texts match failedCallWarning in the JavaScript worker (#1049). - The locked block that handles the outcome reads the terminate flag, the closed flag, the suspend hook count, and the refusal flag. It reads them before it changes them. - The warning is logged after that block. So the rejection warning now comes after the block too. - The refusal-for-now text without a hook now uses the JavaScript wording. It states the same facts. The behavior is unchanged. 19 new tests assert the HTTP statuses and the call times, and then the full text, logged once. On the previous worker.py, every new status and time assertion passes. Only the text assertions fail. --- .../worker.py | 192 +++++++++---- .../tests/lifecycle_hooks_test.py | 260 +++++++++++++++++- 2 files changed, 386 insertions(+), 66 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py index 3f16d1af1..3e87aad03 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py @@ -178,6 +178,113 @@ def _start_timer(delay: float, action: Callable[[], None]) -> Callable[[], None] return timer.cancel +def _failed_call_warning( + outcome: SuspendOutcome, + *, + terminating: bool, + closed: bool, + suspend_hook_arrived: bool, + suspending: bool, +) -> str: + """Return the warning for a failed SuspendMicrovm call. + + The text depends on the outcome and on the listener state when the + outcome is handled. The caller reads that state under the lock, before + it changes it. The conditions, their order, and the texts match the + JavaScript worker's ``failedCallWarning``. + + 1. A terminate hook during the call: ``_start_idle_time`` starts no + idle time. So the listener never calls again. A rejection keeps its + permission hint. For an unknown outcome, the text also says that the + listener refuses jobs, because a terminating listener refuses jobs + for good. + 2. A rejection with a suspend hook during the call, while the hook's + refusal is still in effect: the MicroVM is suspending anyway. So the + refusal stays until the resume hook, or 30 seconds after the last + suspend hook. The text keeps the permission hint. + 3. A rejection otherwise: the MicroVM keeps running. + 4. A refusal for now after ``close()`` during the call: + ``_start_idle_time`` starts no idle time. So the listener never + calls again. + 5. A refusal for now with a suspend hook during the call, while the + hook's refusal is still in effect: the refusal stays, as in item 2. + 6. A refusal for now with a suspend hook during the call, after the + hook's refusal ended: the listener accepts jobs, and calls again one + idle time after the call and every job end. + 7. A refusal for now otherwise: the next idle time lasts at least 30 + seconds, unless a job or a resume hook starts the idle time again. + 8. An unknown outcome otherwise: the refusal continues until the resume + hook, or for 30 seconds. + """ + if outcome is SuspendOutcome.UNKNOWN: + if terminating: + return ( + "the suspend call for the idle MicroVM had an unknown outcome. " + "The MicroVM is terminating, so the worker refuses jobs and " + "does not try the call again." + ) + return ( + "the suspend call for the idle MicroVM had an unknown outcome. The " + "worker refuses jobs until the MicroVM resumes, or for 30 seconds." + ) + if outcome is SuspendOutcome.REJECTED: + if terminating: + return ( + "could not suspend the idle MicroVM, because the service " + "rejected the call. The MicroVM is terminating, so the worker " + "does not try the call again. A missing permission needs " + "lambda:SuspendMicrovm on the MicroVM image in its execution " + "role." + ) + if suspend_hook_arrived and suspending: + return ( + "could not suspend the idle MicroVM, because the service " + "rejected the call. A suspend hook arrived during the call, so " + "the MicroVM is suspending anyway. The hook's refusal of jobs " + "stays until the resume hook, or 30 seconds after the last " + "suspend hook. A missing permission needs lambda:SuspendMicrovm " + "on the MicroVM image in its execution role." + ) + return ( + "could not suspend the idle MicroVM, because the service rejected " + "the call. It keeps running. A missing permission needs " + "lambda:SuspendMicrovm on the MicroVM image in its execution role." + ) + if terminating: + return ( + "could not suspend the idle MicroVM, because the service refused " + "the call for now. The MicroVM is terminating, so the worker does " + "not try the call again." + ) + if closed: + return ( + "could not suspend the idle MicroVM, because the service refused " + "the call for now. The worker is closed, so it does not try the " + "call again." + ) + if suspend_hook_arrived and suspending: + return ( + "could not suspend the idle MicroVM, because the service refused " + "the call for now. A suspend hook arrived during the call, so this " + "call does not end the hook's refusal. The idle time starts again " + "after the resume hook, or 30 seconds after the last suspend hook." + ) + if suspend_hook_arrived: + return ( + "could not suspend the idle MicroVM, because the service refused " + "the call for now. A suspend hook arrived during the call, and the " + "hook's refusal of jobs ended before the call ended. So the worker " + "accepts jobs. It tries the call again one idle time after the " + "call and every job end." + ) + return ( + "could not suspend the idle MicroVM, because the service refused the " + "call for now. It keeps running. The worker tries the call again after " + "the next idle time. That idle time lasts at least 30 seconds, unless a " + "job or a resume hook starts the idle time again." + ) + + @dataclass(frozen=True, kw_only=True) class _AutoSuspend: """The run hook's request to suspend the MicroVM when idle.""" @@ -305,7 +412,9 @@ class MicrovmWorkerListener: key. A job that ends after the refusal, or a ``resume`` hook after it, starts the normal idle time instead. A ``resume`` hook or a job that ends during the call does not, because the refused outcome - arrives after it. + arrives after it. A ``suspend`` hook whose refusal is still in + effect when the call ends is the exception, as in item 6. Its + refusal stays, and the idle time starts when it ends. The default client retries a throttle. So a throttle from it usually ends as an unknown outcome, as in item 8. A throttle is refused for now only from a caller's client that does not retry it. @@ -1458,66 +1567,45 @@ def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: suspend_microvm(client, target, SUSPEND_CALL_TIMEOUT_SECONDS) except Exception as error: # noqa: BLE001 outcome = classify_suspend_error(error) - if outcome is not SuspendOutcome.UNKNOWN: - if outcome is SuspendOutcome.REJECTED: - self._logger.warning( - "could not suspend the idle MicroVM, because the " - "service rejected the call. It keeps running. A " - "missing permission needs lambda:SuspendMicrovm on the " - "MicroVM image in its execution role.", - extra={**fields, "error": describe(error)}, - ) + deferred = [] + with self._lock: + # The warning depends on this state. The block reads it + # before it changes it. So the text matches the decision + # below, whatever another thread does after the lock is + # released. + hook_arrived = self._suspend_hooks != hooks_before + terminating = self._terminating + closed = self._closed + suspending = self._suspending # The service did nothing. So jobs can run again at once. A # suspend hook that arrived since the idle time ended means # that the MicroVM is suspending anyway, so its refusal stays. - with self._lock: - deferred = [] - hook_arrived = self._suspend_hooks != hooks_before - if not hook_arrived: - deferred = self._stop_refusing() - # A rejection, such as a missing permission, is not - # retried until a job ends. A refusal for now is - # retried after the next idle time. That idle time - # lasts at least 30 seconds, because the same error - # can repeat on every call. - if outcome is SuspendOutcome.REFUSED_FOR_NOW: - self._start_idle_time(after_refusal=True) - if outcome is SuspendOutcome.REFUSED_FOR_NOW: - if hook_arrived: - # The hook's refusal stays, so no 30-second floor - # applies. The idle time starts when that refusal - # ends. - self._logger.warning( - "could not suspend the idle MicroVM, because the " - "service refused the call for now. A suspend hook " - "arrived during the call, so its refusal of jobs " - "stays. That refusal ends when the resume hook " - "arrives, or 30 seconds after the suspend hook. " - "The idle time then starts again.", - extra={**fields, "error": describe(error)}, - ) - else: - self._logger.warning( - "could not suspend the idle MicroVM, because the " - "service refused the call for now. It keeps " - "running, and the worker tries again after the " - "next idle time. That idle time lasts at least 30 " - "seconds, unless a job or a resume hook starts the " - "idle time again.", - extra={**fields, "error": describe(error)}, - ) + if outcome is not SuspendOutcome.UNKNOWN and not hook_arrived: + deferred = self._stop_refusing() + # A rejection, such as a missing permission, is not + # retried until a job ends. A refusal for now is retried + # after the next idle time. That idle time lasts at least + # 30 seconds, because the same error can repeat on every + # call. + if outcome is SuspendOutcome.REFUSED_FOR_NOW: + self._start_idle_time(after_refusal=True) + self._logger.warning( + _failed_call_warning( + outcome, + terminating=terminating, + closed=closed, + suspend_hook_arrived=hook_arrived, + suspending=suspending, + ), + extra={**fields, "error": describe(error)}, + ) + if outcome is not SuspendOutcome.UNKNOWN: self._launch_deferred(deferred) return # A timeout, a conflict, a server error, or an error after a # retried attempt does not show whether the service suspended # the MicroVM. So the refusal continues, as after a successful # call. - self._logger.warning( - "the suspend call for the idle MicroVM had an unknown outcome. " - "The worker refuses jobs until the MicroVM resumes, or for 30 " - "seconds.", - extra={**fields, "error": describe(error)}, - ) finally: if owns_client: # Each suspend creates its own client. Closing it releases diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index fc4e6d71b..44901b017 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -39,6 +39,63 @@ GRACE = 30.0 TERMINATED_MESSAGE = "the MicroVM was terminated before the job finished" +# The warnings for a failed SuspendMicrovm call. They match the JavaScript +# worker's texts word for word. +REJECTED = ( + "could not suspend the idle MicroVM, because the service rejected the " + "call. It keeps running. A missing permission needs lambda:SuspendMicrovm " + "on the MicroVM image in its execution role." +) +REJECTED_TERMINATING = ( + "could not suspend the idle MicroVM, because the service rejected the " + "call. The MicroVM is terminating, so the worker does not try the call " + "again. A missing permission needs lambda:SuspendMicrovm on the MicroVM " + "image in its execution role." +) +REJECTED_SUSPENDING = ( + "could not suspend the idle MicroVM, because the service rejected the " + "call. A suspend hook arrived during the call, so the MicroVM is " + "suspending anyway. The hook's refusal of jobs stays until the resume " + "hook, or 30 seconds after the last suspend hook. A missing permission " + "needs lambda:SuspendMicrovm on the MicroVM image in its execution role." +) +REFUSED = ( + "could not suspend the idle MicroVM, because the service refused the call " + "for now. It keeps running. The worker tries the call again after the " + "next idle time. That idle time lasts at least 30 seconds, unless a job or " + "a resume hook starts the idle time again." +) +REFUSED_TERMINATING = ( + "could not suspend the idle MicroVM, because the service refused the call " + "for now. The MicroVM is terminating, so the worker does not try the call " + "again." +) +REFUSED_CLOSED = ( + "could not suspend the idle MicroVM, because the service refused the call " + "for now. The worker is closed, so it does not try the call again." +) +REFUSED_SUSPENDING = ( + "could not suspend the idle MicroVM, because the service refused the call " + "for now. A suspend hook arrived during the call, so this call does not " + "end the hook's refusal. The idle time starts again after the resume " + "hook, or 30 seconds after the last suspend hook." +) +REFUSED_AFTER_HOOK = ( + "could not suspend the idle MicroVM, because the service refused the call " + "for now. A suspend hook arrived during the call, and the hook's refusal " + "of jobs ended before the call ended. So the worker accepts jobs. It " + "tries the call again one idle time after the call and every job end." +) +UNKNOWN = ( + "the suspend call for the idle MicroVM had an unknown outcome. The worker " + "refuses jobs until the MicroVM resumes, or for 30 seconds." +) +UNKNOWN_TERMINATING = ( + "the suspend call for the idle MicroVM had an unknown outcome. The " + "MicroVM is terminating, so the worker refuses jobs and does not try the " + "call again." +) + LAMBDA_HEADERS = {"Host": "localhost:8080"} FORWARDED_HEADERS = { "Host": "7ed0892b.lambda-microvm.us-east-1.on.aws", @@ -834,7 +891,7 @@ def test_logs_a_rejected_suspend_accepts_jobs_at_once_and_does_not_retry( assert h.microvms.suspended == ["mvm-1"] warnings = [line for line in logger.lines if line[0] == "warning"] assert len(warnings) == 1 - assert "lambda:SuspendMicrovm" in warnings[0][1] + assert warnings[0][1] == REJECTED assert warnings[0][2]["microvmId"] == "mvm-1" assert warnings[0][2]["error"]["name"] == "ClientError" assert h.job("cb-1") == 202 @@ -888,7 +945,7 @@ def test_keeps_refusing_jobs_after_an_unknown_outcome( h.run_hook(IDLE) h.advance(IDLE) - assert "unknown outcome" in logger.messages("warning")[0] + assert logger.messages("warning") == [UNKNOWN] assert h.job("cb-1") == 503 h.advance(GRACE) @@ -930,12 +987,7 @@ def test_accepts_jobs_at_once_and_retries_after_a_refusal_for_now( h.run_hook(IDLE) h.advance(IDLE) - assert logger.messages("warning")[0] == ( - "could not suspend the idle MicroVM, because the service refused the " - "call for now. It keeps running, and the worker tries again after the " - "next idle time. That idle time lasts at least 30 seconds, unless a job " - "or a resume hook starts the idle time again." - ) + assert logger.messages("warning") == [REFUSED] assert h.job("cb-1") == 202 h.finish_job("cb-1") @@ -1164,12 +1216,192 @@ def test_keeps_a_hook_refusal_after_a_refusal_for_now_of_the_own_call( assert h.job("cb-1") == 503 # No 30-second floor applies, so the warning does not promise one. - assert logger.messages("warning") == [ - "could not suspend the idle MicroVM, because the service refused the " - "call for now. A suspend hook arrived during the call, so its refusal " - "of jobs stays. That refusal ends when the resume hook arrives, or 30 " - "seconds after the suspend hook. The idle time then starts again." - ] + assert logger.messages("warning") == [REFUSED_SUSPENDING] + + +def hold_failed_call(h: Harness, failure: BaseException) -> None: + """Start the first SuspendMicrovm call, and keep it open until + :func:`end_failed_call`.""" + h.microvms.hold = True + h.microvms.failure = failure + h.run_hook(IDLE) + h.advance(IDLE) + assert eventually(lambda: h.microvms.suspended == ["mvm-1"]) + + +def end_failed_call(h: Harness) -> None: + """End the held call with its failure. Every later call succeeds, so it + logs no warning.""" + h.microvms.hold = False + h.microvms.finish() + h.settle() + h.microvms.failure = None + + +@pytest.mark.parametrize( + "hooks", + [["terminate"], ["suspend", "terminate"]], + ids=["terminate", "suspend-then-terminate"], +) +@pytest.mark.parametrize( + ("failure", "text"), + [ + (suspend_error("AccessDeniedException", 403), REJECTED_TERMINATING), + (suspend_error("InvalidSignatureException", 403), REFUSED_TERMINATING), + ( + suspend_error("InternalServerException", 500, retries=2), + UNKNOWN_TERMINATING, + ), + ], + ids=["rejected", "refused-for-now", "unknown"], +) +def test_never_calls_again_after_a_terminate_hook_during_a_failed_call( + start: Any, logger: Any, failure: BaseException, text: str, hooks: list[str] +) -> None: + # A terminating listener refuses jobs for good, and starts no idle time. + # So the text names the terminate hook, also after a suspend hook. + h = start() + hold_failed_call(h, failure) + for hook in hooks: + assert h.hook(hook) == 200 + end_failed_call(h) + + assert h.job("cb-1") == 503 + assert h.hook("resume") == 200 + h.advance(GRACE * 4) + assert h.job("cb-2") == 503 + assert h.microvms.suspended == ["mvm-1"] + assert logger.messages("warning") == [text] + + +@pytest.mark.parametrize( + ("failure", "text"), + [ + (suspend_error("InvalidSignatureException", 403), REFUSED_CLOSED), + # A rejection promises no retry. So its text stays true after close(). + (suspend_error("AccessDeniedException", 403), REJECTED), + ], + ids=["refused-for-now", "rejected"], +) +def test_never_calls_again_after_close_during_a_failed_call( + start: Any, logger: Any, failure: BaseException, text: str +) -> None: + h = start() + hold_failed_call(h, failure) + h.listener.close() + end_failed_call(h) + + assert h.job("cb-1") == 202 + h.finish_job("cb-1") + assert h.hook("resume") == 200 + h.advance(GRACE * 4) + assert h.microvms.suspended == ["mvm-1"] + assert logger.messages("warning") == [text] + + +def test_names_the_terminate_hook_when_close_also_came_during_a_refused_call( + start: Any, logger: Any +) -> None: + h = start() + hold_failed_call(h, suspend_error("InvalidSignatureException", 403)) + h.listener.close() + assert h.hook("terminate") == 200 + end_failed_call(h) + + assert h.job("cb-1") == 503 + h.advance(GRACE * 4) + assert h.microvms.suspended == ["mvm-1"] + assert logger.messages("warning") == [REFUSED_TERMINATING] + + +@pytest.mark.parametrize("end", ["resume", "grace"]) +@pytest.mark.parametrize( + ("failure", "text"), + [ + (suspend_error("AccessDeniedException", 403), REJECTED_SUSPENDING), + (suspend_error("InvalidSignatureException", 403), REFUSED_SUSPENDING), + ], + ids=["rejected", "refused-for-now"], +) +def test_keeps_a_suspend_hook_refusal_in_effect_after_a_failed_call( + start: Any, logger: Any, failure: BaseException, text: str, end: str +) -> None: + # Two suspend hooks arrive during the call, 10 seconds apart. The failed + # call does not end their refusal. The refusal ends on the resume hook, + # or 30 seconds after the last suspend hook. The idle time then starts + # without the 30-second floor. + h = start() + hold_failed_call(h, failure) + assert h.hook("suspend") == 200 + h.advance(10) + assert h.hook("suspend") == 200 + end_failed_call(h) + + assert h.job("cb-1") == 503 + if end == "resume": + assert h.hook("resume") == 200 + else: + h.advance(GRACE - 0.001) + assert h.job("cb-2") == 503 + h.advance(0.001) + h.advance(IDLE - 0.001) + assert h.microvms.suspended == ["mvm-1"] + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + assert logger.messages("warning") == [text] + + +@pytest.mark.parametrize("then", ["no-job", "job"]) +@pytest.mark.parametrize("end", ["resume", "grace"]) +def test_accepts_jobs_after_a_refusal_for_now_when_the_hook_refusal_ended( + start: Any, logger: Any, end: str, then: str +) -> None: + # A suspend hook arrives during the call. Its refusal ends before the + # call ends: on a resume hook, or after 30 seconds, because botocore + # cannot cancel an attempt in flight. The refused outcome then neither + # ends a refusal nor asks for the 30-second floor. + h = start() + hold_failed_call(h, suspend_error("InvalidSignatureException", 403)) + assert h.hook("suspend") == 200 + if end == "resume": + assert h.hook("resume") == 200 + else: + h.advance(GRACE) + end_failed_call(h) + + if then == "job": + assert h.job("cb-1") == 202 + h.advance(GRACE) + assert h.microvms.suspended == ["mvm-1"] + h.finish_job("cb-1") + h.advance(IDLE - 0.001) + assert h.microvms.suspended == ["mvm-1"] + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + assert logger.messages("warning") == [REFUSED_AFTER_HOOK] + + +@pytest.mark.parametrize("end", ["resume", "grace"]) +def test_says_the_microvm_keeps_running_after_a_rejection_when_the_hook_refusal_ended( + start: Any, logger: Any, end: str +) -> None: + h = start() + hold_failed_call(h, suspend_error("AccessDeniedException", 403)) + assert h.hook("suspend") == 200 + if end == "resume": + assert h.hook("resume") == 200 + else: + h.advance(GRACE) + end_failed_call(h) + + assert h.job("cb-1") == 202 + h.finish_job("cb-1") + h.advance(IDLE - 0.001) + assert h.microvms.suspended == ["mvm-1"] + h.advance(0.001) + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + assert logger.messages("warning") == [REJECTED] + def test_keeps_refusing_jobs_until_a_call_past_its_deadline_has_ended( From eff94b39034c8163b72bb58cb4d3527b67021e56 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Wed, 21 Oct 2026 21:58:01 -0700 Subject: [PATCH 09/12] feat(microvm-worker): log the wait before a suspend The info line "suspending the idle MicroVM" logged only idleSeconds. After a refusal for now, the wait before the next call lasts at least 30 seconds. So with a 1-second idle time, the line said idleSeconds: 1 for a call that came 30 seconds after the previous one. The line now also logs waitedSeconds. It is the delay that the idle timer waited. 1. _start_idle_time passes the delay that it chose to the timer's action. 2. The action passes it on to the thread that makes the call. 3. The call logs it next to idleSeconds. The JavaScript worker logs the same value as waitedMs. A new test checks both fields for a 1-second and a 45-second idle time. --- .../worker.py | 27 ++++++++++++++----- .../tests/lifecycle_hooks_test.py | 26 ++++++++++++++++++ 2 files changed, 46 insertions(+), 7 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py index 3e87aad03..9c473c72d 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py @@ -1448,8 +1448,11 @@ def _start_idle_time(self, *, after_refusal: bool = False) -> None: idle_seconds = max(idle_seconds, SUSPEND_GRACE_SECONDS) generation = self._idle_generation try: + # The timer keeps the delay that it waits, so that the call can + # log it. self._cancel_idle_timer = _start_timer( - idle_seconds, lambda: self._idle_time_ended(generation) + idle_seconds, + lambda: self._idle_time_ended(generation, idle_seconds), ) except Exception as error: # noqa: BLE001 # Without a timer thread, the MicroVM keeps running until a job @@ -1465,7 +1468,7 @@ def _stop_idle_time(self) -> None: self._cancel_idle_timer() self._cancel_idle_timer = None - def _idle_time_ended(self, generation: int) -> None: + def _idle_time_ended(self, generation: int, waited_seconds: float) -> None: with self._lock: auto_suspend = self._auto_suspend # A job that started after the timer was set cancels it. This @@ -1490,7 +1493,7 @@ def _idle_time_ended(self, generation: int) -> None: try: threading.Thread( target=self._suspend_self, - args=(auto_suspend, hooks_before), + args=(auto_suspend, hooks_before, waited_seconds), name="microvm-suspend", daemon=True, ).start() @@ -1506,9 +1509,11 @@ def _idle_time_ended(self, generation: int) -> None: self._suspend_call_ended() self._launch_deferred(deferred) - def _suspend_self(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: + def _suspend_self( + self, auto_suspend: _AutoSuspend, hooks_before: int, waited_seconds: float + ) -> None: try: - self._call_suspend(auto_suspend, hooks_before) + self._call_suspend(auto_suspend, hooks_before, waited_seconds) finally: with self._changed: self._suspend_call_ended() @@ -1536,7 +1541,9 @@ def _suspend_call_ended(self) -> None: self._start_idle_time(after_refusal=self._idle_after_call_floor) self._changed.notify_all() - def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: + def _call_suspend( + self, auto_suspend: _AutoSuspend, hooks_before: int, waited_seconds: float + ) -> None: target = auto_suspend.microvm_id fields = {"microvmId": target} # The listener closes only a client that it created itself. A client @@ -1559,9 +1566,15 @@ def _call_suspend(self, auto_suspend: _AutoSuspend, hooks_before: int) -> None: deferred = self._end_own_refusal(hooks_before) self._launch_deferred(deferred) return + # waitedSeconds differs from idleSeconds after a refusal for now, + # because that idle time lasts at least SUSPEND_GRACE_SECONDS. self._logger.info( "suspending the idle MicroVM", - extra={**fields, "idleSeconds": auto_suspend.idle_seconds}, + extra={ + **fields, + "idleSeconds": auto_suspend.idle_seconds, + "waitedSeconds": waited_seconds, + }, ) try: suspend_microvm(client, target, SUSPEND_CALL_TIMEOUT_SECONDS) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index 44901b017..868255bc1 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -1403,6 +1403,32 @@ def test_says_the_microvm_keeps_running_after_a_rejection_when_the_hook_refusal_ assert logger.messages("warning") == [REJECTED] +@pytest.mark.parametrize( + ("idle", "waited"), [(1.0, GRACE), (45.0, 45.0)], ids=["idle-1s", "idle-45s"] +) +def test_logs_the_idle_time_and_the_wait_before_each_call( + start: Any, logger: Any, idle: float, waited: float +) -> None: + # After a refusal for now, the wait lasts at least 30 seconds. So it can + # differ from the session's idle time. + h = start() + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + + h.run_hook(idle) + h.advance(idle) + h.advance(waited) + + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + calls = [ + data + for level, message, data in logger.lines + if level == "info" and message == "suspending the idle MicroVM" + ] + assert calls == [ + {"microvmId": "mvm-1", "idleSeconds": idle, "waitedSeconds": idle}, + {"microvmId": "mvm-1", "idleSeconds": idle, "waitedSeconds": waited}, + ] + def test_keeps_refusing_jobs_until_a_call_past_its_deadline_has_ended( start: Any, monkeypatch: pytest.MonkeyPatch From a0d7ec79fdf9f95aba05274a8de2088cddca9cff Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Wed, 21 Oct 2026 21:58:11 -0700 Subject: [PATCH 10/12] docs(microvm-worker): give the JS credentials reason README item 6 and rule 2 of classify_suspend_error gave a reason why missing credentials count as a rejection. The reason was that the call sends no request. 1. A call refused for now also does nothing at the service. 2. So that reason does not separate a rejection from a refusal for now. 3. The difference is whether a later call can succeed. A later call in the same MicroVM most likely finds no credentials either. Both texts now give that reason, as the JavaScript worker does. --- .../README.md | 2 +- .../self_suspend.py | 5 +++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md index d0c0383e2..b7940a6c4 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md @@ -109,7 +109,7 @@ A session's run hook payload can set `autoSuspendIdleSeconds`. The session sets 3. When the idle time ends, the worker calls `SuspendMicrovm` with the MicroVM ID from the `run` hook, never one from a job request. The call returned in under 100 milliseconds in testing, before the MicroVM froze. No attempt of the call starts after 10 seconds, because a `before-send` handler on the client stops botocore's retries at that deadline. botocore cannot cancel an attempt in flight, and it opens the connection after `before-send`. So an attempt that started before the deadline can still reach the service after it. The worker waits for that attempt to end, and refuses jobs until then. The client's connect and read timeouts bound the attempt: 5 and 10 seconds for the default client. A client from `create_microvms_client` should use similar timeouts. botocore's own defaults are 60 seconds each, so with them the refusal can last minutes. The durable function resumes the MicroVM before the next job, and the process continues with its memory and files. 4. From the moment the idle time ends, the worker answers every job with HTTP 503 and does not start it. A job accepted then would freeze with the MicroVM, and nothing would resume it. After a 503, the durable function checks the state, resumes the MicroVM, and delivers the job again. 5. The refusal ends when the `resume` lifecycle hook arrives, or 30 seconds after the call returned, if no hook arrives. The idle time then starts again. At most one call runs at a time. A `resume` hook that arrives during the call ends the refusal at once, and the next idle time starts when the call ends. So enable the `resume` hook in the image. Without it, the first job after a resume can wait a little over 30 seconds: the 30 seconds, plus up to 4 seconds until the durable function's next delivery attempt. A test measured 32 seconds. -6. A call that the service rejected on its first attempt, such as `AccessDeniedException` for a missing permission, is logged as a warning, and the MicroVM keeps running. Missing credentials count as a rejection, because the call sends no request. The worker accepts jobs again at once and does not retry the call. The next job that ends starts the idle time again. +6. A call that the service rejected on its first attempt, such as `AccessDeniedException` for a missing permission, is logged as a warning, and the MicroVM keeps running. Missing credentials count as a rejection. A later call in the same MicroVM most likely finds no credentials either. The worker accepts jobs again at once and does not retry the call. The next job that ends starts the idle time again. 7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. That idle time lasts at least 30 seconds, also when `autoSuspendIdleSeconds` is shorter. The same error can repeat on every call, for example with a wrong secret key or an expired session token from environment variables. So while no job ends and no lifecycle hook arrives, the worker makes at most one call per 30 seconds, and logs one warning per call. A job that ends after the refusal, or a `resume` hook after it, starts the normal idle time instead. A `resume` hook or a job that ends during the call does not shorten the idle time after the refusal, because the refused outcome arrives after it. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker classifies these errors the same way. Its default client retries a clock-skew error. So there, a clock-skew error usually ends as an unknown outcome. 8. A call whose outcome is unknown is handled like a successful call, because the service may have suspended the MicroVM anyway. This covers a timeout, a conflict, a server error, and a dropped connection. An error after botocore retried an earlier attempt also counts as unknown, because the earlier attempt may have suspended the MicroVM. The default client uses botocore's standard retry mode with 3 attempts, and that mode retries a throttle. So a throttle usually ends here. The refusal continues until the `resume` hook or the 30-second limit. The idle time then starts again, so the worker tries the call again. diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py index 6bb5d8b88..21ecaf6b0 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/self_suspend.py @@ -180,8 +180,9 @@ def classify_suspend_error(error: BaseException) -> SuspendOutcome: have suspended the MicroVM before its answer was lost. So any error after a retry is :attr:`SuspendOutcome.UNKNOWN`. The default client retries a throttle. So a throttle from it usually ends here. - 2. Missing credentials stop the call before any request. They are - :attr:`SuspendOutcome.REJECTED`, as in the JavaScript worker. + 2. Missing credentials are :attr:`SuspendOutcome.REJECTED`, as in the + JavaScript worker. A later call in the same MicroVM most likely finds + no credentials either. 3. A known rejection code is :attr:`SuspendOutcome.REJECTED`. 4. A conflict is :attr:`SuspendOutcome.UNKNOWN`, whatever its status. It can mean that the MicroVM is already suspending. From ad0b5500c4d7e00afa06b9fd17be0a051247b1c9 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Wed, 21 Oct 2026 21:58:36 -0700 Subject: [PATCH 11/12] docs(microvm-worker): name the suspend hook exception README item 6 and item 6 of the listener docstring said that a rejected call ends the refusal at once. README item 7 said the same for a call refused for now. 1. A suspend hook can arrive during the call. Its refusal can still be in effect when the call ends. 2. The MicroVM is then suspending anyway. So the failed call does not end that refusal. 3. That refusal ends on the resume hook, or 30 seconds after the last suspend hook. The idle time then starts again. Both items now name this exception, as the JavaScript README does since #1049. Item 7 of the listener docstring got the same sentence in dadacce7. Item 6 also said that the worker does not retry a rejected call until a job ends. A resume hook during the call is an exception too. The idle time then starts when the call ends. Item 6 now names it, as the JavaScript README does. Tests in dadacce7 check each of these rules. Two suspend hooks arrive 10 seconds apart. Jobs get HTTP 503 until the resume hook, or until 30 seconds after the second hook. The next call comes one idle time after that. --- .../README.md | 4 ++-- .../worker.py | 9 +++++++++ 2 files changed, 11 insertions(+), 2 deletions(-) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md index b7940a6c4..e4a8a2d49 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/README.md +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/README.md @@ -109,8 +109,8 @@ A session's run hook payload can set `autoSuspendIdleSeconds`. The session sets 3. When the idle time ends, the worker calls `SuspendMicrovm` with the MicroVM ID from the `run` hook, never one from a job request. The call returned in under 100 milliseconds in testing, before the MicroVM froze. No attempt of the call starts after 10 seconds, because a `before-send` handler on the client stops botocore's retries at that deadline. botocore cannot cancel an attempt in flight, and it opens the connection after `before-send`. So an attempt that started before the deadline can still reach the service after it. The worker waits for that attempt to end, and refuses jobs until then. The client's connect and read timeouts bound the attempt: 5 and 10 seconds for the default client. A client from `create_microvms_client` should use similar timeouts. botocore's own defaults are 60 seconds each, so with them the refusal can last minutes. The durable function resumes the MicroVM before the next job, and the process continues with its memory and files. 4. From the moment the idle time ends, the worker answers every job with HTTP 503 and does not start it. A job accepted then would freeze with the MicroVM, and nothing would resume it. After a 503, the durable function checks the state, resumes the MicroVM, and delivers the job again. 5. The refusal ends when the `resume` lifecycle hook arrives, or 30 seconds after the call returned, if no hook arrives. The idle time then starts again. At most one call runs at a time. A `resume` hook that arrives during the call ends the refusal at once, and the next idle time starts when the call ends. So enable the `resume` hook in the image. Without it, the first job after a resume can wait a little over 30 seconds: the 30 seconds, plus up to 4 seconds until the durable function's next delivery attempt. A test measured 32 seconds. -6. A call that the service rejected on its first attempt, such as `AccessDeniedException` for a missing permission, is logged as a warning, and the MicroVM keeps running. Missing credentials count as a rejection. A later call in the same MicroVM most likely finds no credentials either. The worker accepts jobs again at once and does not retry the call. The next job that ends starts the idle time again. -7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. That idle time lasts at least 30 seconds, also when `autoSuspendIdleSeconds` is shorter. The same error can repeat on every call, for example with a wrong secret key or an expired session token from environment variables. So while no job ends and no lifecycle hook arrives, the worker makes at most one call per 30 seconds, and logs one warning per call. A job that ends after the refusal, or a `resume` hook after it, starts the normal idle time instead. A `resume` hook or a job that ends during the call does not shorten the idle time after the refusal, because the refused outcome arrives after it. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker classifies these errors the same way. Its default client retries a clock-skew error. So there, a clock-skew error usually ends as an unknown outcome. +6. A call that the service rejected on its first attempt, such as `AccessDeniedException` for a missing permission, is logged as a warning, and the MicroVM keeps running. Missing credentials count as a rejection. A later call in the same MicroVM most likely finds no credentials either. The worker accepts jobs again at once and does not retry the call. The next job that ends starts the idle time again. The exception is a `resume` hook that arrived during the call. The idle time then starts when the call ends. So the worker retries the call one idle time after the call ends, if no job runs and no `suspend` hook refusal is in effect when the call ends. A second exception is a `suspend` hook that arrived during the call and whose refusal is still in effect when the call ends. The MicroVM is then suspending anyway. So the rejection does not end the hook's refusal. That refusal ends on the `resume` hook, or 30 seconds after the last `suspend` hook. The idle time then starts again. +7. A call that the service refused for now on its first attempt is logged as a warning too, and the worker accepts jobs again at once. This covers expired credentials and a signature error, with or without a clock offset, whatever the HTTP status. The service answers these before it acts. botocore retries none of these errors, so they reach the worker on the first attempt. The idle time then starts again, so the worker tries the call again. That idle time lasts at least 30 seconds, also when `autoSuspendIdleSeconds` is shorter. The same error can repeat on every call, for example with a wrong secret key or an expired session token from environment variables. So while no job ends and no lifecycle hook arrives, the worker makes at most one call per 30 seconds, and logs one warning per call. A job that ends after the refusal, or a `resume` hook after it, starts the normal idle time instead. A `resume` hook or a job that ends during the call does not shorten the idle time after the refusal, because the refused outcome arrives after it. A `suspend` hook whose refusal is still in effect when the call ends is the exception, as in item 6. Its refusal stays, and the idle time starts when it ends. The default client retries a throttle, so a throttle from it usually ends as an unknown outcome, as in item 8. A throttle counts as refused for now only from a client that does not retry it, such as a client from `create_microvms_client` with one attempt. The JavaScript worker classifies these errors the same way. Its default client retries a clock-skew error. So there, a clock-skew error usually ends as an unknown outcome. 8. A call whose outcome is unknown is handled like a successful call, because the service may have suspended the MicroVM anyway. This covers a timeout, a conflict, a server error, and a dropped connection. An error after botocore retried an earlier attempt also counts as unknown, because the earlier attempt may have suspended the MicroVM. The default client uses botocore's standard retry mode with 3 attempts, and that mode retries a throttle. So a throttle usually ends here. The refusal continues until the `resume` hook or the 30-second limit. The idle time then starts again, so the worker tries the call again. `worker.close()` stops the idle time. A closed worker never suspends its MicroVM again. A refusal that is already running still ends on the `resume` hook or after 30 seconds. diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py index 9c473c72d..f49114830 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/src/aws_durable_execution_sdk_python_microvm_worker/worker.py @@ -404,6 +404,15 @@ class MicrovmWorkerListener: 6. A call that the service rejected on its first attempt, for example for a missing permission, ends the refusal at once. The MicroVM keeps running, and the listener does not retry the call until a job ends. + The exception is a ``resume`` hook that arrived during the call. The + idle time then starts when the call ends. So the listener retries the + call one idle time after the call ends, if no job runs and no + ``suspend`` hook refusal is in effect when the call ends. A second + exception is a ``suspend`` hook that arrived during the call and + whose refusal is still in effect when the call ends. The MicroVM is + then suspending anyway. So the rejection does not end the hook's + refusal. That refusal ends on the ``resume`` hook, or 30 seconds + after the last ``suspend`` hook. The idle time then starts again. 7. A call that the service refused for now on its first attempt, such as expired credentials or a signature error, ends the refusal at once too. The idle time then starts again, so the listener tries the From 6058457e86fedbe05e10c7d8c893740c30f81a23 Mon Sep 17 00:00:00 2001 From: Pooya Paridel Date: Wed, 21 Oct 2026 22:52:32 -0700 Subject: [PATCH 12/12] test(microvm-worker): check the wait on every path The "suspending the idle MicroVM" info line logs waitedSeconds. Only one test checked the field. That test covers a refusal for now, where the wait lasts at least 30 seconds. So a worker that logged the session's idle time as waitedSeconds failed one test case: idle-1s. A new test checks waitedSeconds after four other paths. Each path uses an idle time of 1 second. 1. A job ends after a refusal for now. The wait is 1 second. 2. A resume hook arrives after a refusal for now. The wait is 1 second. 3. The 30-second grace after an unknown outcome ends. The wait is 1 second. 4. A resume hook arrives during a call that ends refused for now. The refusal asks for the idle time last. So the floor applies, and the wait is 30 seconds. A mutation logged the session's idle time as waitedSeconds. Case 4 and idle-1s then failed. A second mutation logged at least 30 seconds on every call. All four new cases then failed. No worker code changed. --- .../tests/lifecycle_hooks_test.py | 54 +++++++++++++++++++ 1 file changed, 54 insertions(+) diff --git a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py index 868255bc1..3a1a4be2f 100644 --- a/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py +++ b/packages/aws-durable-execution-sdk-python-microvm-worker/tests/lifecycle_hooks_test.py @@ -1430,6 +1430,60 @@ def test_logs_the_idle_time_and_the_wait_before_each_call( ] +@pytest.mark.parametrize( + ("restart", "waited"), + [ + ("job-end", 1.0), + ("resume", 1.0), + ("unknown-outcome-grace", 1.0), + ("resume-during-refused-call", GRACE), + ], + ids=["job-end", "resume", "unknown-outcome-grace", "resume-during-refused-call"], +) +def test_logs_the_wait_of_the_idle_time_that_started_the_call( + start: Any, logger: Any, restart: str, waited: float +) -> None: + # waitedSeconds is the delay of the idle timer that started the call. A + # job end, a resume hook, and the end of the 30-second grace each start + # the normal idle time. A resume hook during a refused call asks for the + # idle time first. The refusal for now asks for it last, with the floor. + # So that wait lasts 30 seconds. + h = start() + if restart == "unknown-outcome-grace": + h.microvms.failure = suspend_error("InternalServerException", 500, retries=2) + else: + h.microvms.failure = suspend_error("InvalidSignatureException", 403) + h.microvms.hold = restart == "resume-during-refused-call" + + h.run_hook(1.0) + h.advance(1.0) + if restart == "resume-during-refused-call": + assert eventually(lambda: h.microvms.suspended == ["mvm-1"]) + assert h.hook("resume") == 200 + h.microvms.hold = False + h.microvms.finish() + h.settle() + h.microvms.failure = None + if restart == "job-end": + assert h.job("cb-1") == 202 + h.finish_job("cb-1") + elif restart == "resume": + assert h.hook("resume") == 200 + elif restart == "unknown-outcome-grace": + h.advance(GRACE) + h.advance(waited - 0.001) + assert h.microvms.suspended == ["mvm-1"] + h.advance(0.001) + + assert h.microvms.suspended == ["mvm-1", "mvm-1"] + waits = [ + (data["idleSeconds"], data["waitedSeconds"]) + for level, message, data in logger.lines + if level == "info" and message == "suspending the idle MicroVM" + ] + assert waits == [(1.0, 1.0), (1.0, waited)] + + def test_keeps_refusing_jobs_until_a_call_past_its_deadline_has_ended( start: Any, monkeypatch: pytest.MonkeyPatch ) -> None: