hooks disabled: old client + new exporter + new controller

[mangelajo]

[03/10/26 15:34:53] DEBUG    DEBUG:asyncio:Using selector: EpollSelector                                                                                                                                         selector_events.py:64
                    DEBUG    DEBUG:jumpstarter.common.grpc:Resolved grpc.jumpstarter.10.0.2.2.nip.io to 1 IP(s): 10.0.2.2                                                                                                   grpc.py:74
                    DEBUG    DEBUG:jumpstarter.common.grpc:Attempting TLS connection to 10.0.2.2:8082 (timeout=5s)                                                                                                          grpc.py:28
                    DEBUG    DEBUG:jumpstarter.common.grpc:Successfully connected to 10.0.2.2:8082                                                                                                                          grpc.py:33
                    DEBUG    DEBUG:jumpstarter.common.grpc:Successfully extracted 1 certificate(s) from 10.0.2.2:8082                                                                                                       grpc.py:40
                    DEBUG    DEBUG:jumpstarter.common.grpc:Using certificates from 10.0.2.2:8082                                                                                                                           grpc.py:105
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                         _channel.py:369
                    DEBUG    DEBUG:grpc._cython.cygrpc:Using AsyncIOEngine.POLLER as I/O engine                                                                                                                        _channel.py:370
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                         _channel.py:370
                    DEBUG    DEBUG:jumpstarter.client.lease:Creating lease request for selector hooks=none for duration 0:30:00                                                                                            lease.py:65
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                            _call.py:569
                    INFO     INFO:jumpstarter.client.lease:Acquiring lease 019cd863-037c-7c60-a00c-44088a2f48a9 for selector hooks=none for duration 0:30:00                                                               lease.py:73
                    DEBUG    DEBUG:jumpstarter.client.lease:Polling Lease 019cd863-037c-7c60-a00c-44088a2f48a9                                                                                                            lease.py:138
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                            _call.py:569
                    DEBUG    DEBUG:jumpstarter.client.lease:Lease 019cd863-037c-7c60-a00c-44088a2f48a9 acquired                                                                                                           lease.py:143
                    DEBUG    DEBUG:jumpstarter.client.lease:Serving Unix socket at /run/user/1000/jumpstarter-dfihxjla/socket                                                                                             lease.py:220
                    INFO     INFO:jumpstarter.client.lease:Waiting for ready connection at /run/user/1000/jumpstarter-dfihxjla/socket                                                                                     lease.py:227
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                         _channel.py:369
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                         _channel.py:370
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                            _call.py:569
                    DEBUG    DEBUG:jumpstarter.client.lease:Connecting to Lease with name 019cd863-037c-7c60-a00c-44088a2f48a9                                                                                            lease.py:210
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                            _call.py:569
                    INFO     INFO:jumpstarter.client.lease:Releasing Lease 019cd863-037c-7c60-a00c-44088a2f48a9                                                                                                           lease.py:193
                    DEBUG    DEBUG:grpc._cython.cygrpc:[_cygrpc] Loaded running loop: id(loop)=140049467442912                                                                                                            _call.py:569
╭─────────────────────────────── Traceback (most recent call last) ────────────────────────────────╮
│ /home/fedora/.local/jumpstarter/bin/jmp:8 in <module>                                            │
│                                                                                                  │
│   5 from jumpstarter_cli.jmp import jmp                                                          │
│   6 if __name__ == '__main__':                                                                   │
│   7 │   sys.argv[0] = re.sub(r'(-script\.pyw|\.exe)?$', '', sys.argv[0])                         │
│ ❱ 8 │   sys.exit(jmp())                                                                          │
│   9                                                                                              │
│                                                                                                  │
│ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/click/core.py:1462 in        │
│ __call__                                                                                         │
│                                                                                                  │
│   1459 │                                                                                         │
│   1460 │   def __call__(self, *args: t.Any, **kwargs: t.Any) -> t.Any:                           │
│   1461 │   │   """Alias for :meth:`main`."""                                                     │
│ ❱ 1462 │   │   return self.main(*args, **kwargs)                                                 │
│   1463                                                                                           │
│   1464                                                                                           │
│   1465 class _FakeSubclassCheck(type):                                                           │
│                                                                                                  │
│ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/click/core.py:1383 in main   │
│                                                                                                  │
│   1380 │   │   try:                                                                              │
│   1381 │   │   │   try:                                                                          │

│ │ │ /usr/lib64/python3.13/concurrent/futures/_base.py:456 in result                          │ │ │
│ │ │                                                                                          │ │ │
│ │ │   453 │   │   │   │   if self._state in [CANCELLED, CANCELLED_AND_NOTIFIED]:             │ │ │
│ │ │   454 │   │   │   │   │   raise CancelledError()                                         │ │ │
│ │ │   455 │   │   │   │   elif self._state == FINISHED:                                      │ │ │
│ │ │ ❱ 456 │   │   │   │   │   return self.__get_result()                                     │ │ │
│ │ │   457 │   │   │   │   else:                                                              │ │ │
│ │ │   458 │   │   │   │   │   raise TimeoutError()                                           │ │ │
│ │ │   459 │   │   finally:                                                                   │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /usr/lib64/python3.13/concurrent/futures/_base.py:401 in __get_result                    │ │ │
│ │ │                                                                                          │ │ │
│ │ │   398 │   def __get_result(self):                                                        │ │ │
│ │ │   399 │   │   if self._exception is not None:                                            │ │ │
│ │ │   400 │   │   │   try:                                                                   │ │ │
│ │ │ ❱ 401 │   │   │   │   raise self._exception                                              │ │ │
│ │ │   402 │   │   │   finally:                                                               │ │ │
│ │ │   403 │   │   │   │   # Break a reference cycle with the exception in self._exception    │ │ │
│ │ │   404 │   │   │   │   self = None                                                        │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/anyio/from_thread.py │ │ │
│ │ │ :252 in _call_func                                                                       │ │ │
│ │ │                                                                                          │ │ │
│ │ │   249 │   │   │   │   │   else:                                                          │ │ │
│ │ │   250 │   │   │   │   │   │   future.add_done_callback(callback)                         │ │ │
│ │ │   251 │   │   │   │   │                                                                  │ │ │
│ │ │ ❱ 252 │   │   │   │   │   retval = await retval_or_awaitable                             │ │ │
│ │ │   253 │   │   │   else:                                                                  │ │ │
│ │ │   254 │   │   │   │   retval = retval_or_awaitable                                       │ │ │
│ │ │   255 │   │   except self._cancelled_exc_class:                                          │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/anyio/from_thread.py │ │ │
│ │ │ :131 in run_async_cm                                                                     │ │ │
│ │ │                                                                                          │ │ │
│ │ │   128 │   async def run_async_cm(self) -> bool | None:                                   │ │ │
│ │ │   129 │   │   try:                                                                       │ │ │
│ │ │   130 │   │   │   self._exit_event = Event()                                             │ │ │
│ │ │ ❱ 131 │   │   │   value = await self._async_cm.__aenter__()                              │ │ │
│ │ │   132 │   │   except BaseException as exc:                                               │ │ │
│ │ │   133 │   │   │   self._enter_future.set_exception(exc)                                  │ │ │
│ │ │   134 │   │   │   raise                                                                  │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /usr/lib64/python3.13/contextlib.py:214 in __aenter__                                    │ │ │
│ │ │                                                                                          │ │ │
│ │ │   211 │   │   # they are only needed for recreation, which is not possible anymore       │ │ │
│ │ │   212 │   │   del self.args, self.kwds, self.func                                        │ │ │
│ │ │   213 │   │   try:                                                                       │ │ │
│ │ │ ❱ 214 │   │   │   return await anext(self.gen)                                           │ │ │
│ │ │   215 │   │   except StopAsyncIteration:                                                 │ │ │
│ │ │   216 │   │   │   raise RuntimeError("generator didn't yield") from None                 │ │ │
│ │ │   217                                                                                    │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/jumpstarter/client/l │ │ │
│ │ │ ease.py:219 in serve_unix_async                                                          │ │ │
│ │ │                                                                                          │ │ │
│ │ │   216 │                                                                                  │ │ │
│ │ │   217 │   @asynccontextmanager                                                           │ │ │
│ │ │   218 │   async def serve_unix_async(self):                                              │ │ │
│ │ │ ❱ 219 │   │   async with TemporaryUnixListener(self.handle_async) as path:               │ │ │
│ │ │   220 │   │   │   logger.debug("Serving Unix socket at %s", path)                        │ │ │
│ │ │   221 │   │   │   await self._wait_for_ready_connection(path)                            │ │ │
│ │ │   222 │   │   │   # TODO: talk to the exporter to make sure it's ready.... (once we have │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /usr/lib64/python3.13/contextlib.py:235 in __aexit__                                     │ │ │
│ │ │                                                                                          │ │ │
│ │ │   232 │   │   │   │   # tell if we get the same exception back                           │ │ │
│ │ │   233 │   │   │   │   value = typ()                                                      │ │ │
│ │ │   234 │   │   │   try:                                                                   │ │ │
│ │ │ ❱ 235 │   │   │   │   await self.gen.athrow(value)                                       │ │ │
│ │ │   236 │   │   │   except StopAsyncIteration as exc:                                      │ │ │
│ │ │   237 │   │   │   │   # Suppress StopIteration *unless* it's the same exception that     │ │ │
│ │ │   238 │   │   │   │   # was passed to throw().  This prevents a StopIteration            │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/jumpstarter/common/t │ │ │
│ │ │ empfile.py:27 in TemporaryUnixListener                                                   │ │ │
│ │ │                                                                                          │ │ │
│ │ │   24 │                                                                                   │ │ │
│ │ │   25 │   with cm as path:                                                                │ │ │
│ │ │   26 │   │   async with await create_unix_listener(path) as listener:                    │ │ │
│ │ │ ❱ 27 │   │   │   async with create_task_group() as tg:                                   │ │ │
│ │ │   28 │   │   │   │   tg.start_soon(listener.serve, handler, tg)                          │ │ │
│ │ │   29 │   │   │   │   try:                                                                │ │ │
│ │ │   30 │   │   │   │   │   yield path                                                      │ │ │
│ │ │                                                                                          │ │ │
│ │ │ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/anyio/_backends/_asy │ │ │
│ │ │ ncio.py:781 in __aexit__                                                                 │ │ │
│ │ │                                                                                          │ │ │
│ │ │    778 │   │   │   │   │   # added to self._exceptions so it's ok to break exception     │ │ │
│ │ │    779 │   │   │   │   │   # chaining and avoid adding a "During handling of above..."   │ │ │
│ │ │    780 │   │   │   │   │   # for each nesting level.                                     │ │ │
│ │ │ ❱  781 │   │   │   │   │   raise BaseExceptionGroup(                                     │ │ │
│ │ │    782 │   │   │   │   │   │   "unhandled errors in a TaskGroup", self._exceptions       │ │ │
│ │ │    783 │   │   │   │   │   ) from None                                                   │ │ │
│ │ │    784 │   │   │   │   elif exc_val:                                                     │ │ │
│ │ ╰──────────────────────────────────────────────────────────────────────────────────────────╯ │ │
│ │ ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)                            │ │
│ │                                                                                              │ │
│ │ ╭──────────────────────────────────── Sub-exception #1 ────────────────────────────────────╮ │ │
│ │ │ ╭───────────────────────── Traceback (most recent call last) ──────────────────────────╮ │ │ │
│ │ │ │ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/jumpstarter/clie │ │ │ │
│ │ │ │ nt/lease.py:211 in handle_async                                                      │ │ │ │
│ │ │ │                                                                                      │ │ │ │
│ │ │ │   208 │                                                                              │ │ │ │
│ │ │ │   209 │   async def handle_async(self, stream):                                      │ │ │ │
│ │ │ │   210 │   │   logger.debug("Connecting to Lease with name %s", self.name)            │ │ │ │
│ │ │ │ ❱ 211 │   │   response = await self.controller.Dial(jumpstarter_pb2.DialRequest(leas │ │ │ │
│ │ │ │   212 │   │   async with connect_router_stream(                                      │ │ │ │
│ │ │ │   213 │   │   │   response.router_endpoint, response.router_token, stream, self.tls_ │ │ │ │
│ │ │ │   214 │   │   ):                                                                     │ │ │ │
│ │ │ │                                                                                      │ │ │ │
│ │ │ │ /home/fedora/.local/jumpstarter/venv/lib64/python3.13/site-packages/grpc/aio/_call.p │ │ │ │
│ │ │ │ y:330 in __await__                                                                   │ │ │ │
│ │ │ │                                                                                      │ │ │ │
│ │ │ │   327 │   │   │   if self._cython_call.is_locally_cancelled():                       │ │ │ │
│ │ │ │   328 │   │   │   │   raise asyncio.CancelledError()                                 │ │ │ │
│ │ │ │   329 │   │   │   else:                                                              │ │ │ │
│ │ │ │ ❱ 330 │   │   │   │   raise _create_rpc_error(                                       │ │ │ │
│ │ │ │   331 │   │   │   │   │   self._cython_call._initial_metadata,                       │ │ │ │
│ │ │ │   332 │   │   │   │   │   self._cython_call._status,                                 │ │ │ │
│ │ │ │   333 │   │   │   │   )                                                              │ │ │ │
│ │ │ ╰──────────────────────────────────────────────────────────────────────────────────────╯ │ │ │
│ │ │ AioRpcError: <AioRpcError of RPC that terminated with:                                   │ │ │
│ │ │         status = StatusCode.FAILED_PRECONDITION                                          │ │ │
│ │ │         details = "exporter is not ready (status: Available)"                            │ │ │
│ │ │         debug_error_string = "UNKNOWN:Error received from peer ipv4:10.0.2.2:8082        │ │ │
│ │ │ {grpc_message:"exporter is not ready (status: Available)", grpc_status:9}"               │ │ │
│ │ │ >                                                                                        │ │ │
│ │ ╰──────────────────────────────────────────────────────────────────────────────────────────╯ │ │
│ ╰──────────────────────────────────────────────────────────────────────────────────────────────╯ │
╰──────────────────────────────────────────────────────────────────────────────────────────────────╯

[mangelajo]

we are missing coverage for this which is a supported path.

[mangelajo]

This can probably be handled by adding retries to the Dial if FAILED_PRECONDITION is received on the main branch (or release-0.8 if we branch off)

[ambient-code]

Investigation: Dial race condition with hooks=none

Root Cause

This is a race condition between the client's Dial call and the exporter's status transition from Available to LeaseReady.

The sequence of events:

1. The lease controller assigns an exporter to the lease and sets the lease condition to Ready.
2. The client polls the lease, sees Ready, and immediately calls Dial on the controller.
3. Meanwhile, the exporter receives the lease assignment via its Status stream, then must:
   • Create a new LeaseContext
   • Start handle_lease(), which creates a gRPC session
   • Start the Listen stream (to receive forwarded Dial requests)
   • Only then report ExporterStatus.LEASE_READY
4. The controller's Dial handler calls checkExporterStatusForDriverCalls(), sees the exporter is still in Available status, and rejects with FAILED_PRECONDITION: "exporter is not ready (status: Available)".

Why hooks=none matters

When hooks are disabled, the exporter skips the BeforeLeaseHook phase and goes directly Available → LeaseReady. However, the race window still exists because the exporter must establish its session and Listen stream before it can report LeaseReady.

Ironically, having hooks enabled can mask this race because checkExporterStatusForDriverCalls permits Dial during hook execution (BeforeLeaseHook status).

Fix: Client-side retry (already implemented)

Looking at the current code in lease.py lines 308-338, a retry with exponential backoff has already been added to handle_async():

• Catches FAILED_PRECONDITION errors containing "not ready"
• Uses exponential backoff starting at 0.3s, capped at 2.0s
• Bounded by a total dial_timeout of 30 seconds (configurable)
• Logs each retry attempt for debuggability

This correctly handles the race condition for new clients. ✅

Remaining concern: old clients

The issue title says "old client + new exporter + new controller." Old clients (pre-fix) won't have this retry logic and will fail immediately on FAILED_PRECONDITION. A server-side mitigation would help protect them.

Suggested server-side improvement

In controller_service.go, the Dial handler could add a brief retry loop when the exporter status is Available (a transient state during lease setup), rather than rejecting immediately:

// In Dial(), after getting the exporter:
maxRetries := 10
retryDelay := 300 * time.Millisecond
for i := 0; i < maxRetries; i++ {
    if err := checkExporterStatusForDriverCalls(exporter.Status.ExporterStatusValue); err == nil {
        break
    }
    if exporter.Status.ExporterStatusValue != ExporterStatusAvailable {
        // Non-transient status (Offline, HookFailed, etc.) -- fail immediately
        return nil, checkExporterStatusForDriverCalls(exporter.Status.ExporterStatusValue)
    }
    time.Sleep(retryDelay)
    // Re-fetch exporter status
    if err := s.Client.Get(ctx, ...); err != nil {
        return nil, err
    }
}

This would protect old clients without requiring them to upgrade, while keeping the fail-fast behavior for genuinely broken states (Offline, HookFailed).

Edge cases

• Permanent Available status: If the exporter is stuck in Available, the server-side retry should have a short window (~3s max) to avoid blocking.
• Hook failure during retry: The client-side retry correctly stops for non-transient errors like "beforeLease hook failed".
• Backport to release-0.8: The client-side fix should be safe to backport. The dial_timeout field defaults to 30s so it's backward-compatible.

---

This investigation was performed by an automated agent (Ambient/Claude).