E2E test failure: Dial rejected with Available status despite server-side retry fix

[ambient-code]

Summary

E2E test can lease and connect to exporters is failing in PR #535 with repeated Dial rejected due to exporter status errors, followed by authentication failures with context cancellation.

Error Details

Failed run: https://github.com/jumpstarter-dev/jumpstarter/actions/runs/24201578910/job/70646355079?pr=535#step:6:698

Test: Core E2E Tests > Lease and connect > can lease and connect to exporters
Location: /home/runner/work/jumpstarter/jumpstarter/e2e/test/e2e_test.go:406
Duration: Failed after 31.5 seconds

Key error logs:

1. Repeated Dial rejections with Available status:

2026-04-09T16:50:00Z  INFO  Dial rejected due to exporter status  
  {"peer": "10.244.0.1:21066", 
   "client": {"name":"test-client-oidc","namespace":"jumpstarter-lab"}, 
   "lease": {"name":"019d7326-6a7f-711e-bfed-b5bd8bbd90f4","namespace":"jumpstarter-lab"}, 
   "status": "Available", 
   "error": "rpc error: code = FailedPrecondition desc = exporter is not ready (status: Available)"}

2. Authentication failure with context canceled:

2026-04-09T16:50:10Z  ERROR  unable to authenticate client  
  {"peer": "10.244.0.1:21066", 
   "error": "Get \"https://10.96.0.1:443/apis/jumpstarter.dev/v1alpha1/namespaces/jumpstarter-lab/clients/test-client-oidc\": context canceled"}

Final error:

Error: Connection to exporter lost

Timeline:

1. 16:49:50 - Lease acquired successfully
2. 16:49:50 - Client waits for ready connection at socket
3. 16:50:00 - Multiple Dial rejections with "Available" status (~10 seconds after lease)
4. 16:50:10 - Dial rejections continue + authentication errors with "context canceled" (~20 seconds after lease)
5. 16:50:10 - Connection lost, test fails

Context

Related PR #440 (MERGED)

PR #440 specifically addressed this race condition by adding server-side retry in the controller's Dial handler:

• Up to 10 retry attempts with 300ms delay (~3 second max)
• Only retries for Available status (transient state during lease setup)
• Other statuses (Offline, HookFailed) fail immediately

However, the error logs show the Dial is still being rejected — suggesting either:

1. The server-side retry isn't being triggered
2. The retry timeout (3s) is insufficient for this scenario
3. The exporter is stuck in Available status longer than expected
4. A regression was introduced in PR Remove opendal dependency from QEMU driver #535
5. The context is being canceled before retries can complete

Expected Behavior

The server-side retry logic from PR #440 should handle the transient Available status by retrying the Dial request until the exporter transitions to LeaseReady (within the 3-second retry window).

Actual Behavior

The Dial requests are being rejected repeatedly over a 20-second period, all with the same Available status error. After ~20 seconds, authentication attempts fail with "context canceled", eventually causing a connection failure.

Questions to Investigate

1. Is the context deadline too short? The "context canceled" error suggests the context might be timing out before the exporter can transition to LeaseReady
2. Is the server-side retry logic actually executing? (Check controller logs for retry attempts)
3. Why is the exporter remaining in Available status for 20+ seconds?
4. Is the authentication failure a symptom or cause of the connection failure?
5. Is there a timing issue in the client?
6. Are multiple concurrent Dial attempts exhausting the context deadline?

Steps to Reproduce

Run the e2e tests on PR #535:

make e2e-run

The test should fail with the Dial rejection errors followed by authentication failures as shown above.

Environment

• Platform: ubuntu-24.04-arm
• Test method: METHOD=operator (from CI logs)
• PR: Remove opendal dependency from QEMU driver #535
• Related PR: Add server-side Dial retry for transient Available status #440

---

Related:

• Fixes attempt: Add server-side Dial retry for transient Available status #440
• Failing in: Remove opendal dependency from QEMU driver #535

[ambient-code]

Investigation Findings

I performed a thorough code review of the Dial retry logic, exporter status transitions, and E2E test infrastructure. Here are the findings:

Root Cause Analysis

The issue stems from a race condition between two independent processes after lease assignment, compounded by both client-side and server-side retry loops competing against each other on the same context deadline.

The Race Condition Flow

1. Lease reconciler assigns an exporter to a lease (sets lease.Status.ExporterRef) when the exporter is in Available status — this is correct, filterOutNotReadyExporters() in lease_controller.go:539-549 explicitly requires Available status for assignment.

2. The exporter receives the lease assignment via its Status stream, then:

   • Creates a LeaseContext and starts handle_lease()
   • Inside handle_lease(), creates a new Session, starts the Listen stream, and only then calls _report_status(ExporterStatus.LEASE_READY) (line 739 of exporter.py)
   • If a hook_executor is configured, the BEFORE_LEASE_HOOK → LEASE_READY transition takes even longer

3. Meanwhile, the client acquires the lease and immediately calls Dial — but the exporter is still in Available status because the Status→LeaseReady transition hasn't completed yet.

Why the Server-Side Retry (from PR #440) Is Insufficient

The server-side retry in controller_service.go:654-696 has these parameters:

• retryDelay starts at 500ms with exponential backoff capped at 3s
• maxTotalWait = 10s

This looks adequate on paper. However, the log timeline in the issue shows Dial rejections spanning 20 seconds (16:49:50 to 16:50:10), which far exceeds the 10s server-side retry window. This means:

1. The server-side retry is executing and exhausting its 10s window
2. The client-side retry (lease.py:310-338, dial_timeout=30s) then fires additional Dial RPCs
3. Each new Dial RPC from the client starts a fresh server-side retry loop
4. But critically: the client's gRPC context is shared — when the context is canceled (around 16:50:10), both the authentication (authenticateClient) and the retry select on ctx.Done() fail simultaneously

The "context canceled" authentication error at 16:50:10 confirms this: the parent context (likely from jmp shell's overall timeout or gRPC deadline) expired, killing all in-flight Dial attempts.

Why the Exporter Stays in Available for 20+ Seconds

The exporter's Status stream (_retry_stream in exporter.py:237-283) has its own retry logic with up to 5 retries and backoff. If the Status stream disconnects/reconnects during the lease transition, the exporter may:

1. Miss or delay processing the leased=True status update
2. Not start handle_lease() promptly
3. Therefore not transition to LEASE_READY within the expected window

Additionally, session creation in session_for_lease() involves creating a new Session with device factory, setting up dual Unix sockets, and starting gRPC services — all of which take non-trivial time under CI load.

Proposed Fix Plan

Option A: Increase server-side retry window (low risk)

• Increase maxTotalWait from 10s to 30s in controller_service.go:658
• This aligns the server-side retry with the client-side dial_timeout default (30s)
• Pro: Simple change, no behavioral breakage
• Con: Doesn't address the root cause; Dial RPCs hold server resources longer

Option B: Watch-based Dial with status transition (recommended)

Instead of polling in a sleep loop, the server-side Dial handler should watch the Exporter resource and wait for the status to transition away from Available:

// In Dial handler, replace the retry loop with:
if statusErr != nil && exporter.Status.ExporterStatusValue == ExporterStatusAvailable {
    watcher, err := s.Client.Watch(ctx, &ExporterList{}, ...)
    // Watch for status change with ctx deadline
    for event := range watcher.ResultChan() {
        updated := event.Object.(*Exporter)
        if checkExporterStatusForDriverCalls(updated.Status.ExporterStatusValue) == nil {
            exporter = *updated
            statusErr = nil
            break
        }
        if updated.Status.ExporterStatusValue != ExporterStatusAvailable {
            break // Non-transient status, fail immediately
        }
    }
}

• Pro: Reacts instantly when the exporter transitions, no wasted polling; respects context deadline naturally
• Con: Slightly more complex; needs careful error handling for watch failures

Option C: Remove client-side Dial retry (simplification)

Since the server already retries, the client-side retry in lease.py:310-338 creates redundant Dial RPCs that waste server resources and can cause confusion in logs. If Option B is implemented, the client-side retry becomes unnecessary.

• This would be a follow-up change after Option B is stable

Additional Observations

1. The jmp shell command in the E2E test likely has an implicit timeout (the test itself fails at 31.5s), which becomes the effective gRPC context deadline for all Dial calls.

2. The WaitForExporters() helper (utils.go:521-527) correctly waits for Available status before proceeding, but this only ensures the exporter was available before the lease — not that it transitions to LEASE_READY promptly after.

3. There is no indication that PR Remove opendal dependency from QEMU driver #535 introduced a regression — the timing sensitivity was always present; PR Remove opendal dependency from QEMU driver #535 may have just changed timing enough to expose it more frequently on ARM CI runners.

Recommendation

Start with Option A as an immediate fix (one-line change, no risk), then implement Option B as a proper solution. Option C can be done as cleanup afterward.

[mangelajo]

option A sounds good

[ambient-code]

PR created with Option A fix (approved by @mangelajo): #542

This increases the server-side Dial retry maxTotalWait from 10s to 30s, aligning it with the client-side dial_timeout default.