Skip to content

Commit 02a515e

Browse files
Honor context when acquiring init semaphore
Queued backend init must not block on the semaphore after the session budget expires. Warn only on deadline exceeded; log caller cancel at debug. Co-authored-by: Ravi Tharuma <RaviTharuma@users.noreply.github.com>
1 parent 2e878b9 commit 02a515e

3 files changed

Lines changed: 145 additions & 6 deletions

File tree

pkg/vmcp/session/default_session_test.go

Lines changed: 56 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1186,6 +1186,62 @@ func TestNewSessionFactory_SessionInitTimeoutBoundsWait(t *testing.T) {
11861186
require.NoError(t, sess.Close())
11871187
}
11881188

1189+
func TestNewSessionFactory_SessionInitTimeoutSkipsQueuedSemaphoreAcquire(t *testing.T) {
1190+
t.Parallel()
1191+
1192+
// One in-flight backend holds the only semaphore slot until the session
1193+
// budget expires, then delays release so queued backends would hang on
1194+
// `sem <-` if acquire ignored ctx. Those queued connectors ignore ctx
1195+
// and sleep long enough that MakeSession would miss the budget.
1196+
const queuedSleep = 3 * time.Second
1197+
started := make(chan struct{})
1198+
var holderStarted atomic.Bool
1199+
var queuedEntered atomic.Int64
1200+
connector := func(ctx context.Context, _ *vmcp.BackendTarget, _ *auth.Identity, _ string, _ internalbk.ListChangedSink) (internalbk.Session, *vmcp.CapabilityList, error) {
1201+
if holderStarted.CompareAndSwap(false, true) {
1202+
close(started)
1203+
select {
1204+
case <-ctx.Done():
1205+
// Keep the slot occupied after expiry so queued
1206+
// acquire must lose to ctx.Done() in the select.
1207+
time.Sleep(150 * time.Millisecond)
1208+
return nil, nil, ctx.Err()
1209+
case <-time.After(30 * time.Second):
1210+
return nil, nil, errors.New("holder did not observe session budget")
1211+
}
1212+
}
1213+
queuedEntered.Add(1)
1214+
time.Sleep(queuedSleep)
1215+
return nil, nil, errors.New("queued backend ran after session budget")
1216+
}
1217+
1218+
backends := []*vmcp.Backend{
1219+
{ID: "holder", Name: "holder", BaseURL: "http://x:1", TransportType: "streamable-http"},
1220+
{ID: "queued-a", Name: "queued-a", BaseURL: "http://x:2", TransportType: "streamable-http"},
1221+
{ID: "queued-b", Name: "queued-b", BaseURL: "http://x:3", TransportType: "streamable-http"},
1222+
}
1223+
factory := newSessionFactoryWithConnector(connector,
1224+
WithSessionInitTimeout(80*time.Millisecond),
1225+
WithBackendInitTimeout(30*time.Second),
1226+
WithMaxBackendInitConcurrency(1),
1227+
)
1228+
1229+
start := time.Now()
1230+
sess, err := factory.MakeSessionWithID(context.Background(), uuid.New().String(), nil, backends, nil)
1231+
elapsed := time.Since(start)
1232+
1233+
require.NoError(t, err)
1234+
require.NotNil(t, sess)
1235+
select {
1236+
case <-started:
1237+
default:
1238+
t.Fatal("expected the in-flight backend to start before MakeSession returned")
1239+
}
1240+
assert.Zero(t, queuedEntered.Load(), "queued backends must not acquire the semaphore after the session budget expires")
1241+
assert.Less(t, elapsed, queuedSleep, "MakeSession must return without waiting for queued connectors")
1242+
require.NoError(t, sess.Close())
1243+
}
1244+
11891245
func TestValidateSessionID(t *testing.T) {
11901246
t.Parallel()
11911247

pkg/vmcp/session/factory.go

Lines changed: 19 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ package session
77

88
import (
99
"context"
10+
"errors"
1011
"fmt"
1112
"log/slog"
1213
"slices"
@@ -510,18 +511,30 @@ func (f *defaultMultiSessionFactory) makeBaseSession(
510511
for i, b := range backends {
511512
go func(i int, b *vmcp.Backend) {
512513
defer wg.Done()
513-
sem <- struct{}{}
514-
defer func() { <-sem }()
514+
// Acquire is context-aware so queued backends do not block on
515+
// the semaphore after sessionInitTimeout (or cancel) has fired.
516+
select {
517+
case sem <- struct{}{}:
518+
defer func() { <-sem }()
519+
case <-ctx.Done():
520+
return
521+
}
515522
rawResults[i], modernSkipped[i] = f.initOneBackend(ctx, b, identity, sessionHints[b.ID], sink)
516523
}(i, b)
517524
}
518525
wg.Wait()
519526

520527
if err := ctx.Err(); err != nil {
521-
slog.Warn("session initialize budget expired; returning with backends that connected in time",
522-
"error", err,
523-
"backendCount", len(backends),
524-
"timeout", f.sessionInitTimeout)
528+
if errors.Is(err, context.DeadlineExceeded) {
529+
slog.Warn("session initialize budget expired; returning with backends that connected in time",
530+
"error", err,
531+
"backendCount", len(backends),
532+
"timeout", f.sessionInitTimeout)
533+
} else {
534+
slog.Debug("session initialize cancelled; returning with backends that connected in time",
535+
"error", err,
536+
"backendCount", len(backends))
537+
}
525538
}
526539

527540
connections := make(map[string]backend.Session, len(backends))

pkg/vmcp/session/factory_revision_test.go

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import (
99
"errors"
1010
"log/slog"
1111
"testing"
12+
"time"
1213

1314
"github.com/google/uuid"
1415
"github.com/stretchr/testify/assert"
@@ -212,3 +213,72 @@ func TestMakeSession_AllBackendsFailedWarning(t *testing.T) {
212213
})
213214
}
214215
}
216+
217+
const (
218+
sessionBudgetExpiredMsg = "session initialize budget expired"
219+
sessionCancelledMsg = "session initialize cancelled"
220+
)
221+
222+
//nolint:paralleltest // setupLogRecorder swaps the global slog default logger.
223+
func TestMakeSession_SessionInitContextLogs(t *testing.T) {
224+
t.Run("deadline exceeded logs a warning", func(t *testing.T) {
225+
buf := setupLogRecorder(t)
226+
released := make(chan struct{})
227+
t.Cleanup(func() { close(released) })
228+
connector := func(ctx context.Context, _ *vmcp.BackendTarget, _ *auth.Identity, _ string, _ internalbk.ListChangedSink) (internalbk.Session, *vmcp.CapabilityList, error) {
229+
select {
230+
case <-ctx.Done():
231+
return nil, nil, ctx.Err()
232+
case <-released:
233+
return &mockConnectedBackend{}, &vmcp.CapabilityList{}, nil
234+
}
235+
}
236+
factory := newSessionFactoryWithConnector(connector, WithSessionInitTimeout(50*time.Millisecond))
237+
backend := &vmcp.Backend{ID: "slow", Name: "slow", BaseURL: "http://x:9", TransportType: "streamable-http"}
238+
239+
sess, err := factory.MakeSessionWithID(context.Background(), uuid.New().String(), nil, []*vmcp.Backend{backend}, nil)
240+
require.NoError(t, err)
241+
t.Cleanup(func() { _ = sess.Close() })
242+
243+
logs := buf.String()
244+
assert.Contains(t, logs, sessionBudgetExpiredMsg)
245+
assert.NotContains(t, logs, sessionCancelledMsg)
246+
})
247+
248+
t.Run("caller cancel logs at debug", func(t *testing.T) {
249+
buf := setupLogRecorder(t)
250+
entered := make(chan struct{})
251+
connector := func(ctx context.Context, _ *vmcp.BackendTarget, _ *auth.Identity, _ string, _ internalbk.ListChangedSink) (internalbk.Session, *vmcp.CapabilityList, error) {
252+
close(entered)
253+
<-ctx.Done()
254+
return nil, nil, ctx.Err()
255+
}
256+
factory := newSessionFactoryWithConnector(connector, WithSessionInitTimeout(30*time.Second))
257+
backend := &vmcp.Backend{ID: "slow", Name: "slow", BaseURL: "http://x:9", TransportType: "streamable-http"}
258+
259+
ctx, cancel := context.WithCancel(context.Background())
260+
errCh := make(chan error, 1)
261+
var sess MultiSession
262+
go func() {
263+
var err error
264+
sess, err = factory.MakeSessionWithID(ctx, uuid.New().String(), nil, []*vmcp.Backend{backend}, nil)
265+
errCh <- err
266+
}()
267+
select {
268+
case <-entered:
269+
case <-time.After(2 * time.Second):
270+
t.Fatal("timeout waiting for connector to start")
271+
}
272+
cancel()
273+
require.NoError(t, <-errCh)
274+
t.Cleanup(func() {
275+
if sess != nil {
276+
_ = sess.Close()
277+
}
278+
})
279+
280+
logs := buf.String()
281+
assert.Contains(t, logs, sessionCancelledMsg)
282+
assert.NotContains(t, logs, sessionBudgetExpiredMsg)
283+
})
284+
}

0 commit comments

Comments
 (0)