Skip to content

Commit ed8746b

Browse files
revit13Copilot
andauthored
test(coordinator): Fix request timeout for multimodal e2e specs (llm-d#2111)
* test(coordinator): raise request timeout for multimodal e2e specs Signed-off-by: Revital Sur <eres@il.ibm.com> * Use shutdown_timeout=1 Signed-off-by: Revital Sur <eres@il.ibm.com> * Dump EPP/Envoy logs and access log on failure Signed-off-by: Revital Sur <eres@il.ibm.com> * test(coordinator): create Services once to stop gateway DNS churn Signed-off-by: Revital Sur <eres@il.ibm.com> * Debug coordinator. Signed-off-by: Revital Sur <eres@il.ibm.com> * Add dumps Signed-off-by: Revital Sur <eres@il.ibm.com> * Add dump. Signed-off-by: Revital Sur <eres@il.ibm.com> * Add Stable-Service fix Signed-off-by: Revital Sur <eres@il.ibm.com> * Strip the diagnostics (Envoy access log, failure/end-of-spec dumps, dumpEnvoyClusters) Signed-off-by: Revital Sur <eres@il.ibm.com> * Fix lint. Signed-off-by: Revital Sur <eres@il.ibm.com> * Add Envoy access log, failure/end-of-spec dumps, dumpEnvoyClusters when the test fails. Signed-off-by: Revital Sur <eres@il.ibm.com> * Keep Services and RBAC stable across e2e specs Signed-off-by: Revital Sur <eres@il.ibm.com> * Minor changes. Signed-off-by: Revital Sur <eres@il.ibm.com> * Reuse DumpPodsAndLogs. Signed-off-by: Revital Sur <eres@il.ibm.com> * Add time to envoy access log. Signed-off-by: Revital Sur <eres@il.ibm.com> * Add access_log_flush_interval Signed-off-by: Revital Sur <eres@il.ibm.com> * Lower cluster connect_timeout Signed-off-by: Revital Sur <eres@il.ibm.com> * Update comments. Signed-off-by: Revital Sur <eres@il.ibm.com> * Rename E2E_PRINT_COORDINATOR_LOGS Signed-off-by: Revital Sur <eres@il.ibm.com> * Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> Signed-off-by: Revital Sur <eres@il.ibm.com> * Fix lint error. Signed-off-by: Revital Sur <eres@il.ibm.com> * Address review comments. Signed-off-by: Revital Sur <eres@il.ibm.com> * Remove dumpEnvoyClusters Signed-off-by: Revital Sur <eres@il.ibm.com> --------- Signed-off-by: Revital Sur <eres@il.ibm.com> Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
1 parent ae91966 commit ed8746b

8 files changed

Lines changed: 126 additions & 47 deletions

File tree

Makefile.coord.mk

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -116,7 +116,7 @@ endif
116116
# Env vars forwarded into the e2e test container.
117117
E2E_ENV_VARS = COORDINATOR_IMAGE VLLM_IMAGE EPP_IMAGE VLLM_RENDER_IMAGE VLLM_RENDER_PORT \
118118
E2E_GATEWAY_PORT E2E_KEEP_CLUSTER_ON_FAILURE \
119-
E2E_PRINT_COORDINATOR_LOGS K8S_CONTEXT READY_TIMEOUT MODEL_NAME
119+
E2E_PRINT_LOGS K8S_CONTEXT READY_TIMEOUT MODEL_NAME
120120
BUILDER_E2E_ENV_FLAGS = $(foreach v,$(E2E_ENV_VARS),$(if $($(v)),-e '$(v)=$($(v))'))
121121
ifneq ($(filter command line environment,$(origin NAMESPACE)),)
122122
BUILDER_E2E_ENV_FLAGS += -e NAMESPACE=$(NAMESPACE)

README.coord.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -341,7 +341,7 @@ kubectl --context kind-e2e-coordinator-tests get pods
341341
|---|---|---|
342342
| `E2E_KEEP_CLUSTER_ON_FAILURE` | `false` | Preserve the Kind cluster when the suite fails |
343343
| `E2E_GATEWAY_PORT` | `30080` | Host port mapped to the gateway NodePort |
344-
| `E2E_PRINT_COORDINATOR_LOGS` | `false` | Print coordinator pod logs during the run |
344+
| `E2E_PRINT_LOGS` | `false` | Print all pod logs (coordinator, EPPs, Envoy, workers) for every spec, not just on failure |
345345
| `CONTAINER_RUNTIME` | `docker` | Container runtime used to load images into Kind (`docker` or `podman`) |
346346
| `EPP_IMAGE` | `ghcr.io/llm-d/llm-d-router-endpoint-picker:dev` | EPP image loaded into the Kind cluster |
347347
| `VLLM_IMAGE` | `ghcr.io/llm-d/llm-d-inference-sim:v0.10.2` | vLLM image loaded into the Kind cluster |

test/coordinator/e2e/coordinator/configs_test.go

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,11 @@ server:
2323
listen_addr: ":8080"
2424
read_timeout: 30s
2525
write_timeout: 120s
26-
shutdown_timeout: 25s
26+
# Recreated per spec behind a suite-lived Envoy; drain fast so a deleted
27+
# coordinator stops serving immediately instead of lingering on a stale
28+
# endpoint the gateway may still route to. 0s is avoided: it makes the
29+
# server Shutdown context expire instantly and the process exit non-zero.
30+
shutdown_timeout: 1s
2731
2832
gateway:
2933
address: "http://envoy.${NAMESPACE}.svc:8081"

test/coordinator/e2e/coordinator/coordinator_test.go

Lines changed: 5 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -121,23 +121,14 @@ func runCoordinatorPipeline(body []byte, expectedSteps []string, expectedImages
121121
testutils.DeleteObjects(testConfig, encodePool, nsName)
122122
})
123123

124-
// Dump coordinator logs on failure, or always when E2E_PRINT_COORDINATOR_LOGS is
125-
// set. Registered second → runs first (LIFO), so the deployment still exists.
124+
// Dump all pod logs (coordinator, EPPs, Envoy, workers) on failure, or always
125+
// when E2E_PRINT_LOGS is set. Registered second → runs first (LIFO), so the
126+
// pods still exist.
126127
ginkgo.DeferCleanup(func() {
127-
if !ginkgo.CurrentSpecReport().Failed() && !printCoordinatorLogs {
128+
if !ginkgo.CurrentSpecReport().Failed() && !printLogs {
128129
return
129130
}
130-
args := []string{"logs", "deployment/llm-d-coordinator",
131-
"-c", "coordinator", "--namespace=" + nsName}
132-
if k8sContext != "" {
133-
args = append(args, "--context="+k8sContext)
134-
}
135-
out, err := exec.Command("kubectl", args...).CombinedOutput()
136-
if err != nil {
137-
fmt.Fprintf(ginkgo.GinkgoWriter, "\n--- coordinator logs (kubectl error: %v) ---\n%s\n---\n", err, string(out))
138-
} else {
139-
fmt.Fprintf(ginkgo.GinkgoWriter, "\n--- coordinator logs ---\n%s\n---\n", string(out))
140-
}
131+
testutils.DumpPodsAndLogs(testConfig, nsName, testutils.WithFullLogs())
141132
})
142133

143134
// Pools first so each EPP can resolve its --pool-name.

test/coordinator/e2e/coordinator/e2e_suite_test.go

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -79,7 +79,7 @@ var (
7979
testConfig *testutils.TestConfig
8080

8181
keepClusterOnFailure = env.GetEnvBool("E2E_KEEP_CLUSTER_ON_FAILURE", false, ginkgo.GinkgoLogr)
82-
printCoordinatorLogs = env.GetEnvBool("E2E_PRINT_COORDINATOR_LOGS", false, ginkgo.GinkgoLogr)
82+
printLogs = env.GetEnvBool("E2E_PRINT_LOGS", false, ginkgo.GinkgoLogr)
8383

8484
containerRuntime = env.GetEnvString("CONTAINER_RUNTIME", "docker", ginkgo.GinkgoLogr)
8585
eppImage = env.GetEnvString("EPP_IMAGE", "ghcr.io/llm-d/llm-d-router-endpoint-picker:dev", ginkgo.GinkgoLogr)
@@ -99,6 +99,7 @@ var (
9999

100100
portForwardSessions []*gexec.Session
101101
rendererObjects []string
102+
stableInfraObjects []string
102103
createdNameSpace bool
103104
)
104105

@@ -131,6 +132,10 @@ var _ = ginkgo.BeforeSuite(func() {
131132
}
132133

133134
rendererObjects = createRenderer()
135+
136+
// Coordinator and EPP Services/RBAC are created once and kept stable across
137+
// specs (see createStableInfra).
138+
createStableInfra()
134139
})
135140

136141
var _ = ginkgo.ReportAfterSuite("cleanup", func(report ginkgo.Report) {
@@ -148,6 +153,9 @@ var _ = ginkgo.ReportAfterSuite("cleanup", func(report ginkgo.Report) {
148153
if len(rendererObjects) > 0 {
149154
testutils.DeleteObjects(testConfig, rendererObjects, nsName)
150155
}
156+
if len(stableInfraObjects) > 0 {
157+
testutils.DeleteObjects(testConfig, stableInfraObjects, nsName)
158+
}
151159
for _, session := range portForwardSessions {
152160
session.Terminate()
153161
}

test/coordinator/e2e/coordinator/setup_test.go

Lines changed: 40 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -80,10 +80,10 @@ func createCRDs() {
8080
_ = testutils.CreateObjsFromYaml(testConfig, gieCRDs, "")
8181
}
8282

83-
// createEndPointPicker creates the scheduling ConfigMap and EPP Deployment (plus
84-
// its ServiceAccount, RoleBinding, and Service) for the given phase from the
85-
// supplied EPP config and waits for the EPP Deployment to become ready. Returns
86-
// the created object ids for cleanup.
83+
// createEndPointPicker creates the scheduling ConfigMap and EPP Deployment for
84+
// the given phase from the supplied EPP config and waits for the EPP Deployment
85+
// to become ready. Its ServiceAccount, RoleBinding, and Service are created once
86+
// by createStableInfra. Returns the created object ids for cleanup.
8787
func createEndPointPicker(phase, config string) []string {
8888
manifest := map[string]string{
8989
"encode": encodeEPPManifest,
@@ -96,7 +96,9 @@ func createEndPointPicker(phase, config string) []string {
9696

9797
objects := make([]string, 1, 8)
9898
objects[0] = "ConfigMap/" + cmName
99-
objects = append(objects, applyManifest(manifest, eppSubstitutions())...)
99+
// The Service, ServiceAccount, and RoleBinding are created once by
100+
// createStableInfra; recreate only the Deployment per spec.
101+
objects = append(objects, applyManifest(manifest, eppSubstitutions(), "Service", "ServiceAccount", "RoleBinding")...)
100102
podsInDeploymentsReady(objects)
101103
return objects
102104
}
@@ -154,8 +156,8 @@ func createModelServers(encodeReplicas, prefillReplicas, decodeReplicas int) []s
154156
}
155157

156158
// createCoordinator builds the coordinator ConfigMap from the given pipeline
157-
// config, deploys the coordinator component (Deployment + Service + SA), and
158-
// waits for readiness.
159+
// config, deploys the coordinator Deployment, and waits for readiness. Its
160+
// Service and ServiceAccount are created once by createStableInfra.
159161
func createCoordinator(config string) []string {
160162
nsName := getNamespace()
161163
coordinatorYAML := e2eutil.SubstituteMany([]string{config}, map[string]string{
@@ -177,7 +179,9 @@ func createCoordinator(config string) []string {
177179
objects[0] = "ConfigMap/llm-d-coordinator-config"
178180

179181
docs := e2eutil.RunKustomize(coordinatorComponentDir)
180-
docs = e2eutil.FilterKinds(docs, "ConfigMap")
182+
// Service and ServiceAccount are created once by createStableInfra; recreate
183+
// only the Deployment per spec.
184+
docs = e2eutil.FilterKinds(docs, "ConfigMap", "Service", "ServiceAccount")
181185
docs = e2eutil.SubstituteMany(docs, coordinatorSubstitutions())
182186
docs = e2eutil.RemoveEmptyArgs(docs)
183187
objects = append(objects, testutils.CreateObjsFromYaml(testConfig, docs, nsName)...)
@@ -188,8 +192,11 @@ func createCoordinator(config string) []string {
188192
}
189193

190194
// waitForCoordinatorReady polls /readyz through Envoy until it returns 200,
191-
// catching Envoy's STRICT_DNS resolution lagging behind the per-test Service
192-
// (podsInDeploymentsReady already confirms the coordinator pod itself is ready).
195+
// confirming the freshly recreated coordinator pod is reachable through the
196+
// gateway before the test sends its request. The gateway Service is stable
197+
// across specs (see createStableInfra), so this waits only for the new pod to
198+
// appear behind it. (podsInDeploymentsReady already confirms the coordinator
199+
// pod itself is ready.)
193200
func waitForCoordinatorReady() {
194201
ginkgo.By("Waiting for coordinator to be reachable via gateway")
195202
gomega.Eventually(func() bool {
@@ -222,13 +229,35 @@ func createEPPConfigMap(name, content string) {
222229
}
223230
}
224231

225-
func applyManifest(path string, subs map[string]string) []string {
232+
func applyManifest(path string, subs map[string]string, excludeKinds ...string) []string {
226233
docs := testutils.ReadYaml(path)
227234
docs = e2eutil.SubstituteMany(docs, subs)
228235
docs = e2eutil.RemoveEmptyArgs(docs)
236+
docs = e2eutil.FilterKinds(docs, excludeKinds...)
229237
return testutils.CreateObjsFromYaml(testConfig, docs, getNamespace())
230238
}
231239

240+
// createStableInfra creates the coordinator and per-phase EPP Services,
241+
// ServiceAccounts, and RoleBindings once, up front. It appends each created id to
242+
// stableInfraObjects as it goes rather than returning them at the end, so a
243+
// partial failure still leaves the already-created objects tracked for suite
244+
// teardown. Envoy fronts the Services via STRICT_DNS clusters and outlives the
245+
// per-spec workload; recreating a Service each spec would rotate its ClusterIP and
246+
// force Envoy to re-resolve, so only the Deployments behind them churn per spec.
247+
// Mirrors the non-coordinator e2e, which creates the EPP Services and RBAC once in
248+
// its setup and recreates only the Deployment per test.
249+
func createStableInfra() {
250+
docs := e2eutil.RunKustomize(coordinatorComponentDir)
251+
docs = e2eutil.FilterKinds(docs, "ConfigMap", "Deployment")
252+
docs = e2eutil.SubstituteMany(docs, coordinatorSubstitutions())
253+
docs = e2eutil.RemoveEmptyArgs(docs)
254+
stableInfraObjects = append(stableInfraObjects, testutils.CreateObjsFromYaml(testConfig, docs, getNamespace())...)
255+
256+
for _, manifest := range []string{encodeEPPManifest, prefillEPPManifest, decodeEPPManifest} {
257+
stableInfraObjects = append(stableInfraObjects, applyManifest(manifest, eppSubstitutions(), "Deployment")...)
258+
}
259+
}
260+
232261
func eppSubstitutions() map[string]string {
233262
return map[string]string{
234263
"${EPP_NAME}": eppName,

test/coordinator/e2e/coordinator/testdata/envoy.yaml

Lines changed: 24 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -80,6 +80,18 @@ data:
8080
"@type": type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager
8181
stat_prefix: http-8081
8282
preserve_external_request_id: true
83+
access_log:
84+
- name: envoy.access_loggers.stdout
85+
typed_config:
86+
"@type": type.googleapis.com/envoy.extensions.access_loggers.stream.v3.StdoutAccessLog
87+
log_format:
88+
text_format_source:
89+
inline_string: "[envoy] %START_TIME(%s.%3f)% %REQ(:METHOD)% %REQ(:PATH)% code=%RESPONSE_CODE% flags=%RESPONSE_FLAGS% cluster=%UPSTREAM_CLUSTER% upstream=%UPSTREAM_HOST% epp-phase=%REQ(EPP-PHASE)% id=%REQ(X-REQUEST-ID)% dur=%DURATION%\n"
90+
access_log_options:
91+
# Emit periodic access-log entries for in-flight streams so a
92+
# request that hangs (never terminates) is still recorded,
93+
# instead of only being logged on completion/disconnect.
94+
access_log_flush_interval: 5s
8395
route_config:
8496
name: vllm
8597
virtual_hosts:
@@ -162,6 +174,14 @@ data:
162174
cluster: coordinator
163175
timeout: 86400s
164176
idle_timeout: 86400s
177+
# Retry a failed upstream connection on a fresh one so a
178+
# transient connect hiccup to the coordinator ClusterIP is
179+
# ridden out instead of hanging the request. connect-failure
180+
# is safe for the non-idempotent POST: the connect never
181+
# completed, so no bytes reached the coordinator.
182+
retry_policy:
183+
retry_on: "connect-failure"
184+
num_retries: 3
165185
upgrade_configs:
166186
- upgrade_type: websocket
167187
typed_per_filter_config:
@@ -235,7 +255,10 @@ data:
235255
# the default (no EPP-Phase) route as the pipeline entry point.
236256
- name: coordinator
237257
type: STRICT_DNS
238-
connect_timeout: 1000s
258+
# Fail a stuck connect quickly (paired with the route retry_policy) so a
259+
# transient inability to open a connection to the coordinator ClusterIP is
260+
# retried on a fresh connection instead of hanging until the client times out.
261+
connect_timeout: 5s
239262
lb_policy: LEAST_REQUEST
240263
load_assignment:
241264
cluster_name: coordinator

test/utils/dump.go

Lines changed: 41 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -37,15 +37,36 @@ const (
3737
dumpLimitBytes = int64(1 << 20) // 1MiB
3838
)
3939

40+
// dumpConfig controls how much container log DumpPodsAndLogs fetches.
41+
type dumpConfig struct {
42+
tailLines int64
43+
limitBytes int64
44+
}
45+
46+
// DumpOption overrides DumpPodsAndLogs defaults.
47+
type DumpOption func(*dumpConfig)
48+
49+
// WithFullLogs streams complete container logs instead of the default tail, for
50+
// callers that need the entire log (e.g. a gateway access log). A non-positive
51+
// tail/limit disables that cap.
52+
func WithFullLogs() DumpOption {
53+
return func(c *dumpConfig) { c.tailLines, c.limitBytes = 0, 0 }
54+
}
55+
4056
// DumpPodsAndLogs prints pod statuses and container logs for the given namespace
4157
// to the Ginkgo writer. Call this before cleanup to ensure the information is
4258
// available when CI tests fail.
43-
func DumpPodsAndLogs(cfg *TestConfig, nsName string) {
59+
func DumpPodsAndLogs(cfg *TestConfig, nsName string, opts ...DumpOption) {
4460
if cfg == nil || cfg.KubeCli == nil {
4561
ginkgo.GinkgoWriter.Println("Skipping pod dump: cluster not initialized")
4662
return
4763
}
4864

65+
dc := dumpConfig{tailLines: dumpTailLines, limitBytes: dumpLimitBytes}
66+
for _, opt := range opts {
67+
opt(&dc)
68+
}
69+
4970
ginkgo.GinkgoWriter.Printf("\n=== Dumping pod states and logs (namespace: %s) ===\n", nsName)
5071

5172
ctx, cancel := context.WithTimeout(cfg.Context, dumpTimeout)
@@ -113,15 +134,15 @@ func DumpPodsAndLogs(cfg *TestConfig, nsName string) {
113134

114135
for _, c := range pod.Spec.InitContainers {
115136
if restarted[c.Name] {
116-
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, true)
137+
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, true, dc)
117138
}
118-
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, false)
139+
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, false, dc)
119140
}
120141
for _, c := range pod.Spec.Containers {
121142
if restarted[c.Name] {
122-
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, true)
143+
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, true, dc)
123144
}
124-
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, false)
145+
dumpContainerLogs(ctx, cfg, pod.Namespace, pod.Name, c.Name, false, dc)
125146
}
126147
}
127148
ginkgo.GinkgoWriter.Println("=== End of pod dump ===")
@@ -138,15 +159,15 @@ func printContainerStatus(kind string, cs corev1.ContainerStatus) {
138159
ginkgo.GinkgoWriter.Println(status)
139160
}
140161

141-
func dumpContainerLogs(ctx context.Context, cfg *TestConfig, nsName, podName, containerName string, previous bool) {
142-
tailLines := dumpTailLines
143-
limitBytes := dumpLimitBytes
144-
req := cfg.KubeCli.CoreV1().Pods(nsName).GetLogs(podName, &corev1.PodLogOptions{
145-
Container: containerName,
146-
TailLines: &tailLines,
147-
LimitBytes: &limitBytes,
148-
Previous: previous,
149-
})
162+
func dumpContainerLogs(ctx context.Context, cfg *TestConfig, nsName, podName, containerName string, previous bool, dc dumpConfig) {
163+
logOpts := &corev1.PodLogOptions{Container: containerName, Previous: previous}
164+
if dc.tailLines > 0 {
165+
logOpts.TailLines = &dc.tailLines
166+
}
167+
if dc.limitBytes > 0 {
168+
logOpts.LimitBytes = &dc.limitBytes
169+
}
170+
req := cfg.KubeCli.CoreV1().Pods(nsName).GetLogs(podName, logOpts)
150171
stream, err := req.Stream(ctx)
151172
if err != nil {
152173
ginkgo.GinkgoWriter.Printf(" [logs] %s/%s: failed to stream logs: %v\n", podName, containerName, err)
@@ -163,9 +184,12 @@ func dumpContainerLogs(ctx context.Context, cfg *TestConfig, nsName, podName, co
163184
ginkgo.GinkgoWriter.Printf(" [logs] %s/%s: failed to read logs: %v\n", podName, containerName, err)
164185
return
165186
}
166-
label := fmt.Sprintf("last %d lines", dumpTailLines)
187+
scope := "full log"
188+
if dc.tailLines > 0 {
189+
scope = fmt.Sprintf("last %d lines", dc.tailLines)
190+
}
167191
if previous {
168-
label = fmt.Sprintf("previous instance, last %d lines", dumpTailLines)
192+
scope = "previous instance, " + scope
169193
}
170-
ginkgo.GinkgoWriter.Printf(" [logs] %s/%s (%s):\n%s\n", podName, containerName, label, buf.String())
194+
ginkgo.GinkgoWriter.Printf(" [logs] %s/%s (%s):\n%s\n", podName, containerName, scope, buf.String())
171195
}

0 commit comments

Comments
 (0)