Skip to content
Draft
Show file tree
Hide file tree
Changes from 4 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 8 additions & 0 deletions docs-website/router/metrics-and-monitoring.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -247,6 +247,14 @@ telemetry:

* `router.engine.messages.sent`: The number of total messages for subscriptions sent over from the subgraph to the router.

* `router.subscription.delivery.attempts`: Downstream subscription frame delivery attempts, tagged with `wg.subscription.transport`, `wg.subscription.frame_type`, and, for WebSockets, `wg.websocket.subprotocol`.

* `router.subscription.delivery.write.failures`: Downstream writes that the router knows failed. The bounded `wg.subscription.failure_stage` and `wg.subscription.failure_reason` dimensions distinguish deadline, serialization, write, and flush failures without attaching client or event identifiers to metrics.

* `router.subscription.disconnects`: Closed SSE requests and WebSocket connections, tagged with the transport, disconnect initiator, and disconnect reason. A WebSocket connection is counted once even when it carries multiple subscriptions.

Failed event writes also produce a structured `Subscription event delivery failed` log containing the request, connection, subscription, and event identifiers. Kafka offsets and NATS stream sequences are used when available; otherwise the router generates an occurrence ID. Payloads are represented by a SHA-256 hash and byte count and are not logged. A successful transport write means the router handed the frame to the connection; SSE and WebSocket do not provide application-level client acknowledgements.


### Resolver Metrics

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -122,6 +122,12 @@ telemetry:

* [`router_engine_messages_sent_total`](#router-engine-messages-sent-total): The number of total messages for subscriptions sent over from the subgraph to the router.

* `router_subscription_delivery_attempts_total`: The number of downstream SSE and WebSocket subscription frame delivery attempts.

* `router_subscription_delivery_write_failures_total`: The number of downstream subscription frame writes known to have failed.

* `router_subscription_disconnects_total`: The number of downstream SSE requests and WebSocket connections that closed, grouped by bounded initiator and reason dimensions.

### Resolver Metrics

These metrics expose usage of the GraphQL engine's resolver concurrency pool. Use them to detect when operations queue because the pool is saturated.
Expand Down
248 changes: 248 additions & 0 deletions router-tests/events/kafka_sse_write_timeout_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,248 @@
package events_test

import (
"bufio"
"context"
"errors"
"net/http"
"os"
"strings"
"sync"
"sync/atomic"
"testing"
"time"

"github.com/stretchr/testify/require"

"github.com/wundergraph/cosmo/router-tests/events"
"github.com/wundergraph/cosmo/router-tests/testenv"
"github.com/wundergraph/cosmo/router/core"
nodev1 "github.com/wundergraph/cosmo/router/gen/proto/wg/cosmo/node/v1"
"github.com/wundergraph/cosmo/router/pkg/config"
)

const blockSSEWriteHeader = "X-Test-Block-SSE-Write"

var (
_ core.Module = (*blockingSSEWriterModule)(nil)
_ core.RouterOnRequestHandler = (*blockingSSEWriterModule)(nil)
)

// blockingSSEWriterModule simulates a client that stops draining its SSE
// connection without closing it. The wrapped writer only returns when the
// router sets a write deadline or the test releases it during cleanup.
type blockingSSEWriterModule struct {
armed *atomic.Bool
writeStarted chan struct{}
startedOnce *sync.Once
release chan struct{}
}

func (m *blockingSSEWriterModule) Module() core.ModuleInfo {
return core.ModuleInfo{
ID: "blockingSSEWriterModule",
Priority: 1,
New: func() core.Module {
return &blockingSSEWriterModule{
armed: m.armed,
writeStarted: m.writeStarted,
startedOnce: m.startedOnce,
release: m.release,
}
},
}
}

func (m *blockingSSEWriterModule) RouterOnRequest(ctx core.RequestContext, next http.Handler) {
if ctx.Request().Header.Get(blockSSEWriteHeader) != "true" {
next.ServeHTTP(ctx.ResponseWriter(), ctx.Request())
return
}

next.ServeHTTP(&deadlineBlockingResponseWriter{
ResponseWriter: ctx.ResponseWriter(),
armed: m.armed,
writeStarted: m.writeStarted,
startedOnce: m.startedOnce,
release: m.release,
}, ctx.Request())
}

type deadlineBlockingResponseWriter struct {
http.ResponseWriter
armed *atomic.Bool
writeStarted chan struct{}
startedOnce *sync.Once
release chan struct{}
deadlineNanos atomic.Int64
}

func (w *deadlineBlockingResponseWriter) Write(data []byte) (int, error) {
if !w.armed.CompareAndSwap(true, false) {
return w.ResponseWriter.Write(data)
}

w.startedOnce.Do(func() { close(w.writeStarted) })
deadlineNanos := w.deadlineNanos.Load()
if deadlineNanos == 0 {
<-w.release
return 0, os.ErrDeadlineExceeded
}

wait := time.Until(time.Unix(0, deadlineNanos))
if wait <= 0 {
return 0, os.ErrDeadlineExceeded
}
timer := time.NewTimer(wait)
defer timer.Stop()
select {
case <-w.release:
return 0, os.ErrDeadlineExceeded
case <-timer.C:
return 0, os.ErrDeadlineExceeded
}
}

func (w *deadlineBlockingResponseWriter) Flush() {
if flusher, ok := w.ResponseWriter.(http.Flusher); ok {
flusher.Flush()
}
}

func (w *deadlineBlockingResponseWriter) FlushError() error {
if flusher, ok := w.ResponseWriter.(interface{ FlushError() error }); ok {
return flusher.FlushError()
}
w.Flush()
return nil
}

func (w *deadlineBlockingResponseWriter) SetWriteDeadline(deadline time.Time) error {
w.deadlineNanos.Store(deadline.UnixNano())
return nil
}

func (w *deadlineBlockingResponseWriter) Unwrap() http.ResponseWriter {
return w.ResponseWriter
}

func TestKafkaSubscriptionRecoversAfterSSEWriteTimeout(t *testing.T) {
if testing.Short() {
t.Skip("skipping Kafka integration test in short mode")
}

const topic = "employeeUpdated-sse-write-timeout"
armed := &atomic.Bool{}
writeStarted := make(chan struct{})
release := make(chan struct{})
var releaseOnce sync.Once
t.Cleanup(func() { releaseOnce.Do(func() { close(release) }) })

module := &blockingSSEWriterModule{
armed: armed,
writeStarted: writeStarted,
startedOnce: &sync.Once{},
release: release,
}

testenv.Run(t, &testenv.Config{
RouterConfigJSONTemplate: testenv.ConfigWithEdfsKafkaJSONTemplate,
EnableKafka: true,
RouterOptions: []core.Option{core.WithCustomModules(module)},
ModifyRouterConfig: func(routerConfig *nodev1.RouterConfig) {
overrideKafkaTopicsForField(t, routerConfig, "employeeUpdatedMyKafka",
[]string{"employeeUpdated", "employeeUpdatedTwo"}, topic)
},
ModifyEngineExecutionConfiguration: func(cfg *config.EngineExecutionConfiguration) {
cfg.SSEServerWriteTimeout = 100 * time.Millisecond
},
}, func(t *testing.T, xEnv *testenv.Environment) {
events.KafkaEnsureTopicExists(t, xEnv, EventWaitTimeout, topic)

ctx, cancel := context.WithCancel(t.Context())
defer cancel()
client := &http.Client{}
blockedResp := openSSESubscription(t, ctx, client, xEnv.GraphQLRequestURL(), true)
defer blockedResp.Body.Close()
healthyResp := openSSESubscription(t, ctx, client, xEnv.GraphQLRequestURL(), false)
defer healthyResp.Body.Close()
healthyReader := bufio.NewReader(healthyResp.Body)

xEnv.WaitForSubscriptionCount(2, EventWaitTimeout)
xEnv.WaitForTriggerCount(1, EventWaitTimeout)

armed.Store(true)
xEnv.KafkaPublishUntilReceived(topic,
`{"__typename":"Employee","id":1,"update":{"name":"blocked"}}`, 1, EventWaitTimeout)

select {
case <-writeStarted:
case <-time.After(EventWaitTimeout):
t.Fatal("timed out waiting for the SSE write to block")
}

require.Contains(t, readSSEData(t, healthyReader), `"id":1`)

xEnv.WaitForSubscriptionCount(1, EventWaitTimeout)
xEnv.KafkaPublishUntilReceived(topic,
`{"__typename":"Employee","id":2,"update":{"name":"recovery"}}`, 1, EventWaitTimeout)

recovery := make(chan string, 1)
go func() {
data, err := readSSEDataLine(healthyReader)
if err != nil {
recovery <- "error: " + err.Error()
return
}
recovery <- data
}()

select {
case data := <-recovery:
require.Contains(t, data, `"id":2`)
case <-time.After(EventWaitTimeout):
t.Fatal("healthy subscription did not receive the queued event after the SSE write deadline")
}
})
}

func openSSESubscription(t *testing.T, ctx context.Context, client *http.Client, url string, blocked bool) *http.Response {
t.Helper()
req, err := http.NewRequestWithContext(ctx, http.MethodPost, url,
strings.NewReader(`{"query":"subscription { employeeUpdatedMyKafka(employeeID: 3) { id } }"}`))
require.NoError(t, err)
req.Header.Set("Content-Type", "application/json")
req.Header.Set("Accept", "text/event-stream")
if blocked {
req.Header.Set(blockSSEWriteHeader, "true")
}

resp, err := client.Do(req)
require.NoError(t, err)
require.Equal(t, http.StatusOK, resp.StatusCode)
require.Equal(t, "text/event-stream", resp.Header.Get("Content-Type"))
return resp
}

func readSSEData(t *testing.T, reader *bufio.Reader) string {
t.Helper()
data, err := readSSEDataLine(reader)
require.NoError(t, err)
return data
}

func readSSEDataLine(reader *bufio.Reader) (string, error) {
for {
line, err := reader.ReadString('\n')
if err != nil {
return "", err
}
line = strings.TrimSpace(line)
if strings.HasPrefix(line, "data: ") {
return strings.TrimPrefix(line, "data: "), nil
}
if strings.HasPrefix(line, "event: complete") {
return "", errors.New("subscription completed before receiving data")
}
}
}
4 changes: 3 additions & 1 deletion router-tests/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -209,5 +209,7 @@ replace (
github.com/wundergraph/cosmo/router => ../router
github.com/wundergraph/cosmo/router-plugin => ../router-plugin
github.com/wundergraph/cosmo/speedtrap => ../speedtrap
// github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2
// Temporary preview dependency for https://github.com/wundergraph/graphql-go-tools/pull/1640.
// Remove this replacement after the delivery reporting API is released upstream.
github.com/wundergraph/graphql-go-tools/v2 => github.com/mwisner/graphql-go-tools/v2 v2.16.0-subscription-delivery-diagnostics.1
)
4 changes: 2 additions & 2 deletions router-tests/go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -246,6 +246,8 @@ github.com/modelcontextprotocol/go-sdk v1.7.0 h1:yqjY2dsbKAC0LSuWZVBMrHgiG8ukXv6
github.com/modelcontextprotocol/go-sdk v1.7.0/go.mod h1:dL7u98E/zjJTGzEq+j30jQ8K2k1mb6LeAH4inEcSGts=
github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA=
github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ=
github.com/mwisner/graphql-go-tools/v2 v2.16.0-subscription-delivery-diagnostics.1 h1:k8xCNsmuq5JCekSahOrHCFIhj1c9gcgR7GnFhxpwjL0=
github.com/mwisner/graphql-go-tools/v2 v2.16.0-subscription-delivery-diagnostics.1/go.mod h1:uKF6qMf1u7sC6E/NunkiLxBlWG9wrmWH5A/xHieHh+c=
github.com/nats-io/jwt/v2 v2.8.1 h1:V0xpGuD/N8Mi+fQNDynXohVvp7ZztevW5io8CUWlPmU=
github.com/nats-io/jwt/v2 v2.8.1/go.mod h1:nWnOEEiVMiKHQpnAy4eXlizVEtSfzacZ1Q43LIRavZg=
github.com/nats-io/nats-server/v2 v2.12.7 h1:prQ9cPiWHcnwfT81Wi5lU9LL8TLY+7pxDru6fQYLCQQ=
Expand Down Expand Up @@ -386,8 +388,6 @@ github.com/wundergraph/astjson v1.1.0 h1:xORDosrZ87zQFJwNGe/HIHXqzpdHOFmqWgykCLV
github.com/wundergraph/astjson v1.1.0/go.mod h1:h12D/dxxnedtLzsKyBLK7/Oe4TAoGpRVC9nDpDrZSWw=
github.com/wundergraph/go-arena v1.3.0 h1:n0ng5a1vbd8YGq1u3rMr0vPU5f6AZ1BXIiUhL1UIok8=
github.com/wundergraph/go-arena v1.3.0/go.mod h1:ROOysEHWJjLQ8FSfNxZCziagb7Qw2nXY3/vgKRh7eWw=
github.com/wundergraph/graphql-go-tools/v2 v2.16.0 h1:zZ8XuHGfkWkMrqKvy2vc5u//Z94/t01leQhrTTbVOxo=
github.com/wundergraph/graphql-go-tools/v2 v2.16.0/go.mod h1:Q0DH6cCkFM/LAUT2ETlo6AMIZhUklZczF2I6uWK9HSA=
github.com/xrash/smetrics v0.0.0-20250705151800-55b8f293f342 h1:FnBeRrxr7OU4VvAzt5X7s6266i6cSVkkFPS0TuXWbIg=
github.com/xrash/smetrics v0.0.0-20250705151800-55b8f293f342/go.mod h1:Ohn+xnUBiLI6FVj/9LpzZWtj1/D6lUovWYBkxHVV3aM=
github.com/yosida95/uritemplate/v3 v3.0.2 h1:Ed3Oyj9yrmi9087+NczuL5BwkIc4wvTb5zIM+UJPGz4=
Expand Down
1 change: 1 addition & 0 deletions router/core/graph_server.go
Original file line number Diff line number Diff line change
Expand Up @@ -1806,6 +1806,7 @@ func (s *graphServer) buildGraphMux(
SubgraphErrorPropagation: s.subgraphErrorPropagation,
EngineLoaderHooks: loaderHooks,
HeaderPropagation: s.headerPropagation,
SSEServerWriteTimeout: s.engineExecutionConfiguration.SSEServerWriteTimeout,
}

if s.redisClient != nil {
Expand Down
33 changes: 26 additions & 7 deletions router/core/graphql_handler.go
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,9 @@ import (
"net/http"
"strconv"
"strings"
"time"

"github.com/go-chi/chi/v5/middleware"
otelmetric "go.opentelemetry.io/otel/metric"
"go.opentelemetry.io/otel/trace"
"go.uber.org/zap"
Expand Down Expand Up @@ -87,6 +89,7 @@ type HandlerOptions struct {
EnableCostResponseHeaders bool

ApolloSubscriptionMultipartPrintBoundary bool
SSEServerWriteTimeout time.Duration
HeaderPropagation *HeaderPropagation
}

Expand All @@ -109,6 +112,7 @@ func NewGraphQLHandler(opts HandlerOptions) *GraphQLHandler {
subgraphErrorPropagation: opts.SubgraphErrorPropagation,
engineLoaderHooks: opts.EngineLoaderHooks,
apolloSubscriptionMultipartPrintBoundary: opts.ApolloSubscriptionMultipartPrintBoundary,
sseServerWriteTimeout: opts.SSEServerWriteTimeout,
headerPropagation: opts.HeaderPropagation,
}
return graphQLHandler
Expand Down Expand Up @@ -143,6 +147,7 @@ type GraphQLHandler struct {
enableCostResponseHeaders bool

apolloSubscriptionMultipartPrintBoundary bool
sseServerWriteTimeout time.Duration
}

func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
Expand Down Expand Up @@ -284,26 +289,40 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
}
case *plan.SubscriptionResponsePlan:
var (
writer resolve.SubscriptionResponseWriter
ok bool
writer resolve.SubscriptionResponseWriter
writerErr error
)
h.setDebugCacheHeaders(w, reqCtx.operation)

defer propagateSubgraphErrors(resolveCtx)
resolveCtx, writer, ok = GetSubscriptionResponseWriter(resolveCtx, r, w, h.apolloSubscriptionMultipartPrintBoundary)
if !ok {
reqCtx.logger.Error("unable to get subscription response writer", zap.Error(errCouldNotFlushResponse))
trackFinalResponseError(r.Context(), errCouldNotFlushResponse)
resolveCtx, writer, writerErr = GetSubscriptionResponseWriter(resolveCtx, r, w, SubscriptionResponseWriterOptions{
ApolloSubscriptionMultipartPrintBoundary: h.apolloSubscriptionMultipartPrintBoundary,
SSEWriteTimeout: h.sseServerWriteTimeout,
Logger: reqCtx.logger,
Stats: h.engineStats,
Telemetry: subscriptionTelemetryContext{
transport: subscriptionTransportSSE,
requestID: middleware.GetReqID(r.Context()),
operationName: reqCtx.operation.name,
writeTimeout: h.sseServerWriteTimeout,
},
})
if writerErr != nil {
reqCtx.logger.Error("unable to get subscription response writer", zap.Error(writerErr))
trackFinalResponseError(r.Context(), writerErr)
writeRequestErrors(writeRequestErrorsParams{
request: r,
writer: w,
statusCode: http.StatusInternalServerError,
requestErrors: graphqlerrors.RequestErrorsFromError(errCouldNotFlushResponse),
requestErrors: graphqlerrors.RequestErrorsFromError(writerErr),
logger: reqCtx.logger,
headerPropagation: h.headerPropagation,
})
return
}
if lifecycle, ok := writer.(*HttpFlushWriter); ok {
defer lifecycle.subscriptionRequestEnded()
}

if !resolveCtx.ExecutionOptions.SkipLoader {
h.engineStats.ConnectionsInc()
Expand Down
Loading
Loading