[BUG] Waiting here is unbounded, which removes the only timeout enforcement RIE has over the init phase.

The init phase has no deadline of its own: initContext.Wait() is documented as "Timeout handling is managed upstream entirely" (internal/lambda/rapidcore/sandbox_api.go), and rapid.handleInit blocks inside doRuntimeDomainInit until the runtime calls /next, the process exits, or a Reset cancels the flow. The only thing that issues that Reset in RIE is the timeout goroutine started inside Server.Invoke:

go func() {
select {
case <-time.After(s.GetInvokeTimeout()):
timeoutChan <- ErrInvokeTimeout
...

Because AwaitInitCompletion() now runs before sandbox.Invoke(...), that clock is never armed while init is pending. Concretely:

• Runtime hangs during init (bootstrap never calls /next, e.g. a blocking import): the HTTP request hangs forever with no response and no Reset. Previously the client got Task timed out after N seconds.
• Init is merely slower than the function timeout (say 30s init with AWS_LAMBDA_FUNCTION_TIMEOUT=3): the handler blocks for the full 30s, and only then does the 3s invoke timeout start counting, so the client can wait init duration + invoke timeout.

Bounding the wait keeps the fix while preserving the timeout path — on expiry, control falls through to Invoke, which arms its timer and drives the Reset/timeout response as before:

// rapidcore
func (s Server) AwaitInitCompletion(timeout time.Duration) {
select {
case <-s.initCompleted:
case <-time.After(timeout):
// init still running; Invoke() enforces the timeout and triggers the Reset
}
}

// rie
initStart := InitHandler(sandbox, functionVersion, timeout, bs)
sandbox.AwaitInitCompletion(timeoutDuration)

Note the reported value is already clamped with math.Min(..., timeoutDuration), so capping the wait does not change what gets printed in the successful case.

[CONCURRENCY] initCompleted is the only channel field on Server accessed without the mutex, and both of its unguarded accesses are reachable from different goroutines: it is assigned in Init (line 521), closed by the awaitInitCompletion goroutine (line 217), and received from here.

Two concrete problems:

1. Double close panic. close(s.initCompleted) re-reads the field at close time rather than using the channel the goroutine was started for. InvokeHandler is a plain net/http handler and initDone is an unsynchronized bool, so two concurrent first invokes can both reach Init. If the second Init replaces the field before the first goroutine closes it, both goroutines close the same channel and the process dies with panic: close of closed channel.
2. Blocking on a nil channel. If AwaitInitCompletion is ever reached without a preceding Init, <-s.initCompleted is a receive on a nil channel and blocks forever. Invoke guards the analogous case explicitly (if initFailures == nil { return ErrInitNotStarted }).

Following the existing setInitFailuresChan/getInitFailuresChan pattern and capturing the channel locally fixes both:

func (s Server) setInitCompletedChan() {
s.mutex.Lock()
defer s.mutex.Unlock()
s.initCompleted = make(chan struct{})
}

func (s Server) getInitCompletedChan() chan struct{} {
s.mutex.Lock()
defer s.mutex.Unlock()
return s.initCompleted
}

func (s Server) awaitInitCompletion() {
initCompleted := s.getInitCompletedChan() // capture before Wait()
initSuccess, initFailure := s.initContext.Wait()
close(initCompleted) // never closes a channel created by a later Init()
...
}

func (s Server) AwaitInitCompletion() {
if initCompleted := s.getInitCompletedChan(); initCompleted != nil {
<-initCompleted
}
}

[CONCURRENCY] The global initMutex is locked and unlocked without defer, with a call into the whole init path in between. net/http recovers panics in handler goroutines, so a panic anywhere inside InitHandler would kill only this request and leave initMutex locked forever — every subsequent invoke would then block on initMutex.Lock() and the emulator would be permanently wedged with no error surfaced.

This is not hypothetical for InitHandler: it indexes envVar[1] on strings.SplitN(env, "=", 2) for every entry of os.Environ(), which panics on an environ entry with no =.

Scoping the lock so it is always released is enough:

func startInitOnce(sandbox Sandbox, functionVersion string, timeout int64, bs interop.Bootstrap) time.Time {
initMutex.Lock()
defer initMutex.Unlock()

if initDone {
return time.Time{}
}
// Set initDone so next invokes do not try to Init the function again
initDone = true
return InitHandler(sandbox, functionVersion, timeout, bs)
}

Then the call site becomes initStart := startInitOnce(sandbox, functionVersion, timeout, bs), and the zero-time return keeps working with the existing initStart.IsZero() check in formatInitDuration.

[GENERAL] The timeout branch still passes the pre-init invokeStart to printEndReports, so this REPORT line counts the init window twice now that formatInitDuration measures real init completion.

invokeStart is captured at line 134, right after init is kicked off, and sandbox.Invoke blocks through the entire init phase. The success path compensates for that at line 227 by rebasing invokeStart to initEnd; this branch does not.

For a cold invoke that times out during init, Server.Invoke returns ErrInvokeTimeout only after Reset has cancelled the init flow (HandleReset calls CancelFlows before taking handlerExecutionMutex, so initContext.Wait() has already returned an InitFailure). AwaitInitCompletion() therefore returns the time init was aborted, roughly initStart + timeout. formatInitDuration caps that at timeoutDuration, and printEndReports independently caps now - invokeStart at the same value, so a 300 s timeout prints:

REPORT RequestId: ...Init Duration: 300000.00 msDuration: 300000.00 msBilled Duration: 300000 ms

The same elapsed wall clock is reported in both fields, and Init Duration is presented as a completed init when init was actually cancelled. Before this change the branch printed Init Duration: ~0.00 ms, so this is a new inconsistency specific to the timeout path.

Note that simply rebasing invokeStart here (as the success path does) would make Duration collapse to the reset time, which contradicts the Task timed out after N seconds body written two lines below. The cleaner fix is to distinguish a completed init from an aborted one — for example, have the completion signal carry whether init succeeded, and omit Init Duration (or report only the portion that elapsed before the deadline) when the init phase was terminated by the timeout reset — so that Init Duration and Duration never describe the same interval.

[GENERAL] Gating on initSucceeded drops Init Duration from the REPORT line entirely when the invoke times out during init, so the cold-start REPORT loses a field it has always had.

Tracing where this gate actually changes output: on the post-switch path (line 231), initSucceeded == false together with a non-zero initStart is unreachable — every init-failure path returns early through ErrInitDoneFailed or ErrInvokeDoneFailed, and warm invokes are already filtered by the initStart.IsZero() check inside formatInitDuration. That leaves this timeout branch as the only place the gate has an observable effect, and TestInvokeHandlerOmitsInitDurationWhenInitTimesOut locks the omission in.

Before this change RIE always printed an Init Duration on the first invoke (a near-zero value, since it stopped the clock when InitHandler returned). After it, a timeout during init prints:

REPORT RequestId: ...Duration: 1000.00 msBilled Duration: 1000 ms...

with no Init Duration at all, which diverges from the cloud REPORT line that RIE aims for parity with and can break anything parsing that field on a cold invoke.

The values needed are already valid here: awaitInitCompletion sets completedAt = time.Now() before closing done even on the reset-cancelled path, so initEnd is non-zero, and formatInitDuration already clamps to timeoutDuration. Dropping the gate yields the clamped init window rather than nothing:

case rapidcore.ErrInvokeTimeout:
initEnd,  := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
printEndReports(invokePayload.ID, initDuration, memorySize, invokeStart, timeoutDuration)

If omitting the field is deliberate, it is worth saying so explicitly — the reasoning in the PR discussion covered the Duration value for this branch, not the removal of Init Duration.

The core fix checks out: initContext.Wait() returns when the runtime calls /next, so Init Duration now spans runtime startup and user module loading. The earlier double-close, mutex-on-panic, and success-path Duration double-count findings are all genuinely resolved, and the completion signal is ordered before every blocking send in awaitInitCompletion, so I could not reproduce the unbounded-wait scenario in the current code.

[BUG] The timeout branch still reports Duration from the pre-init invokeStart, so a cold invoke that times out counts the init window twice on the same REPORT line.

invokeStart is captured at line 134, immediately after startInitOnce kicks off init, and sandbox.Invoke blocks through the entire init phase. The success path compensates for this at lines 228-230 by rebasing invokeStart to initEnd; this branch does not. Since printEndReports clamps to timeoutDuration and formatInitDuration does too, a cold start that times out during init now prints:

REPORT RequestId: ...Init Duration: 1000.00 msDuration: 1000.00 msBilled Duration: 1000 ms...

for a request whose total wall time was ~1 s. Before this change Init Duration was sub-millisecond (it only measured sandbox.Init returning), so the overlap was invisible; now that it measures real init completion the two fields overlap fully. The same line also presents an init that was aborted by the timeout reset as a completed init — initEnd here is the moment CancelFlows tore init down, not the moment the runtime finished loading.

Making the timeout branch use the same rebase keeps both fields inside a single timeout window (Init Duration + Duration ≈ timeout):

case rapidcore.ErrInvokeTimeout:
initEnd := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
if !initStart.IsZero() && initEnd.After(invokeStart) {
invokeStart = initEnd
}
printEndReports(invokePayload.ID, initDuration, memorySize, invokeStart, timeoutDuration)

If you would rather not report a duration for an init that never completed, the alternative is to suppress Init Duration on this branch instead — but the current combination of "full init duration" plus "full timeout duration" is the one outcome that cannot be reconciled with the elapsed time. Note that TestInvokeHandlerReportsInitDurationWhenInitTimesOut won't catch either variant today: it only asserts Init Duration is in (0, 1000] and that a Duration field is present, so it's worth asserting the relationship between the two values.

[GENERAL] The init-report block is now duplicated verbatim in two places — the timeout branch at lines 214-218 and here at 228-232:

initEnd := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
if !initStart.IsZero() && initEnd.After(invokeStart) {
invokeStart = initEnd
}
printEndReports(invokePayload.ID, initDuration, memorySize, invokeStart, timeoutDuration)

This duplication is what produced the divergences already found in this PR's earlier revisions (the timeout branch printed a pre-init invokeStart while the success path rebased it, and later the two paths disagreed on whether Init Duration was emitted at all). Any future change to the REPORT line has to be applied twice, and the compiler cannot catch a missed one — the symptom is a silently wrong number in a log line, which is exactly the class of bug this PR fixes.

Consolidating both callers into one helper keeps the two REPORT paths structurally unable to drift:

// printInvokeReport emits the END/REPORT lines, attributing the init window to
// Init Duration and the remainder to Duration.
func printInvokeReport(sandbox Sandbox, invokeID string, initStart time.Time, invokeStart time.Time, memorySize string, timeoutDuration time.Duration) {
initEnd := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
if !initStart.IsZero() && initEnd.After(invokeStart) {
invokeStart = initEnd
}
printEndReports(invokeID, initDuration, memorySize, invokeStart, timeoutDuration)
}

Both call sites then become a single line, and the timeout branch no longer needs to reassign invokeStart in the enclosing scope.

[GENERAL] This assertion bounds a wall-clock measurement of a 50 ms sleep to under 90 ms, leaving only ~40 ms of headroom:

sandbox := &delayedInitSandbox{
initDelay:   50  time.Millisecond,
invokeDelay: 50  time.Millisecond,
invokeErr:   rapidcore.ErrInvokeTimeout,
}
...
require.GreaterOrEqual(t, durationMilliseconds, float64(40))
require.Less(t, durationMilliseconds, float64(90))

time.Sleep only guarantees a lower bound. On a CPU-throttled container or a loaded CI runner, a 50 ms sleep plus goroutine rescheduling, GC, and the pipe/regexp work in the same measured window routinely overshoots by tens of milliseconds, so this will fail intermittently on an unrelated change. The test's actual intent — that the invocation window excludes the init window — is fully captured by the lower bound plus the existing sum check against the 1 s timeout.

Dropping the tight ceiling keeps the assertion meaningful without the timing dependency:

require.GreaterOrEqual(t, durationMilliseconds, float64(40))
require.LessOrEqual(t, initDurationMilliseconds+durationMilliseconds, float64(1020))

If an upper bound is still wanted to prove init time is not being double counted, comparing it against initDurationMilliseconds is more robust than a fixed millisecond ceiling, since both values scale together under load.

[GENERAL] This assertion couples two independent wall-clock measurements with a 1.5x ratio, which makes the test load-sensitive:

sandbox := &delayedInitSandbox{
initDelay:   50  time.Millisecond,
invokeDelay: 50  time.Millisecond,
invokeErr:   rapidcore.ErrInvokeTimeout,
}
...
require.GreaterOrEqual(t, durationMilliseconds, float64(40))
require.Less(t, durationMilliseconds, initDurationMilliseconds*1.5)

initDurationMilliseconds measures the initDelay sleep and durationMilliseconds measures the invokeDelay sleep. Both nominally land at ~50 ms, so the upper bound is effectively ~75 ms against a 50 ms measurement — roughly 25 ms of headroom. time.Sleep only guarantees a lower bound, and overshoot is not correlated between the two sleeps: on a contended CI runner (or under -race) the second sleep can overshoot by more than the first, failing the assertion even though the reporting logic is correct. The GreaterOrEqual bounds are safe because sleeps never undershoot; only this relative upper bound is fragile.

The property this test actually cares about is that Init Duration and Duration cover disjoint windows rather than double-counting init. That can be asserted against measured total elapsed time instead of a fixed ratio:

start := time.Now()
InvokeHandler(response, request, sandbox, nil)
elapsed := float64(time.Since(start)) / float64(time.Millisecond)
...
// no double counting: the two reported windows must fit inside real elapsed time
require.LessOrEqual(t, initDurationMilliseconds+durationMilliseconds, elapsed)

That keeps the regression coverage for the double-counting bug this PR fixes without depending on how precisely the two sleeps track each other.