e2e: `jmp shell` fails with "Connection to exporter lost" after ~20s waiting for ready connection

[ambient-code]

Summary

The e2e tests can lease and connect to exporters (test 47) and can lease and connect to exporters by name (test 48) fail intermittently with Error: Connection to exporter lost. The client successfully acquires a lease but then times out waiting for the ready connection on the Unix socket, never reaching the beforeLease hook completion or LEASE_READY status monitoring on the client side.

Failing CI Run

• Run: https://github.com/jumpstarter-dev/jumpstarter/actions/runs/24124076143/job/70384429636#step:6:8601
• Job: e2e-tests (ubuntu-24.04), step 6 "Run e2e tests"

Reproduction Timeline (test 47)

08:23:01  INFO  [jumpstarter.client.lease] Acquiring lease 019d6c30-0a9b-7b81-bc30-cbd918008be8
08:23:01  INFO  Lease acquired successfully! (0:00:00)
08:23:01  INFO  Waiting for ready connection at /run/user/1001/jumpstarter-nkjy63wk/socket
           ← 20 seconds of silence — no beforeLease hook log, no status_monitor update on the client side
08:23:21  INFO  Releasing Lease 019d6c30-0a9b-7b81-bc30-cbd918008be8
           Error: Connection to exporter lost

The same pattern repeats for test 48 (jmp shell --client test-client-oidc --name test-exporter-oidc j power on), also dying after ~20s with the same error.

Observations

1. The exporter side appears healthy — the exporter logs from this test show it had been successfully handling previous leases (sessions created, power on commands executed, sessions closed cleanly).

2. No beforeLease hook activity on the client — In passing runs, the client logs show Waiting for beforeLease hook to complete... followed by Status changed: None -> LEASE_READY. In the failing run, neither of these messages appears — the client goes straight from "Waiting for ready connection" to "Releasing Lease" after ~20s.

3. No exporter-side log entry for the failing lease — The exporter logs dumped on failure don't show a Starting new lease: 019d6c30-0a9b... entry, suggesting the exporter never received or processed the lease assignment for this specific lease.

4. Flaky, not deterministic — The re-run (run 24125318534) passed all 52 tests on the same commit, suggesting a race condition or transient infrastructure issue.

Possible Root Causes

• Race condition in lease routing: The controller assigned the lease, but the exporter hadn't fully re-registered after the previous lease teardown, causing the router to fail to connect the client to the exporter.
• Socket readiness timeout: The client may have a hardcoded ~20s timeout waiting for the Unix socket to become ready, and the exporter-side session setup took too long or never started.
• Router/controller propagation delay: The lease was marked Ready in k8s but the router hadn't yet updated its routing table for the new lease.

Environment

• Runner: ubuntu-24.04 (x86_64)
• Test file: e2e/tests.bats, lines 471-484

[ambient-code]

Root Cause Investigation

Investigated the last 100 commits. Here is the analysis:

Most Likely Cause: Race condition between test cleanup and lease creation

The failure occurs because test 47 creates a new lease before the exporter has finished cleaning up from test 46's lease, and the test infrastructure cannot detect this gap.

The Race Condition (step by step)

1. Test 46 ("can operate on leases") deletes a lease with jmp delete leases --client test-client-legacy --all
2. The exporter's serve() processes the lease-end:
   • Signals lease_ended
   • Blocks on after_lease_hook_done.wait() (line 821 in exporter.py)
   • Clears _lease_context = None (line 825)
   • Sleeps 200ms (line 828)
   • Then resumes iterating the status stream
3. wait_for_exporter (test helper, line 120 of tests.bats) sleeps 2s, then checks `kubectl wait --for=condition=Online --for=condition=Registered`. These conditions are set at initial registration and never cleared between leases, so the check passes immediately — even if the exporter is still blocked in step 2.
4. Test 47 runs jmp shell which creates a new lease. The controller assigns it instantly ("Lease acquired successfully! (0:00:00)").
5. The controller pushes a leased=True status to the exporter's Status stream. But the exporter's serve() is still blocked in step 2 processing the previous lease. The status message is buffered (buffer size 5).
6. The client opens a local Unix socket and starts handle_async, which calls Dial() on the controller. The controller checks checkExporterStatusForDriverCalls() — the exporter's k8s status is still Available (it hasn't processed the new lease yet), so Dial returns FAILED_PRECONDITION "exporter is not ready (status: Available)".
7. The client retries Dial with exponential backoff (0.3s base, 2s max, 30s deadline).
8. If the exporter resumes and processes the new lease in time, the Dial succeeds. If not, the client's connection breaks and the BaseExceptionGroup handler at line 467 of shell.py raises "Connection to exporter lost".

Why ~20 seconds?

The get_status_async() probe at shell.py:290 is called over the Unix socket immediately after client_from_path. Since no router connection exists yet (Dial is still retrying), this gRPC call has no backend and eventually fails or times out, propagating upward as the "Connection to exporter lost" error.

Key Commit: d6cad897 ("Fix exporter state machine: stuck exporters on lease-end during hooks #349")

This commit added await lease_scope.before_lease_hook.wait() inside CancelScope(shield=True) in _cleanup_after_lease (line 597 of exporter.py). While this does NOT cause a deadlock (the finally clause in run_before_lease_hook guarantees the event is set), it increased the duration of the between-lease cleanup window. The cleanup now waits for the beforeLease hook to complete before running the afterLease hook, adding latency to the path where serve() is blocked and unable to accept new leases.

This widened the race window that wait_for_exporter fails to protect against.

Commits Investigated and Ruled Out

Commit	Description	Verdict
b0340dd1 / 4a10a94b	Revert of listenQueues cleanup (#397)	Not the cause. The revert restores pre-#397 behavior where Dial/Listen always share the same queue. No tokens are lost.
647aff95	Wire keepalive config into gRPC server (#399)	Not the cause. No keepalive params are configured in e2e tests; the guard if params != zero prevents any behavior change.
aefd8ad6	Relax keepalive ping spacing	Not the cause. Only affects the exporter's local session server, not the controller connection.
494b043d	Reset retry counter in exporter reconnect	Not the cause. This helps prevent the issue by keeping the Status stream alive.
6d062ec7	Shell token refresh rework	Not the cause. Doesn't change controller-based lease flow.
bb855cf2	Standalone mode for exporter (#320)	Not the cause. All changes gated behind --tls-grpc / _standalone flags.
4e55d730	Auto-connect shell to existing leases (#330)	Not the cause. Only activates when --selector and --name are absent.
94949280 / 4647f1d3	Exception handling improvements	Not the cause. Pure error-presentation changes.
fe619415	Clean up stale MCP connections	Not the cause. MCP-specific, doesn't affect exporter-controller path.

Suggested Fixes

1. Fix wait_for_exporter in e2e tests — Check the exporter's ExporterStatusValue condition (should be Available), not just Online + Registered. Or better, add a condition like Ready that is only set when _lease_context is None and serve() is ready to accept new leases.

2. Reduce between-lease gap — Consider setting before_lease_hook event when the lease ends (as a safety valve in serve() at line 817), so _cleanup_after_lease doesn't have to wait for the hook to finish naturally. The hook's finally block already guarantees cleanup.

3. Add an Available k8s condition — Have the exporter set a distinct condition (e.g., condition=Available) on the k8s resource only after _lease_context is cleared and serve() is ready for new leases. Tests can then kubectl wait --for=condition=Available.

[ambient-code]

Proposed fix in #426.

The fix updates wait_for_exporter (and wait_for_hooks_exporter) to poll .status.exporterStatus for Available after checking the Online+Registered conditions. This ensures the exporter has fully finished cleaning up from the previous lease before the next test creates a new one.

[mangelajo]

This #426 would probably just mask the issue. We need to understand why the exporter does not go ready, or why is it leased when still not ready.

[ambient-code]

Root Cause Found

The lease controller's reconcileStatusExporterRef only checked Online + Registered k8s conditions before assigning leases to exporters. These conditions are set at initial registration and never cleared between leases. The ExporterStatusValue field — which tracks the exporter's actual operational state (Available, AfterLeaseHook, BeforeLeaseHook, LeaseReady, etc.) — was completely ignored.

This meant an exporter still running cleanup from a previous lease (e.g., in AfterLeaseHook status) could be assigned a new lease immediately. The client would then try to Dial(), but the exporter was blocked on after_lease_hook_done.wait() and couldn't process it, resulting in "Connection to exporter lost" after the 30s dial timeout.

Fix

PR #426 now includes both:

1. Controller fix: filterOutNotReadyExporters added to lease_controller.go — only exporters with Available status (or unset, for backwards compat) are eligible for lease assignment
2. E2E defense-in-depth: Test helpers poll exporterStatus=Available before starting new tests

[kirkbrauer]

@mangelajo This makes sense I think, most likely the e2e tests are not defensive enough and exporters no longer release themselves as quickly as before due to the new hooks logic. So I think both fixes would be helpful here.

[mangelajo]

@kirkbrauer ack thanks, if you can, approve this one in addition to me: #426
and let's see how it goes. It seems to be steadily green 🤞