Component(s)
router
Component version
router@0.341.0
wgc version
n/a (not involved)
controlplane version
n/a (not used)
router version
router@0.341.0
What happened?
Description
The supervisor builds the shutdown context as context.WithTimeout(context.Background(), ShutdownDelay) (supervisor.go:109) and hands it to router.Shutdown, which derives its own deadline from it with context.WithTimeout(ctx, GracePeriod) (router.go:1871-1876). A child context cannot outlive its parent, so the effective grace period is min(grace_period, shutdown_delay). There is no cross-field validation of the two in router/pkg/config.
Two log messages fire on that deadline, giving opposite advice. The router logs "Consider increasing the grace period" (router.go:1881-1884) and the supervisor logs "Consider increasing the shutdown delay" (supervisor.go:165-168). They come from the same deadline: the router's error is wrapped with %w (supervisor.go:115) and reaches the supervisor's errors.Is check.
The shipped defaults satisfy the ordering, shutdown_delay: 60s and grace_period: 30s (config.go:1544-1545), so default installs are not affected by the truncation. The contradictory warning pair is not limited to the inverted case though: any shutdown that outruns the grace period produces both lines.
The documented example does not satisfy the ordering. configuration.mdx:169-170 shows shutdown_delay: 15s with grace_period: 20s, on a page whose table states the constraint from both sides: shutdown_delay "Should be higher than GRACE_PERIOD", grace_period "Should be smaller than SHUTDOWN_DELAY" (configuration.mdx:142-143). The Kubernetes page's example is also non-default, GRACE_PERIOD=20s and SHUTDOWN_DELAY=30s (deployment.mdx:50-56), and it does satisfy the ordering, so this looks like one example that drifted rather than a house style. The same pair appears in a user config posted in #1719, filed about something else.
I found this reading the shutdown path while learning Cosmo, then confirmed it by running the router with the documented example values.
Steps to Reproduce
- Run router 0.341.0 with
shutdown_delay: 15s and grace_period: 20s (the values from the docs example), dev_mode: true, and a static execution config.
- Point a subgraph at a handler that sleeps 40s, and send it a query.
SIGTERM the router while that request is in flight.
Expected Result
Either grace_period is honoured as configured, or the router warns at startup when grace_period >= shutdown_delay.
Actual Result
Shutdown ends 15.14s after SIGTERM. The in-flight request is killed rather than drained; curl returns (52) Empty reply from server.
Both warnings fire in the same second, giving opposite advice. Following the first one would have changed nothing.
Nothing logs an effective deadline. graph_server.go:2246 prints {"grace_period": "20s"} in the same second the 15s deadline fires, so from the log alone it looks like a 20s grace period was in force and was somehow exceeded 15s after SIGTERM.
There is also no output at all between SIGTERM and exit, and graph_server.go:2234 "Waiting for in-flight requests to finish" is timestamped after the wait had already timed out.
The final error confirms the wait never completed: failed to shutdown router gracefully: ... failed to wait for in-flight requests: context deadline exceeded.
Both values appear in the log and neither line says which bound: supervisor.go:112 logs {"shutdown_delay": "15s"} at SIGTERM, and 15s later graph_server.go:2246 logs {"grace_period": "20s"}.
Environment information
Environment
OS: Ubuntu 20.04
Router: 0.341.0, prebuilt linux-amd64 binary
Package Manager: n/a, prebuilt binary
Compiler: n/a, not compiled locally
Execution config: static file, no control plane
Subgraph: minimal Python HTTP handler sleeping 40s, to hold a request in flight
Source read at e7b12b1
Router configuration
version: "1"
dev_mode: true
listen_addr: "localhost:3002"
shutdown_delay: 15s
grace_period: 20s
execution_config:
file:
path: "execution-config.json"
telemetry:
tracing:
enabled: falseRouter execution config
Static file (router-tests testdata), not fetched via wgc.
Log output
SIGTERM at 16:02:26.405, process exit at 16:02:41.545. Elapsed: 15.14s.
In-flight `curl` returned `(52) Empty reply from server`.
Repetitive `sseTransport.closeAll` DEBUG lines trimmed; ANSI colour escapes stripped. Nothing else altered.
18:02:26 INFO core/supervisor.go:192 Stopping Router {"service_version": "0.341.0", "component": "supervisor"}
18:02:26 DEBUG core/supervisor.go:159 Got shutdown signal {"component": "supervisor", "shutdown": true}
18:02:26 INFO core/supervisor.go:112 Graceful shutdown of router initiated {"component": "supervisor", "shutdown_delay": "15s"}
[ no output at all for 15 seconds ]
18:02:41 DEBUG core/graph_server.go:2234 Shutdown of graph server initiated. Waiting for in-flight requests to finish.
18:02:41 DEBUG core/graph_server.go:2246 Shutdown of graph server resources {"grace_period": "20s"}
18:02:41 DEBUG core/graph_server.go:2298 shutting down graph mux {"mux": ""}
18:02:41 DEBUG core/graph_server.go:2311 Stopping old plugins
18:02:41 WARN core/router.go:1881 Shutdown deadline exceeded. Router took too long to shutdown. Consider increasing the grace period {"grace_period": 20}
18:02:41 WARN core/supervisor.go:167 Router shutdown deadline exceeded. Consider increasing the shutdown delay {"component": "supervisor"}
18:02:41 ERROR cmd/main.go:238 Could not shutdown router gracefully {"error": "failed to stop router: failed to shutdown router gracefully: failed to shutdown router: context deadline exceeded\nfailed to wait for in-flight requests: context deadline exceeded"}Additional context
Related, same area: config.schema.json:1995-1999 documents the grace_period default as 20s, while config.go:1545 sets 30s.
Happy to send a one-line PR for the schema default, and one fixing the example on the config page, if you'd like them.
Component(s)
router
Component version
router@0.341.0
wgc version
n/a (not involved)
controlplane version
n/a (not used)
router version
router@0.341.0
What happened?
Description
The supervisor builds the shutdown context as
context.WithTimeout(context.Background(), ShutdownDelay)(supervisor.go:109) and hands it torouter.Shutdown, which derives its own deadline from it withcontext.WithTimeout(ctx, GracePeriod)(router.go:1871-1876). A child context cannot outlive its parent, so the effective grace period ismin(grace_period, shutdown_delay). There is no cross-field validation of the two inrouter/pkg/config.Two log messages fire on that deadline, giving opposite advice. The router logs "Consider increasing the grace period" (router.go:1881-1884) and the supervisor logs "Consider increasing the shutdown delay" (supervisor.go:165-168). They come from the same deadline: the router's error is wrapped with
%w(supervisor.go:115) and reaches the supervisor'serrors.Ischeck.The shipped defaults satisfy the ordering,
shutdown_delay: 60sandgrace_period: 30s(config.go:1544-1545), so default installs are not affected by the truncation. The contradictory warning pair is not limited to the inverted case though: any shutdown that outruns the grace period produces both lines.The documented example does not satisfy the ordering. configuration.mdx:169-170 shows
shutdown_delay: 15swithgrace_period: 20s, on a page whose table states the constraint from both sides:shutdown_delay"Should be higher than GRACE_PERIOD",grace_period"Should be smaller than SHUTDOWN_DELAY" (configuration.mdx:142-143). The Kubernetes page's example is also non-default,GRACE_PERIOD=20sandSHUTDOWN_DELAY=30s(deployment.mdx:50-56), and it does satisfy the ordering, so this looks like one example that drifted rather than a house style. The same pair appears in a user config posted in #1719, filed about something else.I found this reading the shutdown path while learning Cosmo, then confirmed it by running the router with the documented example values.
Steps to Reproduce
shutdown_delay: 15sandgrace_period: 20s(the values from the docs example),dev_mode: true, and a static execution config.SIGTERMthe router while that request is in flight.Expected Result
Either
grace_periodis honoured as configured, or the router warns at startup whengrace_period >= shutdown_delay.Actual Result
Shutdown ends 15.14s after SIGTERM. The in-flight request is killed rather than drained;
curlreturns(52) Empty reply from server.Both warnings fire in the same second, giving opposite advice. Following the first one would have changed nothing.
Nothing logs an effective deadline.
graph_server.go:2246prints{"grace_period": "20s"}in the same second the 15s deadline fires, so from the log alone it looks like a 20s grace period was in force and was somehow exceeded 15s after SIGTERM.There is also no output at all between SIGTERM and exit, and
graph_server.go:2234"Waiting for in-flight requests to finish" is timestamped after the wait had already timed out.The final error confirms the wait never completed:
failed to shutdown router gracefully: ... failed to wait for in-flight requests: context deadline exceeded.Both values appear in the log and neither line says which bound:
supervisor.go:112logs{"shutdown_delay": "15s"}at SIGTERM, and 15s latergraph_server.go:2246logs{"grace_period": "20s"}.Environment information
Environment
OS: Ubuntu 20.04
Router: 0.341.0, prebuilt linux-amd64 binary
Package Manager: n/a, prebuilt binary
Compiler: n/a, not compiled locally
Execution config: static file, no control plane
Subgraph: minimal Python HTTP handler sleeping 40s, to hold a request in flight
Source read at e7b12b1
Router configuration
Router execution config
Static file (router-tests testdata), not fetched via wgc.Log output
Additional context
Related, same area: config.schema.json:1995-1999 documents the
grace_perioddefault as20s, while config.go:1545 sets30s.Happy to send a one-line PR for the schema default, and one fixing the example on the config page, if you'd like them.