From 23b57c019b30acfcf9c6ed409f4624a8e7120309 Mon Sep 17 00:00:00 2001 From: Matt Wisner Date: Thu, 20 Aug 2026 06:24:37 -0400 Subject: [PATCH 1/5] fix(router): add SSE server write timeout --- .../events/kafka_sse_write_timeout_test.go | 249 ++++++++++++++++++ router/core/graph_server.go | 1 + router/core/graphql_handler.go | 21 +- router/core/subscription_response_writer.go | 100 +++++-- .../core/subscription_response_writer_test.go | 101 ++++++- router/pkg/config/config.go | 1 + router/pkg/config/config.schema.json | 6 + router/pkg/config/fixtures/full.yaml | 1 + .../pkg/config/testdata/config_defaults.json | 1 + router/pkg/config/testdata/config_full.json | 1 + 10 files changed, 446 insertions(+), 36 deletions(-) create mode 100644 router-tests/events/kafka_sse_write_timeout_test.go diff --git a/router-tests/events/kafka_sse_write_timeout_test.go b/router-tests/events/kafka_sse_write_timeout_test.go new file mode 100644 index 0000000000..e8148a7557 --- /dev/null +++ b/router-tests/events/kafka_sse_write_timeout_test.go @@ -0,0 +1,249 @@ +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`) + + events.ProduceKafkaMessage(t, xEnv, EventWaitTimeout, topic, + `{"__typename":"Employee","id":2,"update":{"name":"recovery"}}`) + + 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") + } + + xEnv.WaitForSubscriptionCount(1, EventWaitTimeout) + }) +} + +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") + } + } +} diff --git a/router/core/graph_server.go b/router/core/graph_server.go index 3cc45d5f9e..e4876a514d 100644 --- a/router/core/graph_server.go +++ b/router/core/graph_server.go @@ -1806,6 +1806,7 @@ func (s *graphServer) buildGraphMux( SubgraphErrorPropagation: s.subgraphErrorPropagation, EngineLoaderHooks: loaderHooks, HeaderPropagation: s.headerPropagation, + SSEServerWriteTimeout: s.engineExecutionConfiguration.SSEServerWriteTimeout, } if s.redisClient != nil { diff --git a/router/core/graphql_handler.go b/router/core/graphql_handler.go index 4ef92da46b..34ae0f8a3c 100644 --- a/router/core/graphql_handler.go +++ b/router/core/graphql_handler.go @@ -10,6 +10,7 @@ import ( "net/http" "strconv" "strings" + "time" otelmetric "go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/trace" @@ -87,6 +88,7 @@ type HandlerOptions struct { EnableCostResponseHeaders bool ApolloSubscriptionMultipartPrintBoundary bool + SSEServerWriteTimeout time.Duration HeaderPropagation *HeaderPropagation } @@ -109,6 +111,7 @@ func NewGraphQLHandler(opts HandlerOptions) *GraphQLHandler { subgraphErrorPropagation: opts.SubgraphErrorPropagation, engineLoaderHooks: opts.EngineLoaderHooks, apolloSubscriptionMultipartPrintBoundary: opts.ApolloSubscriptionMultipartPrintBoundary, + sseServerWriteTimeout: opts.SSEServerWriteTimeout, headerPropagation: opts.HeaderPropagation, } return graphQLHandler @@ -143,6 +146,7 @@ type GraphQLHandler struct { enableCostResponseHeaders bool apolloSubscriptionMultipartPrintBoundary bool + sseServerWriteTimeout time.Duration } func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { @@ -284,21 +288,24 @@ 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, + }) + 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, }) diff --git a/router/core/subscription_response_writer.go b/router/core/subscription_response_writer.go index abe951a380..5b87b2043a 100644 --- a/router/core/subscription_response_writer.go +++ b/router/core/subscription_response_writer.go @@ -3,11 +3,14 @@ package core import ( "bytes" "context" + "errors" + "fmt" "io" "mime" "net/http" "strconv" "strings" + "time" "github.com/wundergraph/astjson" "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" @@ -31,16 +34,23 @@ type withFlushWriter interface { SubscriptionResponseWriter() resolve.SubscriptionResponseWriter } +type SubscriptionResponseWriterOptions struct { + ApolloSubscriptionMultipartPrintBoundary bool + SSEWriteTimeout time.Duration +} + type HttpFlushWriter struct { - ctx context.Context - cancel context.CancelFunc - writer io.Writer - flusher http.Flusher - subscribeOnce bool - sse bool - multipart bool - buf *bytes.Buffer - firstMessage bool + ctx context.Context + cancel context.CancelFunc + writer io.Writer + flusher http.Flusher + responseControl *http.ResponseController + subscribeOnce bool + sse bool + multipart bool + buf *bytes.Buffer + firstMessage bool + sseWriteTimeout time.Duration // apolloSubscriptionMultipartPrintBoundary if set to true will send the multipart boundary at the end of the message to allow // misbehaving client (like apollo client) to read the message just sent before the next one or the heartbeat apolloSubscriptionMultipartPrintBoundary bool @@ -53,7 +63,10 @@ func (f *HttpFlushWriter) Complete() { return } if f.sse { - _, _ = f.writer.Write([]byte("event: complete\ndata: \n\n")) + _ = f.writeAndFlushSSE(func() error { + _, err := f.writer.Write([]byte("event: complete\ndata: \n\n")) + return err + }) } else if f.multipart { // Write the final boundary in the multipart response if f.apolloSubscriptionMultipartPrintBoundary { @@ -63,8 +76,10 @@ func (f *HttpFlushWriter) Complete() { } } - // Flush before closing the writer to ensure all data is sent - f.flusher.Flush() + if !f.sse { + // Flush before closing the writer to ensure all data is sent. + f.flusher.Flush() + } f.cancel() } @@ -85,12 +100,10 @@ func (f *HttpFlushWriter) Heartbeat() error { var heartbeat []byte if f.sse { heartbeat = []byte(":heartbeat\n\n") - - if _, err := f.writer.Write(heartbeat); err != nil { + return f.writeAndFlushSSE(func() error { + _, err := f.writer.Write(heartbeat) return err - } - - f.flusher.Flush() + }) } else if f.multipart { if _, err := f.Write([]byte("{}")); err != nil { return err @@ -151,14 +164,22 @@ func (f *HttpFlushWriter) Flush() (err error) { } full := flushBreak + string(resp) + separation - _, err = f.writer.Write([]byte(full)) + if f.sse { + err = f.writeAndFlushSSE(func() error { + _, writeErr := f.writer.Write([]byte(full)) + return writeErr + }) + } else { + _, err = f.writer.Write([]byte(full)) + if err == nil { + // Flush before closing the writer to ensure all data is sent. + f.flusher.Flush() + } + } if err != nil { return err } - // Flush before closing the writer to ensure all data is sent - f.flusher.Flush() - if f.subscribeOnce { defer f.cancel() } @@ -166,15 +187,31 @@ func (f *HttpFlushWriter) Flush() (err error) { return nil } -func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http.ResponseWriter, apolloSubscriptionMultipartPrintBoundary bool) (*resolve.Context, resolve.SubscriptionResponseWriter, bool) { +func (f *HttpFlushWriter) writeAndFlushSSE(write func() error) error { + if f.sseWriteTimeout > 0 { + if err := f.responseControl.SetWriteDeadline(time.Now().Add(f.sseWriteTimeout)); err != nil { + // Failing closed prevents a response writer without deadline support from + // reintroducing an unbounded shared-trigger stall. + return fmt.Errorf("set SSE write deadline: %w", err) + } + } + + if err := write(); err != nil { + return err + } + + return f.responseControl.Flush() +} + +func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http.ResponseWriter, opts SubscriptionResponseWriterOptions) (*resolve.Context, resolve.SubscriptionResponseWriter, error) { if wfw, ok := w.(withFlushWriter); ok { - return ctx, wfw.SubscriptionResponseWriter(), true + return ctx, wfw.SubscriptionResponseWriter(), nil } wgParams := NegotiateSubscriptionParams(r, false) flusher, ok := w.(http.Flusher) if !ok { - return ctx, nil, false + return ctx, nil, errors.New("subscription response writer does not support flushing") } setSubscriptionHeaders(wgParams, r, w) @@ -182,12 +219,14 @@ func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http flushWriter := &HttpFlushWriter{ writer: w, flusher: flusher, + responseControl: http.NewResponseController(w), sse: wgParams.UseSse, multipart: wgParams.UseMultipart, subscribeOnce: wgParams.SubscribeOnce, buf: &bytes.Buffer{}, firstMessage: true, - apolloSubscriptionMultipartPrintBoundary: apolloSubscriptionMultipartPrintBoundary, + sseWriteTimeout: opts.SSEWriteTimeout, + apolloSubscriptionMultipartPrintBoundary: opts.ApolloSubscriptionMultipartPrintBoundary, } flushWriter.ctx, flushWriter.cancel = context.WithCancel(ctx.Context()) @@ -197,10 +236,17 @@ func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http ctx.ExecutionOptions.SendHeartbeat = true // Flush the response head immediately so the client establishes the connection // before the first message, instead of blocking until one is streamed. - flusher.Flush() + if wgParams.UseSse { + if err := flushWriter.writeAndFlushSSE(func() error { return nil }); err != nil { + flushWriter.cancel() + return ctx, nil, fmt.Errorf("flush initial SSE response headers: %w", err) + } + } else { + flusher.Flush() + } } - return ctx, flushWriter, true + return ctx, flushWriter, nil } func wrapMultipartMessage(resp []byte, wrapPayload bool) ([]byte, error) { diff --git a/router/core/subscription_response_writer_test.go b/router/core/subscription_response_writer_test.go index 02db6b7400..f219412cfd 100644 --- a/router/core/subscription_response_writer_test.go +++ b/router/core/subscription_response_writer_test.go @@ -2,16 +2,41 @@ package core import ( "context" + "errors" "net/http" "net/http/httptest" "net/url" "testing" + "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" ) +type deadlineRecorder struct { + *httptest.ResponseRecorder + deadlines []time.Time + deadlineErr error + flushErr error +} + +func (r *deadlineRecorder) SetWriteDeadline(deadline time.Time) error { + if r.deadlineErr != nil { + return r.deadlineErr + } + r.deadlines = append(r.deadlines, deadline) + return nil +} + +func (r *deadlineRecorder) FlushError() error { + if r.flushErr != nil { + return r.flushErr + } + r.Flush() + return nil +} + func TestNegotiateSubscriptionParams(t *testing.T) { type args struct { r *http.Request @@ -137,10 +162,82 @@ func TestGetSubscriptionResponseWriter(t *testing.T) { req := httptest.NewRequest(http.MethodPost, "/graphql", nil) req.Header.Set("Accept", sseMimeType) - _, _, ok := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, false) - require.True(t, ok) + _, _, err := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, SubscriptionResponseWriterOptions{}) + require.NoError(t, err) assert.Equal(t, sseMimeType, recorder.Header().Get("Content-Type")) assert.True(t, recorder.Flushed, "expected the SSE response head to be flushed before any message is written") }) + + t.Run("sets a fresh deadline for every SSE write and flush", func(t *testing.T) { + recorder := &deadlineRecorder{ResponseRecorder: httptest.NewRecorder()} + req := httptest.NewRequest(http.MethodPost, "/graphql", nil) + req.Header.Set("Accept", sseMimeType) + + _, writer, err := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, SubscriptionResponseWriterOptions{SSEWriteTimeout: time.Second}) + require.NoError(t, err) + require.Len(t, recorder.deadlines, 1, "expected the initial header flush to have a deadline") + + _, err = writer.Write([]byte(`{"data":{"id":1}}`)) + require.NoError(t, err) + require.NoError(t, writer.Flush()) + require.Len(t, recorder.deadlines, 2, "expected the data frame to refresh the deadline") + assert.False(t, recorder.deadlines[1].Before(recorder.deadlines[0])) + + require.NoError(t, writer.Heartbeat()) + require.Len(t, recorder.deadlines, 3, "expected the heartbeat to refresh the deadline") + + writer.Complete() + require.Len(t, recorder.deadlines, 4, "expected the completion frame to refresh the deadline") + }) + + t.Run("propagates an SSE flush error", func(t *testing.T) { + recorder := &deadlineRecorder{ResponseRecorder: httptest.NewRecorder()} + req := httptest.NewRequest(http.MethodPost, "/graphql", nil) + req.Header.Set("Accept", sseMimeType) + + _, writer, err := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, SubscriptionResponseWriterOptions{}) + require.NoError(t, err) + + flushErr := errors.New("flush failed") + recorder.flushErr = flushErr + require.ErrorIs(t, writer.Heartbeat(), flushErr) + }) + + t.Run("propagates an SSE deadline error", func(t *testing.T) { + recorder := &deadlineRecorder{ResponseRecorder: httptest.NewRecorder()} + req := httptest.NewRequest(http.MethodPost, "/graphql", nil) + req.Header.Set("Accept", sseMimeType) + + _, writer, err := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, SubscriptionResponseWriterOptions{SSEWriteTimeout: time.Second}) + require.NoError(t, err) + + deadlineErr := errors.New("deadline failed") + recorder.deadlineErr = deadlineErr + err = writer.Heartbeat() + assert.ErrorIs(t, err, deadlineErr) + assert.ErrorContains(t, err, "set SSE write deadline") + }) + + t.Run("fails closed when an SSE deadline is configured but unsupported", func(t *testing.T) { + recorder := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodPost, "/graphql", nil) + req.Header.Set("Accept", sseMimeType) + + _, writer, err := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, SubscriptionResponseWriterOptions{SSEWriteTimeout: time.Second}) + require.Error(t, err) + assert.ErrorIs(t, err, http.ErrNotSupported) + assert.ErrorContains(t, err, "set SSE write deadline") + assert.Nil(t, writer) + }) + + t.Run("does not require deadline support when the timeout is disabled", func(t *testing.T) { + recorder := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodPost, "/graphql", nil) + req.Header.Set("Accept", sseMimeType) + + _, writer, err := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, SubscriptionResponseWriterOptions{}) + require.NoError(t, err) + assert.NotNil(t, writer) + }) } diff --git a/router/pkg/config/config.go b/router/pkg/config/config.go index 90d99e551c..3fa09b9bca 100644 --- a/router/pkg/config/config.go +++ b/router/pkg/config/config.go @@ -500,6 +500,7 @@ type EngineExecutionConfiguration struct { DisableVariablesRemapping bool `envDefault:"false" env:"ENGINE_DISABLE_VARIABLES_REMAPPING" yaml:"disable_variables_remapping"` EnableRequireFetchReasons bool `envDefault:"false" env:"ENGINE_ENABLE_REQUIRE_FETCH_REASONS" yaml:"enable_require_fetch_reasons"` SubscriptionFetchTimeout time.Duration `envDefault:"30s" env:"ENGINE_SUBSCRIPTION_FETCH_TIMEOUT" yaml:"subscription_fetch_timeout,omitempty"` + SSEServerWriteTimeout time.Duration `envDefault:"0s" env:"ENGINE_SSE_SERVER_WRITE_TIMEOUT" yaml:"sse_server_write_timeout,omitempty"` EnableDefer bool `envDefault:"false" env:"ENGINE_ENABLE_DEFER" yaml:"enable_defer"` // EnableMultiFetch merges entity fetches to the same subgraph that execute diff --git a/router/pkg/config/config.schema.json b/router/pkg/config/config.schema.json index 069292f78e..1aa18493c5 100644 --- a/router/pkg/config/config.schema.json +++ b/router/pkg/config/config.schema.json @@ -4151,6 +4151,12 @@ "default": "30s", "description": "The maximum time a subscription fetch can take before it is considered timed out. The period is specified as a string with a number and a unit, e.g. 10ms, 1s, 1m, 1h. The supported units are 'ms', 's', 'm', 'h'." }, + "sse_server_write_timeout": { + "type": "string", + "format": "go-duration", + "default": "0s", + "description": "The maximum time allowed for each downstream SSE write and flush. When exceeded, the affected SSE subscription is terminated so it cannot indefinitely block other subscriptions sharing a trigger. A value of 0s disables the deadline." + }, "enable_defer": { "type": "boolean", "default": false, diff --git a/router/pkg/config/fixtures/full.yaml b/router/pkg/config/fixtures/full.yaml index b953f28ae4..46afdb6c24 100644 --- a/router/pkg/config/fixtures/full.yaml +++ b/router/pkg/config/fixtures/full.yaml @@ -450,6 +450,7 @@ engine: websocket_client_write_timeout: 10s websocket_server_read_timeout: 5s websocket_server_write_timeout: 10s + sse_server_write_timeout: 10s websocket_server_poll_timeout: 1s websocket_server_conn_buffer_size: 128 websocket_client_read_limit: 1MB diff --git a/router/pkg/config/testdata/config_defaults.json b/router/pkg/config/testdata/config_defaults.json index ad7e252cf8..36751bb81a 100644 --- a/router/pkg/config/testdata/config_defaults.json +++ b/router/pkg/config/testdata/config_defaults.json @@ -519,6 +519,7 @@ "DisableVariablesRemapping": false, "EnableRequireFetchReasons": false, "SubscriptionFetchTimeout": 30000000000, + "SSEServerWriteTimeout": 0, "EnableDefer": false, "EnableMultiFetch": false, "EnableScheduleFetches": false, diff --git a/router/pkg/config/testdata/config_full.json b/router/pkg/config/testdata/config_full.json index f610b51c11..189a37e0eb 100644 --- a/router/pkg/config/testdata/config_full.json +++ b/router/pkg/config/testdata/config_full.json @@ -987,6 +987,7 @@ "DisableVariablesRemapping": false, "EnableRequireFetchReasons": false, "SubscriptionFetchTimeout": 30000000000, + "SSEServerWriteTimeout": 10000000000, "EnableDefer": false, "EnableMultiFetch": false, "EnableScheduleFetches": false, From 90ad6b54cbd8d2fc0e6867e27870e5dabb8ecfab Mon Sep 17 00:00:00 2001 From: Matt Wisner Date: Thu, 20 Aug 2026 06:40:11 -0400 Subject: [PATCH 2/5] fix(router): address SSE timeout review feedback --- .../events/kafka_sse_write_timeout_test.go | 7 ++--- router/pkg/config/config.go | 4 +++ router/pkg/config/config.schema.json | 3 ++ router/pkg/config/config_test.go | 30 +++++++++++++++++++ router/pkg/config/json_schema.go | 24 ++++++++------- 5 files changed, 54 insertions(+), 14 deletions(-) diff --git a/router-tests/events/kafka_sse_write_timeout_test.go b/router-tests/events/kafka_sse_write_timeout_test.go index e8148a7557..a7c602a294 100644 --- a/router-tests/events/kafka_sse_write_timeout_test.go +++ b/router-tests/events/kafka_sse_write_timeout_test.go @@ -183,8 +183,9 @@ func TestKafkaSubscriptionRecoversAfterSSEWriteTimeout(t *testing.T) { require.Contains(t, readSSEData(t, healthyReader), `"id":1`) - events.ProduceKafkaMessage(t, xEnv, EventWaitTimeout, topic, - `{"__typename":"Employee","id":2,"update":{"name":"recovery"}}`) + xEnv.WaitForSubscriptionCount(1, EventWaitTimeout) + xEnv.KafkaPublishUntilReceived(topic, + `{"__typename":"Employee","id":2,"update":{"name":"recovery"}}`, 1, EventWaitTimeout) recovery := make(chan string, 1) go func() { @@ -202,8 +203,6 @@ func TestKafkaSubscriptionRecoversAfterSSEWriteTimeout(t *testing.T) { case <-time.After(EventWaitTimeout): t.Fatal("healthy subscription did not receive the queued event after the SSE write deadline") } - - xEnv.WaitForSubscriptionCount(1, EventWaitTimeout) }) } diff --git a/router/pkg/config/config.go b/router/pkg/config/config.go index 3fa09b9bca..60aa2256f2 100644 --- a/router/pkg/config/config.go +++ b/router/pkg/config/config.go @@ -1722,6 +1722,10 @@ func LoadConfig(configFilePaths []string) (*LoadResult, error) { } } + if cfg.Config.EngineExecutionConfiguration.SSEServerWriteTimeout < 0 { + return nil, errors.New("engine.sse_server_write_timeout must be greater or equal to 0s") + } + // Post-process the config if cfg.Config.DevelopmentMode { cfg.Config.JSONLog = false diff --git a/router/pkg/config/config.schema.json b/router/pkg/config/config.schema.json index 1aa18493c5..15d8b15f1e 100644 --- a/router/pkg/config/config.schema.json +++ b/router/pkg/config/config.schema.json @@ -4154,6 +4154,9 @@ "sse_server_write_timeout": { "type": "string", "format": "go-duration", + "duration": { + "minimum": "0s" + }, "default": "0s", "description": "The maximum time allowed for each downstream SSE write and flush. When exceeded, the affected SSE subscription is terminated so it cannot indefinitely block other subscriptions sharing a trigger. A value of 0s disables the deadline." }, diff --git a/router/pkg/config/config_test.go b/router/pkg/config/config_test.go index e05dca1228..da7db70f1d 100644 --- a/router/pkg/config/config_test.go +++ b/router/pkg/config/config_test.go @@ -478,6 +478,36 @@ telemetry: require.Equal(t, "at '/telemetry/tracing/exporters/0/export_timeout': duration must be less or equal than 2m0s", js.Causes[0].Error()) } +func TestSSEServerWriteTimeoutRejectsNegativeValues(t *testing.T) { + t.Run("config file", func(t *testing.T) { + f := createTempFileFromFixture(t, ` +version: "1" + +graph: + token: "token" + +engine: + sse_server_write_timeout: -1s +`) + + _, err := LoadConfig([]string{f}) + require.ErrorContains(t, err, "duration must be greater or equal than 0s") + }) + + t.Run("environment variable", func(t *testing.T) { + t.Setenv("ENGINE_SSE_SERVER_WRITE_TIMEOUT", "-1s") + f := createTempFileFromFixture(t, ` +version: "1" + +graph: + token: "token" +`) + + _, err := LoadConfig([]string{f}) + require.EqualError(t, err, "engine.sse_server_write_timeout must be greater or equal to 0s") + }) +} + func TestLoadFullConfig(t *testing.T) { t.Parallel() diff --git a/router/pkg/config/json_schema.go b/router/pkg/config/json_schema.go index 46bc4432a9..dc0675f6fe 100644 --- a/router/pkg/config/json_schema.go +++ b/router/pkg/config/json_schema.go @@ -27,8 +27,10 @@ const ( ) type duration struct { - min time.Duration - max time.Duration + min time.Duration + max time.Duration + hasMin bool + hasMax bool } func (d duration) Validate(ctx *jsonschema.ValidatorContext, v any) { @@ -51,7 +53,7 @@ func (d duration) Validate(ctx *jsonschema.ValidatorContext, v any) { return } - if d.min > 0 { + if d.hasMin { if duration < d.min { ctx.AddError(&validationErrorKind{ fmt.Sprintf("duration must be greater or equal than %s", d.min), @@ -61,7 +63,7 @@ func (d duration) Validate(ctx *jsonschema.ValidatorContext, v any) { } } - if d.max > 0 { + if d.hasMax { if duration > d.max { ctx.AddError(&validationErrorKind{ fmt.Sprintf("duration must be less or equal than %s", d.max), @@ -118,23 +120,25 @@ func compileDuration(ctx *jsonschema.CompilerContext, m map[string]any) (jsonsch var minDuration, maxDuration time.Duration var err error - minDurationString, ok := mapVal["minimum"].(string) - if ok { + minDurationString, hasMin := mapVal["minimum"].(string) + if hasMin { minDuration, err = time.ParseDuration(minDurationString) if err != nil { return nil, err } } - maxDurationString, ok := mapVal["maximum"].(string) - if ok { + maxDurationString, hasMax := mapVal["maximum"].(string) + if hasMax { maxDuration, err = time.ParseDuration(maxDurationString) if err != nil { return nil, err } } return duration{ - min: minDuration, - max: maxDuration, + min: minDuration, + max: maxDuration, + hasMin: hasMin, + hasMax: hasMax, }, nil } From d6c22c1254fd9805ff70e672afc9ddd8ea2ef4ec Mon Sep 17 00:00:00 2001 From: Matt Wisner Date: Thu, 20 Aug 2026 09:18:35 -0400 Subject: [PATCH 3/5] feat(router): observe subscription delivery failures --- .../router/metrics-and-monitoring.mdx | 8 + .../prometheus-metric-reference.mdx | 6 + router/core/graphql_handler.go | 14 ++ .../subscription_delivery_observability.go | 226 ++++++++++++++++++ ...ubscription_delivery_observability_test.go | 99 ++++++++ router/core/subscription_response_writer.go | 81 ++++++- router/core/websocket.go | 131 ++++++++-- router/go.mod | 4 +- router/go.sum | 4 +- router/pkg/metric/engine_metrics.go | 57 +++++ router/pkg/metric/engine_metrics_test.go | 52 ++++ router/pkg/otel/attributes.go | 7 + router/pkg/pubsub/datasource/provider.go | 18 ++ .../subscription_event_observability_test.go | 61 +++++ .../datasource/subscription_event_updater.go | 36 ++- router/pkg/pubsub/kafka/adapter.go | 7 + router/pkg/pubsub/kafka/engine_datasource.go | 27 ++- router/pkg/pubsub/nats/adapter.go | 24 +- .../pkg/pubsub/nats/adapter_consume_test.go | 3 + router/pkg/pubsub/nats/engine_datasource.go | 30 ++- router/pkg/pubsub/redis/adapter.go | 8 +- router/pkg/pubsub/redis/engine_datasource.go | 24 +- router/pkg/statistics/engine_stats.go | 75 +++++- 23 files changed, 935 insertions(+), 67 deletions(-) create mode 100644 router/core/subscription_delivery_observability.go create mode 100644 router/core/subscription_delivery_observability_test.go create mode 100644 router/pkg/metric/engine_metrics_test.go create mode 100644 router/pkg/pubsub/datasource/subscription_event_observability_test.go diff --git a/docs-website/router/metrics-and-monitoring.mdx b/docs-website/router/metrics-and-monitoring.mdx index 43f05d58f2..77d59af130 100644 --- a/docs-website/router/metrics-and-monitoring.mdx +++ b/docs-website/router/metrics-and-monitoring.mdx @@ -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 diff --git a/docs-website/router/metrics-and-monitoring/prometheus-metric-reference.mdx b/docs-website/router/metrics-and-monitoring/prometheus-metric-reference.mdx index ab2ac8a46d..d94998a239 100644 --- a/docs-website/router/metrics-and-monitoring/prometheus-metric-reference.mdx +++ b/docs-website/router/metrics-and-monitoring/prometheus-metric-reference.mdx @@ -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. diff --git a/router/core/graphql_handler.go b/router/core/graphql_handler.go index 34ae0f8a3c..ce65f5cda0 100644 --- a/router/core/graphql_handler.go +++ b/router/core/graphql_handler.go @@ -12,6 +12,7 @@ import ( "strings" "time" + "github.com/go-chi/chi/v5/middleware" otelmetric "go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/trace" "go.uber.org/zap" @@ -297,6 +298,16 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { 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, + clientName: reqCtx.operation.clientInfo.Name, + clientVersion: reqCtx.operation.clientInfo.Version, + writeTimeout: h.sseServerWriteTimeout, + }, }) if writerErr != nil { reqCtx.logger.Error("unable to get subscription response writer", zap.Error(writerErr)) @@ -311,6 +322,9 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { }) return } + if lifecycle, ok := writer.(*HttpFlushWriter); ok { + defer lifecycle.subscriptionRequestEnded() + } if !resolveCtx.ExecutionOptions.SkipLoader { h.engineStats.ConnectionsInc() diff --git a/router/core/subscription_delivery_observability.go b/router/core/subscription_delivery_observability.go new file mode 100644 index 0000000000..65cd8f4f61 --- /dev/null +++ b/router/core/subscription_delivery_observability.go @@ -0,0 +1,226 @@ +package core + +import ( + "context" + "errors" + "net" + "sync" + "syscall" + "time" + + "github.com/wundergraph/cosmo/router/pkg/statistics" + "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" + "go.uber.org/zap" +) + +const ( + subscriptionTransportSSE = "sse" + subscriptionTransportWebSocket = "websocket" +) + +type subscriptionTelemetryContext struct { + transport string + subprotocol string + requestID string + operationName string + clientName string + clientVersion string + connectionID resolve.ConnectionID + writeTimeout time.Duration +} + +type subscriptionWriteError struct { + stage string + err error +} + +type subscriptionDisconnectTracker struct { + once sync.Once + stats statistics.EngineStatistics + logger *zap.Logger + telemetry subscriptionTelemetryContext +} + +func newSubscriptionDisconnectTracker(stats statistics.EngineStatistics, logger *zap.Logger, telemetry subscriptionTelemetryContext) *subscriptionDisconnectTracker { + if logger == nil { + logger = zap.NewNop() + } + return &subscriptionDisconnectTracker{stats: stats, logger: logger, telemetry: telemetry} +} + +func (t *subscriptionDisconnectTracker) disconnect(initiator, reason string, err error) { + if t == nil { + return + } + t.once.Do(func() { + observeSubscription(t.stats, statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDisconnect, + Transport: t.telemetry.transport, + Initiator: initiator, + DisconnectReason: reason, + Subprotocol: t.telemetry.subprotocol, + }) + fields := []zap.Field{ + zap.String("transport", t.telemetry.transport), + zap.String("websocket_subprotocol", t.telemetry.subprotocol), + zap.String("request_id", t.telemetry.requestID), + zap.String("client_name", t.telemetry.clientName), + zap.String("client_version", t.telemetry.clientVersion), + zap.Int64("connection_id", int64(t.telemetry.connectionID)), + zap.String("disconnect_initiator", initiator), + zap.String("disconnect_reason", reason), + } + if err != nil { + fields = append(fields, zap.Error(err)) + } + if reason == "normal_completion" || reason == "client_closed" || reason == "context_canceled" { + t.logger.Debug("Subscription client disconnected", fields...) + return + } + t.logger.Info("Subscription client disconnected", fields...) + }) +} + +func disconnectReasonFromWriteError(err error) (initiator, reason string) { + _, failureReason := classifySubscriptionWriteFailure(err) + switch failureReason { + case "timeout": + return "router", "write_timeout" + case "client_disconnected": + return "client", "client_closed" + case "context_canceled": + return "client", "context_canceled" + default: + return "network", "network_error" + } +} + +func (e *subscriptionWriteError) Error() string { return e.err.Error() } +func (e *subscriptionWriteError) Unwrap() error { return e.err } +func (e *subscriptionWriteError) IsSubscriptionDeliveryError() {} + +func wrapSubscriptionWriteError(stage string, err error) error { + if err == nil { + return nil + } + return &subscriptionWriteError{stage: stage, err: err} +} + +func observeSubscriptionDelivery(stats statistics.EngineStatistics, logger *zap.Logger, telemetry subscriptionTelemetryContext, report resolve.SubscriptionDeliveryReport) { + observeSubscription(stats, statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDeliveryAttempt, + Transport: telemetry.transport, + FrameType: "next", + Subprotocol: telemetry.subprotocol, + }) + if report.Err == nil { + return + } + if logger == nil { + logger = zap.NewNop() + } + + stage, reason := classifySubscriptionWriteFailure(report.Err) + observeSubscription(stats, statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDeliveryFailure, + Transport: telemetry.transport, + FrameType: "next", + FailureStage: stage, + FailureReason: reason, + Subprotocol: telemetry.subprotocol, + }) + logger.Warn("Subscription event delivery failed", + zap.String("transport", telemetry.transport), + zap.String("websocket_subprotocol", telemetry.subprotocol), + zap.String("request_id", telemetry.requestID), + zap.String("operation_name", telemetry.operationName), + zap.String("client_name", telemetry.clientName), + zap.String("client_version", telemetry.clientVersion), + zap.Int64("connection_id", int64(report.ConnectionID)), + zap.Int64("subscription_id", report.SubscriptionID), + zap.Uint64("trigger_id", report.TriggerID), + zap.String("event_id", report.EventID), + zap.String("event_hash", report.EventHash), + zap.Int("event_bytes", report.EventBytes), + zap.String("event_source_type", report.SourceType), + zap.String("event_source_name", report.SourceName), + zap.String("event_source_id", report.SourceID), + zap.String("frame_type", "next"), + zap.String("failure_stage", stage), + zap.String("failure_reason", reason), + zap.Int64("configured_write_timeout_ms", telemetry.writeTimeout.Milliseconds()), + zap.Error(report.Err), + ) +} + +func observeSubscriptionFrame(stats statistics.EngineStatistics, logger *zap.Logger, telemetry subscriptionTelemetryContext, frameType string, err error) { + observeSubscription(stats, statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDeliveryAttempt, + Transport: telemetry.transport, + FrameType: frameType, + Subprotocol: telemetry.subprotocol, + }) + if err == nil { + return + } + if logger == nil { + logger = zap.NewNop() + } + stage, reason := classifySubscriptionWriteFailure(err) + observeSubscription(stats, statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDeliveryFailure, + Transport: telemetry.transport, + FrameType: frameType, + FailureStage: stage, + FailureReason: reason, + Subprotocol: telemetry.subprotocol, + }) + logger.Warn("Subscription frame delivery failed", + zap.String("transport", telemetry.transport), + zap.String("websocket_subprotocol", telemetry.subprotocol), + zap.String("request_id", telemetry.requestID), + zap.String("operation_name", telemetry.operationName), + zap.String("client_name", telemetry.clientName), + zap.String("client_version", telemetry.clientVersion), + zap.Int64("connection_id", int64(telemetry.connectionID)), + zap.String("frame_type", frameType), + zap.String("failure_stage", stage), + zap.String("failure_reason", reason), + zap.Int64("configured_write_timeout_ms", telemetry.writeTimeout.Milliseconds()), + zap.Error(err), + ) +} + +func observeSubscription(stats statistics.EngineStatistics, observation statistics.SubscriptionObservation) { + observer, ok := stats.(statistics.SubscriptionObserver) + if !ok { + return + } + observer.ObserveSubscription(observation) +} + +func classifySubscriptionWriteFailure(err error) (stage, reason string) { + stage = "write" + var writeErr *subscriptionWriteError + if errors.As(err, &writeErr) { + stage = writeErr.stage + } + + var netErr net.Error + switch { + case errors.Is(err, context.DeadlineExceeded): + return stage, "timeout" + case errors.As(err, &netErr) && netErr.Timeout(): + return stage, "timeout" + case errors.Is(err, context.Canceled): + return stage, "context_canceled" + case errors.Is(err, net.ErrClosed), errors.Is(err, syscall.EPIPE), errors.Is(err, syscall.ECONNRESET): + return stage, "client_disconnected" + case errors.Is(err, errors.ErrUnsupported): + return stage, "unsupported" + case stage == "serialize": + return stage, "serialization_error" + default: + return stage, "network_error" + } +} diff --git a/router/core/subscription_delivery_observability_test.go b/router/core/subscription_delivery_observability_test.go new file mode 100644 index 0000000000..d7f2f5c98b --- /dev/null +++ b/router/core/subscription_delivery_observability_test.go @@ -0,0 +1,99 @@ +package core + +import ( + "context" + "errors" + "testing" + + "github.com/gobwas/ws" + "github.com/stretchr/testify/require" + "github.com/wundergraph/cosmo/router/internal/wsproto" + "github.com/wundergraph/cosmo/router/pkg/statistics" + "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + zapobserver "go.uber.org/zap/zaptest/observer" +) + +func TestObserveSubscriptionDeliveryRecordsFailureWithoutPayload(t *testing.T) { + logCore, logs := zapobserver.New(zapcore.DebugLevel) + stats := statistics.NewEngineStats(t.Context(), zap.NewNop(), false) + telemetry := subscriptionTelemetryContext{ + transport: subscriptionTransportSSE, + requestID: "request-1", + operationName: "ProductUpdated", + clientName: "storefront", + clientVersion: "1.2.3", + } + + observeSubscriptionDelivery(stats, zap.New(logCore), telemetry, resolve.SubscriptionDeliveryReport{ + TriggerID: 3, + ConnectionID: 5, + SubscriptionID: 7, + EventID: "orders/2/19", + EventHash: "abc123", + EventBytes: 17, + SourceType: "kafka", + SourceName: "orders", + SourceID: "orders/2/19", + Err: wrapSubscriptionWriteError("flush", context.DeadlineExceeded), + }) + + report := stats.GetReport() + require.Len(t, report.SubscriptionObservations, 2) + require.Equal(t, 1, logs.Len()) + fields := logs.All()[0].ContextMap() + require.Equal(t, "orders/2/19", fields["event_id"]) + require.Equal(t, "abc123", fields["event_hash"]) + require.Equal(t, "flush", fields["failure_stage"]) + require.Equal(t, "timeout", fields["failure_reason"]) + require.NotContains(t, fields, "payload") +} + +func TestSubscriptionDisconnectTrackerRecordsOnce(t *testing.T) { + logCore, logs := zapobserver.New(zapcore.DebugLevel) + stats := statistics.NewEngineStats(t.Context(), zap.NewNop(), false) + tracker := newSubscriptionDisconnectTracker(stats, zap.New(logCore), subscriptionTelemetryContext{ + transport: subscriptionTransportWebSocket, + subprotocol: wsproto.GraphQLWSSubprotocol, + connectionID: 41, + }) + + tracker.disconnect("client", "client_closed", nil) + tracker.disconnect("network", "network_error", errors.New("late error")) + + require.Equal(t, 1, logs.Len()) + report := stats.GetReport() + require.Len(t, report.SubscriptionObservations, 1) + require.Equal(t, statistics.SubscriptionObservationDisconnect, report.SubscriptionObservations[0].Observation.Kind) + require.Equal(t, "client_closed", report.SubscriptionObservations[0].Observation.DisconnectReason) +} + +func TestWebsocketDisconnectReasonUsesOriginalError(t *testing.T) { + initiator, reason := websocketDisconnectReason(context.DeadlineExceeded, wsproto.CloseKindNormal) + require.Equal(t, "network", initiator) + require.Equal(t, "read_timeout", reason) + + initiator, reason = websocketDisconnectReason(errClientTerminatedConnection, wsproto.CloseKindNormal) + require.Equal(t, "client", initiator) + require.Equal(t, "client_closed", reason) + + initiator, reason = websocketDisconnectReason(&wsproto.CloseError{ + Kind: wsproto.CloseKind{Code: ws.StatusProtocolError, Reason: "bad frame"}, + }, wsproto.CloseKindNormal) + require.Equal(t, "client", initiator) + require.Equal(t, "protocol_error", reason) +} + +func TestHttpFlushWriterMarksContextFailuresAsDeliveryErrors(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + cancel() + writer := &HttpFlushWriter{ctx: ctx} + + _, err := writer.Write([]byte(`{"data":{}}`)) + var deliveryErr resolve.SubscriptionDeliveryError + require.ErrorAs(t, err, &deliveryErr) + stage, reason := classifySubscriptionWriteFailure(err) + require.Equal(t, "buffer", stage) + require.Equal(t, "context_canceled", reason) +} diff --git a/router/core/subscription_response_writer.go b/router/core/subscription_response_writer.go index 5b87b2043a..4b03efdf67 100644 --- a/router/core/subscription_response_writer.go +++ b/router/core/subscription_response_writer.go @@ -13,7 +13,9 @@ import ( "time" "github.com/wundergraph/astjson" + "github.com/wundergraph/cosmo/router/pkg/statistics" "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" + "go.uber.org/zap" ) const ( @@ -37,6 +39,9 @@ type withFlushWriter interface { type SubscriptionResponseWriterOptions struct { ApolloSubscriptionMultipartPrintBoundary bool SSEWriteTimeout time.Duration + Logger *zap.Logger + Stats statistics.EngineStatistics + Telemetry subscriptionTelemetryContext } type HttpFlushWriter struct { @@ -51,6 +56,11 @@ type HttpFlushWriter struct { buf *bytes.Buffer firstMessage bool sseWriteTimeout time.Duration + logger *zap.Logger + stats statistics.EngineStatistics + telemetry subscriptionTelemetryContext + requestContext context.Context + disconnect *subscriptionDisconnectTracker // apolloSubscriptionMultipartPrintBoundary if set to true will send the multipart boundary at the end of the message to allow // misbehaving client (like apollo client) to read the message just sent before the next one or the heartbeat apolloSubscriptionMultipartPrintBoundary bool @@ -63,10 +73,17 @@ func (f *HttpFlushWriter) Complete() { return } if f.sse { - _ = f.writeAndFlushSSE(func() error { + err := f.writeAndFlushSSE(func() error { _, err := f.writer.Write([]byte("event: complete\ndata: \n\n")) return err }) + observeSubscriptionFrame(f.stats, f.logger, f.telemetry, "complete", err) + if err != nil { + initiator, reason := disconnectReasonFromWriteError(err) + f.disconnect.disconnect(initiator, reason, err) + } else { + f.disconnect.disconnect("server", "normal_completion", nil) + } } else if f.multipart { // Write the final boundary in the multipart response if f.apolloSubscriptionMultipartPrintBoundary { @@ -86,7 +103,7 @@ func (f *HttpFlushWriter) Complete() { func (f *HttpFlushWriter) Write(p []byte) (n int, err error) { if err = f.ctx.Err(); err != nil { - return + return 0, wrapSubscriptionWriteError("buffer", err) } return f.buf.Write(p) @@ -100,10 +117,16 @@ func (f *HttpFlushWriter) Heartbeat() error { var heartbeat []byte if f.sse { heartbeat = []byte(":heartbeat\n\n") - return f.writeAndFlushSSE(func() error { + err := f.writeAndFlushSSE(func() error { _, err := f.writer.Write(heartbeat) return err }) + observeSubscriptionFrame(f.stats, f.logger, f.telemetry, "heartbeat", err) + if err != nil { + initiator, reason := disconnectReasonFromWriteError(err) + f.disconnect.disconnect(initiator, reason, err) + } + return err } else if f.multipart { if _, err := f.Write([]byte("{}")); err != nil { return err @@ -122,10 +145,41 @@ func (f *HttpFlushWriter) Error(data []byte) { return } _, _ = f.buf.Write(data) - _ = f.Flush() + err := f.Flush() + if f.sse { + observeSubscriptionFrame(f.stats, f.logger, f.telemetry, "terminal_error", err) + if err != nil { + initiator, reason := disconnectReasonFromWriteError(err) + f.disconnect.disconnect(initiator, reason, err) + } else { + f.disconnect.disconnect("server", "normal_completion", nil) + } + } f.cancel() } +func (f *HttpFlushWriter) ReportSubscriptionDelivery(report resolve.SubscriptionDeliveryReport) { + if !f.sse { + return + } + observeSubscriptionDelivery(f.stats, f.logger, f.telemetry, report) + if report.Err != nil { + initiator, reason := disconnectReasonFromWriteError(report.Err) + f.disconnect.disconnect(initiator, reason, report.Err) + } +} + +func (f *HttpFlushWriter) subscriptionRequestEnded() { + if !f.sse { + return + } + if err := f.requestContext.Err(); err != nil { + f.disconnect.disconnect("client", "context_canceled", err) + return + } + f.disconnect.disconnect("server", "normal_completion", nil) +} + func (f *HttpFlushWriter) Flush() (err error) { if err = f.ctx.Err(); err != nil { return err @@ -192,15 +246,15 @@ func (f *HttpFlushWriter) writeAndFlushSSE(write func() error) error { if err := f.responseControl.SetWriteDeadline(time.Now().Add(f.sseWriteTimeout)); err != nil { // Failing closed prevents a response writer without deadline support from // reintroducing an unbounded shared-trigger stall. - return fmt.Errorf("set SSE write deadline: %w", err) + return wrapSubscriptionWriteError("deadline", fmt.Errorf("set SSE write deadline: %w", err)) } } if err := write(); err != nil { - return err + return wrapSubscriptionWriteError("write", err) } - return f.responseControl.Flush() + return wrapSubscriptionWriteError("flush", f.responseControl.Flush()) } func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http.ResponseWriter, opts SubscriptionResponseWriterOptions) (*resolve.Context, resolve.SubscriptionResponseWriter, error) { @@ -226,8 +280,15 @@ func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http buf: &bytes.Buffer{}, firstMessage: true, sseWriteTimeout: opts.SSEWriteTimeout, + logger: opts.Logger, + stats: opts.Stats, + telemetry: opts.Telemetry, + requestContext: r.Context(), apolloSubscriptionMultipartPrintBoundary: opts.ApolloSubscriptionMultipartPrintBoundary, } + if flushWriter.sse { + flushWriter.disconnect = newSubscriptionDisconnectTracker(flushWriter.stats, flushWriter.logger, flushWriter.telemetry) + } flushWriter.ctx, flushWriter.cancel = context.WithCancel(ctx.Context()) ctx = ctx.WithContext(flushWriter.ctx) @@ -237,7 +298,11 @@ func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http // Flush the response head immediately so the client establishes the connection // before the first message, instead of blocking until one is streamed. if wgParams.UseSse { - if err := flushWriter.writeAndFlushSSE(func() error { return nil }); err != nil { + err := flushWriter.writeAndFlushSSE(func() error { return nil }) + observeSubscriptionFrame(flushWriter.stats, flushWriter.logger, flushWriter.telemetry, "headers", err) + if err != nil { + initiator, reason := disconnectReasonFromWriteError(err) + flushWriter.disconnect.disconnect(initiator, reason, err) flushWriter.cancel() return ctx, nil, fmt.Errorf("flush initial SSE response headers: %w", err) } diff --git a/router/core/websocket.go b/router/core/websocket.go index 3fe6ec3345..557c313912 100644 --- a/router/core/websocket.go +++ b/router/core/websocket.go @@ -7,6 +7,7 @@ import ( "encoding/json" "errors" "fmt" + "io" "net" "net/http" "regexp" @@ -383,7 +384,7 @@ func (h *WebsocketHandler) handleUpgradeRequest(w http.ResponseWriter, r *http.R requestLogger.Debug("Initializing websocket connection", zap.Error(err)) - handler.Close(false, wsproto.CloseKindOf(err)) + handler.CloseWithError(false, wsproto.CloseKindOf(err), err) return } @@ -405,7 +406,7 @@ func (h *WebsocketHandler) handleUpgradeRequest(w http.ResponseWriter, r *http.R } http.Error(handler.w, http.StatusText(statusCode), statusCode) _ = handler.writeErrorMessage(requestID, errorMessage) - handler.Close(false, wsproto.CloseKindNormal) + handler.close(false, wsproto.CloseKindNormal, "router", "authentication_rejected", err) return } } @@ -417,7 +418,7 @@ func (h *WebsocketHandler) handleUpgradeRequest(w http.ResponseWriter, r *http.R if err != nil { requestLogger.Error("Error parsing initial payload: %v", zap.Error(err)) _ = handler.writeErrorMessage(requestID, err) - handler.Close(false, wsproto.CloseKindNormal) + handler.CloseWithError(false, wsproto.CloseKindNormal, err) return } jwtToken, ok := initialPayloadMap[fromInitialPayloadConfig.Key].(string) @@ -425,7 +426,7 @@ func (h *WebsocketHandler) handleUpgradeRequest(w http.ResponseWriter, r *http.R err := fmt.Errorf("invalid JWT token in initial payload: JWT token is not a string") requestLogger.Error(err.Error()) _ = handler.writeErrorMessage(requestID, err) - handler.Close(false, wsproto.CloseKindNormal) + handler.CloseWithError(false, wsproto.CloseKindNormal, err) return } handler.request.Header.Set(fromInitialPayloadConfig.ExportToken.HeaderKey, jwtToken) @@ -439,7 +440,7 @@ func (h *WebsocketHandler) handleUpgradeRequest(w http.ResponseWriter, r *http.R err = h.addConnection(c, handler) if err != nil { requestLogger.Error("Adding connection to net poller", zap.Error(err)) - handler.Close(true, wsproto.CloseKindNormal) + handler.CloseWithError(true, wsproto.CloseKindNormal, err) } return } @@ -466,7 +467,7 @@ func (h *WebsocketHandler) handleConnectionSync(handler *WebSocketConnectionHand continue } h.logger.Debug("Client closed connection", zap.Error(err)) - handler.Close(true, wsproto.CloseKindOf(err)) + handler.CloseWithError(true, wsproto.CloseKindOf(err), err) return } err = h.HandleMessage(handler, msg) @@ -474,7 +475,7 @@ func (h *WebsocketHandler) handleConnectionSync(handler *WebSocketConnectionHand h.logger.Debug("Handling websocket message", zap.Error(err)) var closeErr *wsproto.CloseError if errors.As(err, &closeErr) { - handler.Close(true, closeErr.Kind) + handler.CloseWithError(true, closeErr.Kind, err) return } } @@ -494,7 +495,7 @@ func (h *WebsocketHandler) addConnection(conn net.Conn, handler *WebSocketConnec return h.netPoll.Add(underlyingConn(conn)) } -func (h *WebsocketHandler) removeConnection(conn net.Conn, handler *WebSocketConnectionHandler, fd int, closeKind wsproto.CloseKind) { +func (h *WebsocketHandler) removeConnection(conn net.Conn, handler *WebSocketConnectionHandler, fd int, closeKind wsproto.CloseKind, cause error) { h.stats.ConnectionsDec() h.connectionsMu.Lock() delete(h.connections, fd) @@ -503,7 +504,7 @@ func (h *WebsocketHandler) removeConnection(conn net.Conn, handler *WebSocketCon if err != nil { h.logger.Warn("Removing connection from net poller", zap.Error(err)) } - handler.Close(true, closeKind) + handler.CloseWithError(true, closeKind, cause) } // underlyingConn unwraps a *tls.Conn to the network connection it wraps. wss @@ -581,7 +582,7 @@ func (h *WebsocketHandler) runPoller() { if fd == 0 { h.logger.Debug("Invalid socket fd", zap.Int("fd", fd)) - h.removeConnection(conn, handler, fd, wsproto.CloseKindNormal) + h.removeConnection(conn, handler, fd, wsproto.CloseKindNormal, errors.New("invalid socket file descriptor")) continue } @@ -591,7 +592,7 @@ func (h *WebsocketHandler) runPoller() { continue } h.logger.Debug("Client closed connection", zap.Error(err)) - h.removeConnection(conn, handler, fd, wsproto.CloseKindOf(err)) + h.removeConnection(conn, handler, fd, wsproto.CloseKindOf(err), err) continue } err = h.HandleMessage(handler, msg) @@ -602,7 +603,7 @@ func (h *WebsocketHandler) runPoller() { // which defaults to CloseKindNormal var closeErr *wsproto.CloseError if errors.As(err, &closeErr) { - h.removeConnection(conn, handler, fd, closeErr.Kind) + h.removeConnection(conn, handler, fd, closeErr.Kind, err) continue } } @@ -636,14 +637,16 @@ type websocketResponseWriter struct { stats statistics.EngineStatistics propagateErrors bool subscriptions *sync.Map + telemetry subscriptionTelemetryContext } var ( - _ http.ResponseWriter = (*websocketResponseWriter)(nil) - _ resolve.SubscriptionResponseWriter = (*websocketResponseWriter)(nil) + _ http.ResponseWriter = (*websocketResponseWriter)(nil) + _ resolve.SubscriptionResponseWriter = (*websocketResponseWriter)(nil) + _ resolve.SubscriptionDeliveryReporter = (*websocketResponseWriter)(nil) ) -func newWebsocketResponseWriter(id string, protocol wsproto.Proto, propagateErrors bool, logger *zap.Logger, stats statistics.EngineStatistics, subscriptions *sync.Map) *websocketResponseWriter { +func newWebsocketResponseWriter(id string, protocol wsproto.Proto, propagateErrors bool, logger *zap.Logger, stats statistics.EngineStatistics, subscriptions *sync.Map, telemetry subscriptionTelemetryContext) *websocketResponseWriter { return &websocketResponseWriter{ id: id, protocol: protocol, @@ -652,6 +655,7 @@ func newWebsocketResponseWriter(id string, protocol wsproto.Proto, propagateErro stats: stats, propagateErrors: propagateErrors, subscriptions: subscriptions, + telemetry: telemetry, } } @@ -668,6 +672,8 @@ func (rw *websocketResponseWriter) Complete() { rw.subscriptions.Delete(rw.id) } err := rw.protocol.Complete(rw.id) + err = wrapSubscriptionWriteError("write", err) + observeSubscriptionFrame(rw.stats, rw.logger, rw.telemetry, "complete", err) if err != nil { rw.logger.Debug("Sending complete message", zap.Error(err)) } @@ -700,15 +706,22 @@ func (rw *websocketResponseWriter) Error(data []byte) { errors = json.RawMessage(`[{"message":"Unable to subscribe"}]`) } if err := rw.protocol.WriteGraphQLErrors(rw.id, errors, nil); err != nil { + err = wrapSubscriptionWriteError("write", err) + observeSubscriptionFrame(rw.stats, rw.logger, rw.telemetry, "terminal_error", err) rw.logger.Debug("Sending error message", zap.Error(err)) return } + observeSubscriptionFrame(rw.stats, rw.logger, rw.telemetry, "terminal_error", nil) // subscriptions-transport-ws clients rely on an explicit "complete" to end // the stream after a data+errors frame. graphql-transport-ws treats the // "error" frame as terminal per spec, so no follow-up is needed there. if rw.protocol.Subprotocol() == wsproto.SubscriptionsTransportWSSubprotocol { if err := rw.protocol.Complete(rw.id); err != nil { + err = wrapSubscriptionWriteError("write", err) + observeSubscriptionFrame(rw.stats, rw.logger, rw.telemetry, "complete", err) rw.logger.Debug("Sending complete after error", zap.Error(err)) + } else { + observeSubscriptionFrame(rw.stats, rw.logger, rw.telemetry, "complete", nil) } } } @@ -728,6 +741,7 @@ func (rw *websocketResponseWriter) Flush() error { "response_headers": rw.header, }) if err != nil { + err = wrapSubscriptionWriteError("serialize", err) rw.logger.Warn("Serializing response headers", zap.Error(err)) return err } @@ -743,7 +757,7 @@ func (rw *websocketResponseWriter) Flush() error { } } - err = rw.protocol.WriteGraphQLData(rw.id, payload, extensions) + err = wrapSubscriptionWriteError("write", rw.protocol.WriteGraphQLData(rw.id, payload, extensions)) rw.buf.Reset() if err != nil { return err @@ -752,6 +766,10 @@ func (rw *websocketResponseWriter) Flush() error { return nil } +func (rw *websocketResponseWriter) ReportSubscriptionDelivery(report resolve.SubscriptionDeliveryReport) { + observeSubscriptionDelivery(rw.stats, rw.logger, rw.telemetry, report) +} + func (rw *websocketResponseWriter) SubscriptionResponseWriter() resolve.SubscriptionResponseWriter { return rw } @@ -813,6 +831,7 @@ type WebSocketConnectionHandler struct { subscriptionIDs atomic.Int64 subscriptions sync.Map stats statistics.EngineStatistics + disconnect *subscriptionDisconnectTracker forwardInitialPayload bool @@ -837,7 +856,16 @@ type forwardConfig struct { var detectNonRegex = regexp.MustCompile(`^[A-Za-z0-9_-]+$`) func NewWebsocketConnectionHandler(ctx context.Context, opts WebSocketConnectionHandlerOptions) *WebSocketConnectionHandler { - return &WebSocketConnectionHandler{ + telemetry := subscriptionTelemetryContext{ + transport: subscriptionTransportWebSocket, + subprotocol: opts.Protocol.Subprotocol(), + requestID: opts.InitRequestID, + clientName: opts.ClientInfo.Name, + clientVersion: opts.ClientInfo.Version, + connectionID: opts.ConnectionID, + writeTimeout: opts.Connection.writeTimeout, + } + handler := &WebSocketConnectionHandler{ ctx: ctx, operationProcessor: opts.OperationProcessor, operationBlocker: opts.OperationBlocker, @@ -862,6 +890,8 @@ func NewWebsocketConnectionHandler(ctx context.Context, opts WebSocketConnection apolloCompatibilityFlags: opts.ApolloCompatibilityFlags, clientInfoFromInitialPayload: opts.ClientInfoFromInitialPayload, } + handler.disconnect = newSubscriptionDisconnectTracker(opts.Stats, opts.Logger, telemetry) + return handler } func (h *WebSocketConnectionHandler) requestError(err error) error { @@ -895,7 +925,9 @@ func (h *WebSocketConnectionHandler) writeErrorMessage(operationID string, err e if err != nil { return fmt.Errorf("encoding GraphQL errors: %w", err) } - return h.protocol.WriteGraphQLErrors(operationID, payload, nil) + writeErr := wrapSubscriptionWriteError("write", h.protocol.WriteGraphQLErrors(operationID, payload, nil)) + observeSubscriptionFrame(h.stats, h.logger, h.disconnect.telemetry, "terminal_error", writeErr) + return writeErr } func (h *WebSocketConnectionHandler) parseAndPlan(registration *SubscriptionRegistration) (*ParsedOperation, *operationContext, error) { @@ -1066,7 +1098,15 @@ func (h *WebSocketConnectionHandler) parseAndPlan(registration *SubscriptionRegi } func (h *WebSocketConnectionHandler) executeSubscription(registration *SubscriptionRegistration) { - rw := newWebsocketResponseWriter(registration.msg.ID, h.protocol, h.graphqlHandler.subgraphErrorPropagation.Enabled, h.logger, h.stats, &h.subscriptions) + rw := newWebsocketResponseWriter(registration.msg.ID, h.protocol, h.graphqlHandler.subgraphErrorPropagation.Enabled, h.logger, h.stats, &h.subscriptions, subscriptionTelemetryContext{ + transport: subscriptionTransportWebSocket, + subprotocol: h.protocol.Subprotocol(), + requestID: h.initRequestID, + clientName: h.clientInfo.Name, + clientVersion: h.clientInfo.Version, + connectionID: h.connectionID, + writeTimeout: h.conn.writeTimeout, + }) _, operationCtx, err := h.parseAndPlan(registration) if err != nil { @@ -1076,6 +1116,7 @@ func (h *WebSocketConnectionHandler) executeSubscription(registration *Subscript } return } + rw.telemetry.operationName = operationCtx.name if h.forwardUpgradeHeaders.enabled && h.upgradeRequestHeaders != nil { if operationCtx.extensions == nil { @@ -1248,7 +1289,8 @@ func (h *WebSocketConnectionHandler) handleComplete(msg *wsproto.Message) error ConnectionID: h.connectionID, SubscriptionID: subscriptionID, } - _ = h.protocol.Complete(msg.ID) + writeErr := wrapSubscriptionWriteError("write", h.protocol.Complete(msg.ID)) + observeSubscriptionFrame(h.stats, h.logger, h.disconnect.telemetry, "complete", writeErr) return h.graphqlHandler.executor.Resolver.UnsubscribeSubscription(id) } @@ -1257,7 +1299,8 @@ func (h *WebsocketHandler) HandleMessage(handler *WebSocketConnectionHandler, ms case wsproto.MessageTypeTerminate: return errClientTerminatedConnection case wsproto.MessageTypePing: - _ = handler.protocol.Pong(msg) + writeErr := wrapSubscriptionWriteError("write", handler.protocol.Pong(msg)) + observeSubscriptionFrame(handler.stats, handler.logger, handler.disconnect.telemetry, "pong", writeErr) case wsproto.MessageTypePong: // "Furthermore, the Pong message may even be sent unsolicited as a unidirectional heartbeat" return nil @@ -1311,6 +1354,8 @@ func (h *WebSocketConnectionHandler) Initialize() (err error) { h.request.Header.Set(h.clientInfoFromInitialPayload.ForwardToRequestHeaders.VersionTargetHeader, clientVersion) } } + h.disconnect.telemetry.clientName = h.clientInfo.Name + h.disconnect.telemetry.clientVersion = h.clientInfo.Version // Update planner options with new client info h.plannerOptions.ClientInfo = h.clientInfo @@ -1396,6 +1441,17 @@ func (h *WebSocketConnectionHandler) shouldComputeOperationSha256(operationKit * } func (h *WebSocketConnectionHandler) Close(unsubscribe bool, closeKind wsproto.CloseKind) { + initiator, reason := websocketDisconnectReason(nil, closeKind) + h.close(unsubscribe, closeKind, initiator, reason, nil) +} + +func (h *WebSocketConnectionHandler) CloseWithError(unsubscribe bool, closeKind wsproto.CloseKind, err error) { + initiator, reason := websocketDisconnectReason(err, closeKind) + h.close(unsubscribe, closeKind, initiator, reason, err) +} + +func (h *WebSocketConnectionHandler) close(unsubscribe bool, closeKind wsproto.CloseKind, initiator, reason string, cause error) { + h.disconnect.disconnect(initiator, reason, cause) if unsubscribe { // Remove any pending IDs associated with this connection err := h.graphqlHandler.executor.Resolver.UnsubscribeClient(h.connectionID) @@ -1412,3 +1468,36 @@ func (h *WebSocketConnectionHandler) Close(unsubscribe bool, closeKind wsproto.C h.logger.Debug("Closing websocket connection", zap.Error(err)) } } + +func websocketDisconnectReason(err error, closeKind wsproto.CloseKind) (initiator, reason string) { + var netErr net.Error + var closeErr *wsproto.CloseError + var closedErr wsutil.ClosedError + var syntaxErr *json.SyntaxError + var typeErr *json.UnmarshalTypeError + switch { + case errors.Is(err, errClientTerminatedConnection), errors.Is(err, io.EOF), errors.Is(err, net.ErrClosed): + return "client", "client_closed" + case errors.As(err, &closedErr): + return "client", "client_closed" + case errors.As(err, &netErr) && netErr.Timeout(): + return "network", "read_timeout" + case errors.As(err, &syntaxErr), errors.As(err, &typeErr): + return "client", "protocol_error" + case errors.As(err, &closeErr): + if closeErr.Kind.Code == ws.StatusNormalClosure { + return "client", "client_closed" + } + return "client", "protocol_error" + case closeKind == wsproto.CloseKindGoingAway: + return "server", "server_shutdown" + case closeKind == wsproto.CloseKindUnauthorized: + return "router", "authentication_rejected" + case closeKind == wsproto.CloseKindInvalidMessageType, closeKind == wsproto.CloseKindTooManyInits: + return "client", "protocol_error" + case err != nil: + return "network", "network_error" + default: + return "server", "normal_completion" + } +} diff --git a/router/go.mod b/router/go.mod index 16d12d9a44..230afe594a 100644 --- a/router/go.mod +++ b/router/go.mod @@ -180,4 +180,6 @@ require ( // Remember you can use Go workspaces to avoid using replace directives in multiple go.mod files // Use what is best for your personal workflow. See CONTRIBUTING.md for more information -// replace 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. +replace github.com/wundergraph/graphql-go-tools/v2 => github.com/mwisner/graphql-go-tools/v2 v2.16.0-subscription-delivery-diagnostics.1 diff --git a/router/go.sum b/router/go.sum index a3c79cf627..3be6644160 100644 --- a/router/go.sum +++ b/router/go.sum @@ -206,6 +206,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/nats.go v1.50.0 h1:5zAeQrTvyrKrWLJ0fu02W3br8ym57qf7csDzgLOpcds= github.com/nats-io/nats.go v1.50.0/go.mod h1:26HypzazeOkyO3/mqd1zZd53STJN0EjCYF9Uy2ZOBno= github.com/nats-io/nkeys v0.4.15 h1:JACV5jRVO9V856KOapQ7x+EY8Jo3qw1vJt/9Jpwzkk4= @@ -334,8 +336,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/yosida95/uritemplate/v3 v3.0.2 h1:Ed3Oyj9yrmi9087+NczuL5BwkIc4wvTb5zIM+UJPGz4= github.com/yosida95/uritemplate/v3 v3.0.2/go.mod h1:ILOh0sOhIJR3+L/8afwt/kE++YT040gmv5BQTMR2HP4= github.com/yuin/gopher-lua v1.1.1 h1:kYKnWBjvbNP4XLT3+bPEwAXJx262OhaHDWDVOPjL46M= diff --git a/router/pkg/metric/engine_metrics.go b/router/pkg/metric/engine_metrics.go index 204331c8ef..63938f7c6b 100644 --- a/router/pkg/metric/engine_metrics.go +++ b/router/pkg/metric/engine_metrics.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" + rotel "github.com/wundergraph/cosmo/router/pkg/otel" "github.com/wundergraph/cosmo/router/pkg/statistics" "go.opentelemetry.io/otel/attribute" otelmetric "go.opentelemetry.io/otel/metric" @@ -21,6 +22,9 @@ const ( engineSubscriptionCountKey = engineMetricBaseKey + "subscriptions" engineTriggerCountKey = engineMetricBaseKey + "triggers" engineMessagesSentKey = engineMetricBaseKey + "messages.sent" + subscriptionDeliveryAttemptsKey = "router.subscription.delivery.attempts" + subscriptionDeliveryFailuresKey = "router.subscription.delivery.write.failures" + subscriptionDisconnectsKey = "router.subscription.disconnects" engineResolversMaxConcurrentKey = engineMetricBaseKey + "resolvers.max_concurrent" engineResolversInflightKey = engineMetricBaseKey + "resolvers.inflight" ) @@ -30,6 +34,9 @@ type engineInstruments struct { subscriptionCount otelmetric.Int64ObservableUpDownCounter triggerCount otelmetric.Int64ObservableUpDownCounter messagesSent otelmetric.Int64ObservableCounter + deliveryAttempts otelmetric.Int64ObservableCounter + deliveryFailures otelmetric.Int64ObservableCounter + disconnects otelmetric.Int64ObservableCounter resolversMaxConcurrent otelmetric.Int64ObservableUpDownCounter resolversInflight otelmetric.Int64ObservableUpDownCounter } @@ -52,6 +59,9 @@ func (i *engineInstruments) toList() []otelmetric.Observable { if i.messagesSent != nil { result = append(result, i.messagesSent) } + if i.deliveryAttempts != nil { + result = append(result, i.deliveryAttempts, i.deliveryFailures, i.disconnects) + } if i.resolversMaxConcurrent != nil { result = append(result, i.resolversMaxConcurrent) @@ -115,6 +125,9 @@ func setupInstruments(m otelmetric.Meter, statConfig *EngineStatsConfig, resolve subscriptionCount otelmetric.Int64ObservableUpDownCounter triggerCount otelmetric.Int64ObservableUpDownCounter messagesSent otelmetric.Int64ObservableCounter + deliveryAttempts otelmetric.Int64ObservableCounter + deliveryFailures otelmetric.Int64ObservableCounter + disconnects otelmetric.Int64ObservableCounter resolversMaxConcurrent otelmetric.Int64ObservableUpDownCounter resolversInflight otelmetric.Int64ObservableUpDownCounter ) @@ -144,6 +157,22 @@ func setupInstruments(m otelmetric.Meter, statConfig *EngineStatsConfig, resolve if err != nil { return nil, err } + + deliveryAttempts, err = m.Int64ObservableCounter(subscriptionDeliveryAttemptsKey, + otelmetric.WithDescription("Number of downstream subscription delivery attempts.")) + if err != nil { + return nil, err + } + deliveryFailures, err = m.Int64ObservableCounter(subscriptionDeliveryFailuresKey, + otelmetric.WithDescription("Number of downstream subscription write failures.")) + if err != nil { + return nil, err + } + disconnects, err = m.Int64ObservableCounter(subscriptionDisconnectsKey, + otelmetric.WithDescription("Number of downstream subscription transport disconnects.")) + if err != nil { + return nil, err + } } if resolverStats { @@ -165,6 +194,9 @@ func setupInstruments(m otelmetric.Meter, statConfig *EngineStatsConfig, resolve subscriptionCount: subscriptionCount, triggerCount: triggerCount, messagesSent: messagesSent, + deliveryAttempts: deliveryAttempts, + deliveryFailures: deliveryFailures, + disconnects: disconnects, resolversMaxConcurrent: resolversMaxConcurrent, resolversInflight: resolversInflight, }, nil @@ -200,6 +232,31 @@ func (e *EngineMetrics) observeInstruments(o otelmetric.Observer, stats statisti o.ObserveInt64(e.instruments.subscriptionCount, int64(report.Subscriptions), otelmetric.WithAttributes(e.baseAttributes...)) o.ObserveInt64(e.instruments.triggerCount, int64(report.Triggers), otelmetric.WithAttributes(e.baseAttributes...)) o.ObserveInt64(e.instruments.messagesSent, int64(report.MessagesSent), otelmetric.WithAttributes(e.baseAttributes...)) + for _, item := range report.SubscriptionObservations { + attrs := append([]attribute.KeyValue{}, e.baseAttributes...) + attrs = append(attrs, rotel.WgSubscriptionTransport.String(item.Observation.Transport)) + if item.Observation.Subprotocol != "" { + attrs = append(attrs, rotel.WgWebSocketSubprotocol.String(item.Observation.Subprotocol)) + } + switch item.Observation.Kind { + case statistics.SubscriptionObservationDeliveryAttempt: + attrs = append(attrs, rotel.WgSubscriptionFrameType.String(item.Observation.FrameType)) + o.ObserveInt64(e.instruments.deliveryAttempts, int64(item.Count), otelmetric.WithAttributes(attrs...)) + case statistics.SubscriptionObservationDeliveryFailure: + attrs = append(attrs, + rotel.WgSubscriptionFrameType.String(item.Observation.FrameType), + rotel.WgSubscriptionFailureStage.String(item.Observation.FailureStage), + rotel.WgSubscriptionFailureReason.String(item.Observation.FailureReason), + ) + o.ObserveInt64(e.instruments.deliveryFailures, int64(item.Count), otelmetric.WithAttributes(attrs...)) + case statistics.SubscriptionObservationDisconnect: + attrs = append(attrs, + rotel.WgSubscriptionDisconnectInitiator.String(item.Observation.Initiator), + rotel.WgSubscriptionDisconnectReason.String(item.Observation.DisconnectReason), + ) + o.ObserveInt64(e.instruments.disconnects, int64(item.Count), otelmetric.WithAttributes(attrs...)) + } + } } if e.instruments.resolversMaxConcurrent != nil { diff --git a/router/pkg/metric/engine_metrics_test.go b/router/pkg/metric/engine_metrics_test.go new file mode 100644 index 0000000000..11efe9ff29 --- /dev/null +++ b/router/pkg/metric/engine_metrics_test.go @@ -0,0 +1,52 @@ +package metric + +import ( + "context" + "testing" + + "github.com/stretchr/testify/require" + "github.com/wundergraph/cosmo/router/pkg/statistics" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "go.uber.org/zap" +) + +func TestEngineMetricsExportsSubscriptionDeliveryAndDisconnectCounters(t *testing.T) { + reader := sdkmetric.NewManualReader() + provider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + stats := statistics.NewEngineStats(t.Context(), zap.NewNop(), false) + metrics, err := NewEngineMetrics(zap.NewNop(), nil, provider, stats, &EngineStatsConfig{Subscription: true}, false) + require.NoError(t, err) + t.Cleanup(func() { require.NoError(t, metrics.Shutdown()) }) + + stats.ObserveSubscription(statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDeliveryAttempt, + Transport: "sse", + FrameType: "next", + }) + stats.ObserveSubscription(statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDeliveryFailure, + Transport: "sse", + FrameType: "next", + FailureStage: "flush", + FailureReason: "timeout", + }) + stats.ObserveSubscription(statistics.SubscriptionObservation{ + Kind: statistics.SubscriptionObservationDisconnect, + Transport: "sse", + Initiator: "router", + DisconnectReason: "write_timeout", + }) + + var resourceMetrics metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &resourceMetrics)) + names := make(map[string]bool) + for _, scope := range resourceMetrics.ScopeMetrics { + for _, metric := range scope.Metrics { + names[metric.Name] = true + } + } + require.True(t, names[subscriptionDeliveryAttemptsKey]) + require.True(t, names[subscriptionDeliveryFailuresKey]) + require.True(t, names[subscriptionDisconnectsKey]) +} diff --git a/router/pkg/otel/attributes.go b/router/pkg/otel/attributes.go index 07e0deaab2..0b13376637 100644 --- a/router/pkg/otel/attributes.go +++ b/router/pkg/otel/attributes.go @@ -52,6 +52,13 @@ const ( WgIsBatchingOperation = attribute.Key("wg.operation.batching.is_batched") WgBatchingOperationsCount = attribute.Key("wg.operation.batching.operations_count") WgBatchingOperationIndex = attribute.Key("wg.operation.batching.operation_index") + WgSubscriptionTransport = attribute.Key("wg.subscription.transport") + WgSubscriptionFrameType = attribute.Key("wg.subscription.frame_type") + WgSubscriptionFailureStage = attribute.Key("wg.subscription.failure_stage") + WgSubscriptionFailureReason = attribute.Key("wg.subscription.failure_reason") + WgSubscriptionDisconnectInitiator = attribute.Key("wg.subscription.disconnect.initiator") + WgSubscriptionDisconnectReason = attribute.Key("wg.subscription.disconnect.reason") + WgWebSocketSubprotocol = attribute.Key("wg.websocket.subprotocol") // HTTPRequestUploadFileCount is the number of files uploaded in a request (Not specified in the OpenTelemetry specification) HTTPRequestUploadFileCount = attribute.Key("http.request.upload.file_count") diff --git a/router/pkg/pubsub/datasource/provider.go b/router/pkg/pubsub/datasource/provider.go index c1e9fea184..9879864971 100644 --- a/router/pkg/pubsub/datasource/provider.go +++ b/router/pkg/pubsub/datasource/provider.go @@ -5,6 +5,7 @@ import ( "iter" "slices" + "github.com/google/uuid" "github.com/wundergraph/cosmo/router/pkg/metric" ) @@ -90,6 +91,23 @@ type StreamEvent interface { Clone() MutableStreamEvent } +// StreamEventMetadataProvider is an optional extension for preserving a +// source event's identity through subscription fan-out and hooks. +type StreamEventMetadataProvider interface { + StreamEventMetadata() EventMetadata +} + +type EventMetadata struct { + ID string + SourceType string + SourceName string + SourceID string +} + +func NewEventID() string { + return uuid.NewString() +} + // A MutableStreamEvent is a stream event that can be modified. type MutableStreamEvent interface { StreamEvent diff --git a/router/pkg/pubsub/datasource/subscription_event_observability_test.go b/router/pkg/pubsub/datasource/subscription_event_observability_test.go new file mode 100644 index 0000000000..a7a4b32b04 --- /dev/null +++ b/router/pkg/pubsub/datasource/subscription_event_observability_test.go @@ -0,0 +1,61 @@ +package datasource + +import ( + "context" + "testing" + + "github.com/stretchr/testify/require" + "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" + "go.uber.org/zap" +) + +type metadataTestEvent struct { + data []byte + metadata EventMetadata +} + +func (e *metadataTestEvent) GetData() []byte { return e.data } +func (e *metadataTestEvent) Clone() MutableStreamEvent { return nil } +func (e *metadataTestEvent) StreamEventMetadata() EventMetadata { return e.metadata } + +type enrichedUpdaterRecorder struct { + events []resolve.SubscriptionEvent +} + +func (u *enrichedUpdaterRecorder) Update([]byte) {} +func (u *enrichedUpdaterRecorder) UpdateSubscription(resolve.SubscriptionIdentifier, []byte) {} +func (u *enrichedUpdaterRecorder) UpdateEvent(event resolve.SubscriptionEvent) { + u.events = append(u.events, event) +} +func (u *enrichedUpdaterRecorder) UpdateSubscriptionEvent(resolve.SubscriptionIdentifier, resolve.SubscriptionEvent) { +} +func (u *enrichedUpdaterRecorder) Complete() {} +func (u *enrichedUpdaterRecorder) Error([]byte) {} +func (u *enrichedUpdaterRecorder) Done() {} +func (u *enrichedUpdaterRecorder) CloseSubscription(resolve.SubscriptionIdentifier) {} +func (u *enrichedUpdaterRecorder) Subscriptions() map[context.Context]resolve.SubscriptionIdentifier { + return nil +} + +func TestSubscriptionEventUpdaterPreservesSourceMetadata(t *testing.T) { + recorder := &enrichedUpdaterRecorder{} + updater := NewSubscriptionEventUpdater(nil, Hooks{}, recorder, zap.NewNop(), nil) + + updater.Update([]StreamEvent{&metadataTestEvent{ + data: []byte(`{"id":1}`), + metadata: EventMetadata{ + ID: "orders/2/19", + SourceType: "kafka", + SourceName: "orders", + SourceID: "orders/2/19", + }, + }}) + + require.Equal(t, []resolve.SubscriptionEvent{{ + Data: []byte(`{"id":1}`), + ID: "orders/2/19", + SourceType: "kafka", + SourceName: "orders", + SourceID: "orders/2/19", + }}, recorder.events) +} diff --git a/router/pkg/pubsub/datasource/subscription_event_updater.go b/router/pkg/pubsub/datasource/subscription_event_updater.go index 77d01c407a..9378451d98 100644 --- a/router/pkg/pubsub/datasource/subscription_event_updater.go +++ b/router/pkg/pubsub/datasource/subscription_event_updater.go @@ -45,7 +45,7 @@ func (s *subscriptionEventUpdater) Update(events []StreamEvent) { if event == nil { continue } - s.eventUpdater.Update(event.GetData()) + s.updateEvent(event) } return } @@ -187,7 +187,7 @@ func (s *subscriptionEventUpdater) updateSubscription(subscriptionCtx context.Co if event == nil { continue } - s.eventUpdater.UpdateSubscription(subID, event.GetData()) + s.updateSubscriptionEvent(subID, event) } // In case there was an error we close the affected subscription. @@ -196,6 +196,38 @@ func (s *subscriptionEventUpdater) updateSubscription(subscriptionCtx context.Co } } +func (s *subscriptionEventUpdater) updateEvent(event StreamEvent) { + enriched, ok := s.eventUpdater.(resolve.SubscriptionEventUpdater) + if !ok { + s.eventUpdater.Update(event.GetData()) + return + } + enriched.UpdateEvent(resolveSubscriptionEvent(event)) +} + +func (s *subscriptionEventUpdater) updateSubscriptionEvent(id resolve.SubscriptionIdentifier, event StreamEvent) { + enriched, ok := s.eventUpdater.(resolve.SubscriptionEventUpdater) + if !ok { + s.eventUpdater.UpdateSubscription(id, event.GetData()) + return + } + enriched.UpdateSubscriptionEvent(id, resolveSubscriptionEvent(event)) +} + +func resolveSubscriptionEvent(event StreamEvent) resolve.SubscriptionEvent { + result := resolve.SubscriptionEvent{Data: event.GetData()} + metadataProvider, ok := event.(StreamEventMetadataProvider) + if !ok { + return result + } + metadata := metadataProvider.StreamEventMetadata() + result.ID = metadata.ID + result.SourceType = metadata.SourceType + result.SourceName = metadata.SourceName + result.SourceID = metadata.SourceID + return result +} + func (s *subscriptionEventUpdater) recoverPanic(subID resolve.SubscriptionIdentifier, err any) { s.logger. WithOptions(zap.AddStacktrace(zapcore.ErrorLevel)). diff --git a/router/pkg/pubsub/kafka/adapter.go b/router/pkg/pubsub/kafka/adapter.go index 3ee51437f4..7e95fc13a8 100644 --- a/router/pkg/pubsub/kafka/adapter.go +++ b/router/pkg/pubsub/kafka/adapter.go @@ -109,8 +109,15 @@ func (p *ProviderAdapter) topicPoller(ctx context.Context, client *kgo.Client, u DestinationName: r.Topic, }) + eventID := fmt.Sprintf("%s/%d/%d", r.Topic, r.Partition, r.Offset) updater.Update([]datasource.StreamEvent{ &Event{ + metadata: datasource.EventMetadata{ + ID: eventID, + SourceType: "kafka", + SourceName: r.Topic, + SourceID: eventID, + }, evt: &MutableEvent{ Data: r.Value, Headers: headers, diff --git a/router/pkg/pubsub/kafka/engine_datasource.go b/router/pkg/pubsub/kafka/engine_datasource.go index 6606b49015..5184358f68 100644 --- a/router/pkg/pubsub/kafka/engine_datasource.go +++ b/router/pkg/pubsub/kafka/engine_datasource.go @@ -16,7 +16,15 @@ import ( // Event implements datasource.StreamEvent type Event struct { - evt *MutableEvent + evt *MutableEvent + metadata datasource.EventMetadata +} + +func (e *Event) StreamEventMetadata() datasource.EventMetadata { + if e.metadata.ID == "" && e.evt != nil { + return e.evt.metadata + } + return e.metadata } func (e *Event) GetData() []byte { @@ -41,7 +49,11 @@ func (e *Event) GetHeaders() map[string][]byte { } func (e Event) Clone() datasource.MutableStreamEvent { - return e.evt.Clone() + clone, _ := e.evt.Clone().(*MutableEvent) + if clone != nil { + clone.metadata = e.metadata + } + return clone } func cloneHeaders(src map[string][]byte) map[string][]byte { @@ -57,11 +69,14 @@ func cloneHeaders(src map[string][]byte) map[string][]byte { // MutableEvent implements datasource.MutableEvent type MutableEvent struct { - Key []byte `json:"key"` - Data json.RawMessage `json:"data"` - Headers map[string][]byte `json:"headers"` + Key []byte `json:"key"` + Data json.RawMessage `json:"data"` + Headers map[string][]byte `json:"headers"` + metadata datasource.EventMetadata } +func (e *MutableEvent) StreamEventMetadata() datasource.EventMetadata { return e.metadata } + func (e *MutableEvent) GetData() []byte { return e.Data } @@ -240,7 +255,7 @@ func (s *PublishDataSource) Load(ctx context.Context, headers http.Header, input return nil, err } - if err := s.pubSub.Publish(ctx, publishData.PublishEventConfiguration(), []datasource.StreamEvent{&Event{&publishData.Event}}); err != nil { + if err := s.pubSub.Publish(ctx, publishData.PublishEventConfiguration(), []datasource.StreamEvent{&Event{evt: &publishData.Event}}); err != nil { // err will not be returned but only logged inside PubSubProvider.Publish to avoid a "unable to fetch from subgraph" error return []byte(`{"__typename": "edfs__PublishResult", "success": false}`), nil } diff --git a/router/pkg/pubsub/nats/adapter.go b/router/pkg/pubsub/nats/adapter.go index a8ba5c3c7e..752825445d 100644 --- a/router/pkg/pubsub/nats/adapter.go +++ b/router/pkg/pubsub/nats/adapter.go @@ -158,8 +158,22 @@ func (p *ProviderAdapter) Subscribe(ctx context.Context, cfg datasource.Subscrip DestinationName: msg.Subject(), }) + metadata, metadataErr := msg.Metadata() + eventID := datasource.NewEventID() + if metadataErr == nil { + streamName := metadata.Stream + if streamName == "" { + streamName = subConf.StreamConfiguration.StreamName + } + eventID = fmt.Sprintf("%s/%d", streamName, metadata.Sequence.Stream) + } updater.Update([]datasource.StreamEvent{ - &Event{evt: &MutableEvent{ + &Event{metadata: datasource.EventMetadata{ + ID: eventID, + SourceType: "nats", + SourceName: msg.Subject(), + SourceID: eventID, + }, evt: &MutableEvent{ Data: msg.Data(), Headers: map[string][]string(msg.Headers()), }}, @@ -208,8 +222,14 @@ func (p *ProviderAdapter) Subscribe(ctx context.Context, cfg datasource.Subscrip ProviderType: metric.ProviderTypeNats, DestinationName: msg.Subject, }) + eventID := datasource.NewEventID() updater.Update([]datasource.StreamEvent{ - &Event{evt: &MutableEvent{ + &Event{metadata: datasource.EventMetadata{ + ID: eventID, + SourceType: "nats", + SourceName: msg.Subject, + SourceID: eventID, + }, evt: &MutableEvent{ Data: msg.Data, Headers: map[string][]string(msg.Header), }}, diff --git a/router/pkg/pubsub/nats/adapter_consume_test.go b/router/pkg/pubsub/nats/adapter_consume_test.go index c775c6a70a..0089e944fc 100644 --- a/router/pkg/pubsub/nats/adapter_consume_test.go +++ b/router/pkg/pubsub/nats/adapter_consume_test.go @@ -36,6 +36,9 @@ func TestProviderAdapterStreamSubscribe(t *testing.T) { msg.EXPECT().Subject().Return("employeeUpdated.12") msg.EXPECT().Data().Return([]byte(`{"id":13}`)) msg.EXPECT().Headers().Return(nil) + msg.EXPECT().Metadata().Return(&jetstream.MsgMetadata{ + Sequence: jetstream.SequencePair{Stream: 42}, + }, nil) msg.EXPECT().Ack().RunAndReturn(func() error { cancel(); return nil }).Once() batch := NewMockMessageBatch(t) diff --git a/router/pkg/pubsub/nats/engine_datasource.go b/router/pkg/pubsub/nats/engine_datasource.go index 6739c418ba..b6cfece3e3 100644 --- a/router/pkg/pubsub/nats/engine_datasource.go +++ b/router/pkg/pubsub/nats/engine_datasource.go @@ -15,7 +15,15 @@ import ( ) type Event struct { - evt *MutableEvent + evt *MutableEvent + metadata datasource.EventMetadata +} + +func (e *Event) StreamEventMetadata() datasource.EventMetadata { + if e.metadata.ID == "" && e.evt != nil { + return e.evt.metadata + } + return e.metadata } func (e *Event) GetData() []byte { @@ -33,14 +41,21 @@ func (e *Event) GetHeaders() map[string][]string { } func (e Event) Clone() datasource.MutableStreamEvent { - return e.evt.Clone() + clone, _ := e.evt.Clone().(*MutableEvent) + if clone != nil { + clone.metadata = e.metadata + } + return clone } type MutableEvent struct { - Data json.RawMessage `json:"data"` - Headers map[string][]string `json:"headers"` + Data json.RawMessage `json:"data"` + Headers map[string][]string `json:"headers"` + metadata datasource.EventMetadata } +func (e *MutableEvent) StreamEventMetadata() datasource.EventMetadata { return e.metadata } + func (e *MutableEvent) GetData() []byte { if e == nil { return nil @@ -60,13 +75,14 @@ func (e *MutableEvent) Clone() datasource.MutableStreamEvent { return nil } return &MutableEvent{ - Data: slices.Clone(e.Data), - Headers: cloneHeaders(e.Headers), + Data: slices.Clone(e.Data), + Headers: cloneHeaders(e.Headers), + metadata: e.metadata, } } func (e *MutableEvent) ToStreamEvent() datasource.StreamEvent { - return &Event{evt: e} + return &Event{evt: e, metadata: e.metadata} } func cloneHeaders(src map[string][]string) map[string][]string { diff --git a/router/pkg/pubsub/redis/adapter.go b/router/pkg/pubsub/redis/adapter.go index 606a473e96..6ebb2cc5b1 100644 --- a/router/pkg/pubsub/redis/adapter.go +++ b/router/pkg/pubsub/redis/adapter.go @@ -161,8 +161,14 @@ func (p *ProviderAdapter) Subscribe(ctx context.Context, conf datasource.Subscri ProviderType: metric.ProviderTypeRedis, DestinationName: msg.Channel, }) + eventID := datasource.NewEventID() updater.Update([]datasource.StreamEvent{ - &Event{evt: &MutableEvent{ + &Event{metadata: datasource.EventMetadata{ + ID: eventID, + SourceType: "redis", + SourceName: msg.Channel, + SourceID: eventID, + }, evt: &MutableEvent{ Data: []byte(msg.Payload), }}, }) diff --git a/router/pkg/pubsub/redis/engine_datasource.go b/router/pkg/pubsub/redis/engine_datasource.go index 55eee83e20..e6c621b577 100644 --- a/router/pkg/pubsub/redis/engine_datasource.go +++ b/router/pkg/pubsub/redis/engine_datasource.go @@ -15,7 +15,15 @@ import ( ) type Event struct { - evt *MutableEvent + evt *MutableEvent + metadata datasource.EventMetadata +} + +func (e *Event) StreamEventMetadata() datasource.EventMetadata { + if e.metadata.ID == "" && e.evt != nil { + return e.evt.metadata + } + return e.metadata } func (e *Event) GetData() []byte { @@ -26,13 +34,20 @@ func (e *Event) GetData() []byte { } func (e *Event) Clone() datasource.MutableStreamEvent { - return e.evt.Clone() + clone, _ := e.evt.Clone().(*MutableEvent) + if clone != nil { + clone.metadata = e.metadata + } + return clone } type MutableEvent struct { - Data json.RawMessage `json:"data"` + Data json.RawMessage `json:"data"` + metadata datasource.EventMetadata } +func (e *MutableEvent) StreamEventMetadata() datasource.EventMetadata { return e.metadata } + func (e *MutableEvent) GetData() []byte { if e == nil { return nil @@ -53,7 +68,8 @@ func (e *MutableEvent) Clone() datasource.MutableStreamEvent { } return &MutableEvent{ - Data: slices.Clone(e.Data), + Data: slices.Clone(e.Data), + metadata: e.metadata, } } diff --git a/router/pkg/statistics/engine_stats.go b/router/pkg/statistics/engine_stats.go index 80b159afe6..6a17850d93 100644 --- a/router/pkg/statistics/engine_stats.go +++ b/router/pkg/statistics/engine_stats.go @@ -30,26 +30,59 @@ type EngineStatistics interface { UnregisterResolver(r ResolverConcurrencyReporter) } +type SubscriptionObservationKind string + +const ( + SubscriptionObservationDeliveryAttempt SubscriptionObservationKind = "delivery_attempt" + SubscriptionObservationDeliveryFailure SubscriptionObservationKind = "delivery_failure" + SubscriptionObservationDisconnect SubscriptionObservationKind = "disconnect" +) + +// SubscriptionObservation contains only bounded values suitable for metric +// dimensions. Event, connection, operation, and client identity belong in +// structured logs and must not be added here. +type SubscriptionObservation struct { + Kind SubscriptionObservationKind + Transport string + FrameType string + FailureStage string + FailureReason string + Initiator string + DisconnectReason string + Subprotocol string +} + +type SubscriptionObserver interface { + ObserveSubscription(SubscriptionObservation) +} + +type SubscriptionObservationCount struct { + Observation SubscriptionObservation + Count uint64 +} + type EngineStats struct { - ctx context.Context - logger *zap.Logger - reportStats bool - connections atomic.Uint64 - subscriptions atomic.Uint64 - messagesSent atomic.Uint64 - triggers atomic.Uint64 + ctx context.Context + logger *zap.Logger + reportStats bool + connections atomic.Uint64 + subscriptions atomic.Uint64 + messagesSent atomic.Uint64 + triggers atomic.Uint64 + subscriptionObservations sync.Map // map[SubscriptionObservation]*atomic.Uint64 resolverMu sync.RWMutex resolverReporters map[ResolverConcurrencyReporter]struct{} } type UsageReport struct { - Connections uint64 - Subscriptions uint64 - MessagesSent uint64 - Triggers uint64 - ResolverMaxConcurrent uint64 - ResolverInflight uint64 + Connections uint64 + Subscriptions uint64 + MessagesSent uint64 + Triggers uint64 + ResolverMaxConcurrent uint64 + ResolverInflight uint64 + SubscriptionObservations []SubscriptionObservationCount } // NewEngineStats creates a new EngineStats instance. If reportStats is true, the stats will be reported every 5 seconds. @@ -79,6 +112,13 @@ func (s *EngineStats) GetReport() *UsageReport { report.ResolverInflight += uint64(r.InflightResolves()) } s.resolverMu.RUnlock() + s.subscriptionObservations.Range(func(key, value any) bool { + report.SubscriptionObservations = append(report.SubscriptionObservations, SubscriptionObservationCount{ + Observation: key.(SubscriptionObservation), + Count: value.(*atomic.Uint64).Load(), + }) + return true + }) return report } @@ -108,6 +148,11 @@ func (s *EngineStats) SubscriptionUpdateSent() { s.messagesSent.Inc() } +func (s *EngineStats) ObserveSubscription(observation SubscriptionObservation) { + counter, _ := s.subscriptionObservations.LoadOrStore(observation, &atomic.Uint64{}) + counter.(*atomic.Uint64).Inc() +} + func (s *EngineStats) ConnectionsInc() { s.connections.Inc() } @@ -166,6 +211,8 @@ func (s *NoopEngineStats) GetReport() *UsageReport { func (s *NoopEngineStats) SubscriptionUpdateSent() {} +func (s *NoopEngineStats) ObserveSubscription(_ SubscriptionObservation) {} + func (s *NoopEngineStats) ConnectionsInc() {} func (s *NoopEngineStats) ConnectionsDec() {} @@ -187,3 +234,5 @@ func (s *NoopEngineStats) UnregisterResolver(_ ResolverConcurrencyReporter) {} var _ EngineStatistics = &EngineStats{} var _ EngineStatistics = &NoopEngineStats{} +var _ SubscriptionObserver = &EngineStats{} +var _ SubscriptionObserver = &NoopEngineStats{} From 5b5aa3791e84f6656120ba3fc1d6a8fb7b841231 Mon Sep 17 00:00:00 2001 From: Matt Wisner Date: Thu, 20 Aug 2026 10:02:13 -0400 Subject: [PATCH 4/5] fix(router): make delivery diagnostics CI-safe --- router-tests/go.mod | 4 ++- router-tests/go.sum | 4 +-- router/core/graphql_handler.go | 2 -- .../subscription_delivery_observability.go | 8 ------ ...ubscription_delivery_observability_test.go | 4 +-- router/core/websocket.go | 27 +++++++------------ 6 files changed, 17 insertions(+), 32 deletions(-) diff --git a/router-tests/go.mod b/router-tests/go.mod index f120748976..ecc0270c42 100644 --- a/router-tests/go.mod +++ b/router-tests/go.mod @@ -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 ) diff --git a/router-tests/go.sum b/router-tests/go.sum index 25513225dc..db6d87a189 100644 --- a/router-tests/go.sum +++ b/router-tests/go.sum @@ -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= @@ -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= diff --git a/router/core/graphql_handler.go b/router/core/graphql_handler.go index ce65f5cda0..e8322a21d7 100644 --- a/router/core/graphql_handler.go +++ b/router/core/graphql_handler.go @@ -304,8 +304,6 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { transport: subscriptionTransportSSE, requestID: middleware.GetReqID(r.Context()), operationName: reqCtx.operation.name, - clientName: reqCtx.operation.clientInfo.Name, - clientVersion: reqCtx.operation.clientInfo.Version, writeTimeout: h.sseServerWriteTimeout, }, }) diff --git a/router/core/subscription_delivery_observability.go b/router/core/subscription_delivery_observability.go index 65cd8f4f61..dc2b4e4b1d 100644 --- a/router/core/subscription_delivery_observability.go +++ b/router/core/subscription_delivery_observability.go @@ -23,8 +23,6 @@ type subscriptionTelemetryContext struct { subprotocol string requestID string operationName string - clientName string - clientVersion string connectionID resolve.ConnectionID writeTimeout time.Duration } @@ -64,8 +62,6 @@ func (t *subscriptionDisconnectTracker) disconnect(initiator, reason string, err zap.String("transport", t.telemetry.transport), zap.String("websocket_subprotocol", t.telemetry.subprotocol), zap.String("request_id", t.telemetry.requestID), - zap.String("client_name", t.telemetry.clientName), - zap.String("client_version", t.telemetry.clientVersion), zap.Int64("connection_id", int64(t.telemetry.connectionID)), zap.String("disconnect_initiator", initiator), zap.String("disconnect_reason", reason), @@ -134,8 +130,6 @@ func observeSubscriptionDelivery(stats statistics.EngineStatistics, logger *zap. zap.String("websocket_subprotocol", telemetry.subprotocol), zap.String("request_id", telemetry.requestID), zap.String("operation_name", telemetry.operationName), - zap.String("client_name", telemetry.clientName), - zap.String("client_version", telemetry.clientVersion), zap.Int64("connection_id", int64(report.ConnectionID)), zap.Int64("subscription_id", report.SubscriptionID), zap.Uint64("trigger_id", report.TriggerID), @@ -180,8 +174,6 @@ func observeSubscriptionFrame(stats statistics.EngineStatistics, logger *zap.Log zap.String("websocket_subprotocol", telemetry.subprotocol), zap.String("request_id", telemetry.requestID), zap.String("operation_name", telemetry.operationName), - zap.String("client_name", telemetry.clientName), - zap.String("client_version", telemetry.clientVersion), zap.Int64("connection_id", int64(telemetry.connectionID)), zap.String("frame_type", frameType), zap.String("failure_stage", stage), diff --git a/router/core/subscription_delivery_observability_test.go b/router/core/subscription_delivery_observability_test.go index d7f2f5c98b..4c3a7555e9 100644 --- a/router/core/subscription_delivery_observability_test.go +++ b/router/core/subscription_delivery_observability_test.go @@ -22,8 +22,6 @@ func TestObserveSubscriptionDeliveryRecordsFailureWithoutPayload(t *testing.T) { transport: subscriptionTransportSSE, requestID: "request-1", operationName: "ProductUpdated", - clientName: "storefront", - clientVersion: "1.2.3", } observeSubscriptionDelivery(stats, zap.New(logCore), telemetry, resolve.SubscriptionDeliveryReport{ @@ -48,6 +46,8 @@ func TestObserveSubscriptionDeliveryRecordsFailureWithoutPayload(t *testing.T) { require.Equal(t, "flush", fields["failure_stage"]) require.Equal(t, "timeout", fields["failure_reason"]) require.NotContains(t, fields, "payload") + require.NotContains(t, fields, "client_name") + require.NotContains(t, fields, "client_version") } func TestSubscriptionDisconnectTrackerRecordsOnce(t *testing.T) { diff --git a/router/core/websocket.go b/router/core/websocket.go index 557c313912..d42f5f76c3 100644 --- a/router/core/websocket.go +++ b/router/core/websocket.go @@ -857,13 +857,11 @@ var detectNonRegex = regexp.MustCompile(`^[A-Za-z0-9_-]+$`) func NewWebsocketConnectionHandler(ctx context.Context, opts WebSocketConnectionHandlerOptions) *WebSocketConnectionHandler { telemetry := subscriptionTelemetryContext{ - transport: subscriptionTransportWebSocket, - subprotocol: opts.Protocol.Subprotocol(), - requestID: opts.InitRequestID, - clientName: opts.ClientInfo.Name, - clientVersion: opts.ClientInfo.Version, - connectionID: opts.ConnectionID, - writeTimeout: opts.Connection.writeTimeout, + transport: subscriptionTransportWebSocket, + subprotocol: opts.Protocol.Subprotocol(), + requestID: opts.InitRequestID, + connectionID: opts.ConnectionID, + writeTimeout: opts.Connection.writeTimeout, } handler := &WebSocketConnectionHandler{ ctx: ctx, @@ -1099,13 +1097,11 @@ func (h *WebSocketConnectionHandler) parseAndPlan(registration *SubscriptionRegi func (h *WebSocketConnectionHandler) executeSubscription(registration *SubscriptionRegistration) { rw := newWebsocketResponseWriter(registration.msg.ID, h.protocol, h.graphqlHandler.subgraphErrorPropagation.Enabled, h.logger, h.stats, &h.subscriptions, subscriptionTelemetryContext{ - transport: subscriptionTransportWebSocket, - subprotocol: h.protocol.Subprotocol(), - requestID: h.initRequestID, - clientName: h.clientInfo.Name, - clientVersion: h.clientInfo.Version, - connectionID: h.connectionID, - writeTimeout: h.conn.writeTimeout, + transport: subscriptionTransportWebSocket, + subprotocol: h.protocol.Subprotocol(), + requestID: h.initRequestID, + connectionID: h.connectionID, + writeTimeout: h.conn.writeTimeout, }) _, operationCtx, err := h.parseAndPlan(registration) @@ -1354,9 +1350,6 @@ func (h *WebSocketConnectionHandler) Initialize() (err error) { h.request.Header.Set(h.clientInfoFromInitialPayload.ForwardToRequestHeaders.VersionTargetHeader, clientVersion) } } - h.disconnect.telemetry.clientName = h.clientInfo.Name - h.disconnect.telemetry.clientVersion = h.clientInfo.Version - // Update planner options with new client info h.plannerOptions.ClientInfo = h.clientInfo } From e3ed5f4c62bdc09578e1e00d1c3a50941012bfe2 Mon Sep 17 00:00:00 2001 From: Matt Wisner Date: Thu, 20 Aug 2026 11:06:30 -0400 Subject: [PATCH 5/5] refactor(router): keep delivery diagnostics transport-local --- .../router/metrics-and-monitoring.mdx | 2 +- router-tests/go.mod | 4 +- router-tests/go.sum | 4 +- .../subscription_delivery_observability.go | 73 +++++++++----- ...ubscription_delivery_observability_test.go | 95 +++++++++++++++---- router/core/subscription_response_writer.go | 41 +++++--- .../core/subscription_response_writer_test.go | 36 +++++++ router/core/websocket.go | 20 ++-- router/go.mod | 4 +- router/go.sum | 4 +- router/pkg/metric/engine_metrics.go | 8 +- router/pkg/metric/engine_metrics_test.go | 35 ++++++- router/pkg/pubsub/datasource/provider.go | 18 ---- .../subscription_event_observability_test.go | 61 ------------ .../datasource/subscription_event_updater.go | 36 +------ router/pkg/pubsub/kafka/adapter.go | 7 -- router/pkg/pubsub/kafka/engine_datasource.go | 27 ++---- router/pkg/pubsub/nats/adapter.go | 24 +---- .../pkg/pubsub/nats/adapter_consume_test.go | 3 - router/pkg/pubsub/nats/engine_datasource.go | 30 ++---- router/pkg/pubsub/redis/adapter.go | 8 +- router/pkg/pubsub/redis/engine_datasource.go | 24 +---- 22 files changed, 266 insertions(+), 298 deletions(-) delete mode 100644 router/pkg/pubsub/datasource/subscription_event_observability_test.go diff --git a/docs-website/router/metrics-and-monitoring.mdx b/docs-website/router/metrics-and-monitoring.mdx index 77d59af130..71cdbad31a 100644 --- a/docs-website/router/metrics-and-monitoring.mdx +++ b/docs-website/router/metrics-and-monitoring.mdx @@ -253,7 +253,7 @@ telemetry: * `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. +Failed event writes also produce a structured `Subscription event delivery failed` log containing request, connection, subscription, and operation identifiers; a router-local delivery sequence; the write duration; and the configured timeout. Payloads are represented by a SHA-256 hash and byte count and are not logged. The delivery sequence is scoped to one subscription and is intended to distinguish its attempted events; it is not a broker offset. 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 diff --git a/router-tests/go.mod b/router-tests/go.mod index ecc0270c42..f120748976 100644 --- a/router-tests/go.mod +++ b/router-tests/go.mod @@ -209,7 +209,5 @@ replace ( github.com/wundergraph/cosmo/router => ../router github.com/wundergraph/cosmo/router-plugin => ../router-plugin github.com/wundergraph/cosmo/speedtrap => ../speedtrap - // 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 +// github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 ) diff --git a/router-tests/go.sum b/router-tests/go.sum index db6d87a189..25513225dc 100644 --- a/router-tests/go.sum +++ b/router-tests/go.sum @@ -246,8 +246,6 @@ 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= @@ -388,6 +386,8 @@ 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= diff --git a/router/core/subscription_delivery_observability.go b/router/core/subscription_delivery_observability.go index dc2b4e4b1d..3bd41ab8a7 100644 --- a/router/core/subscription_delivery_observability.go +++ b/router/core/subscription_delivery_observability.go @@ -2,9 +2,12 @@ package core import ( "context" + "crypto/sha256" + "encoding/hex" "errors" "net" "sync" + "sync/atomic" "syscall" "time" @@ -39,6 +42,14 @@ type subscriptionDisconnectTracker struct { telemetry subscriptionTelemetryContext } +type subscriptionDeliveryTracker struct { + sequence atomic.Uint64 + failureLogged atomic.Bool + stats statistics.EngineStatistics + logger *zap.Logger + subscription string +} + func newSubscriptionDisconnectTracker(stats statistics.EngineStatistics, logger *zap.Logger, telemetry subscriptionTelemetryContext) *subscriptionDisconnectTracker { if logger == nil { logger = zap.NewNop() @@ -46,6 +57,13 @@ func newSubscriptionDisconnectTracker(stats statistics.EngineStatistics, logger return &subscriptionDisconnectTracker{stats: stats, logger: logger, telemetry: telemetry} } +func newSubscriptionDeliveryTracker(stats statistics.EngineStatistics, logger *zap.Logger, subscription string) *subscriptionDeliveryTracker { + if logger == nil { + logger = zap.NewNop() + } + return &subscriptionDeliveryTracker{stats: stats, logger: logger, subscription: subscription} +} + func (t *subscriptionDisconnectTracker) disconnect(initiator, reason string, err error) { if t == nil { return @@ -84,6 +102,8 @@ func disconnectReasonFromWriteError(err error) (initiator, reason string) { return "router", "write_timeout" case "client_disconnected": return "client", "client_closed" + case "connection_closed": + return "router", "connection_closed" case "context_canceled": return "client", "context_canceled" default: @@ -91,9 +111,8 @@ func disconnectReasonFromWriteError(err error) (initiator, reason string) { } } -func (e *subscriptionWriteError) Error() string { return e.err.Error() } -func (e *subscriptionWriteError) Unwrap() error { return e.err } -func (e *subscriptionWriteError) IsSubscriptionDeliveryError() {} +func (e *subscriptionWriteError) Error() string { return e.err.Error() } +func (e *subscriptionWriteError) Unwrap() error { return e.err } func wrapSubscriptionWriteError(stage string, err error) error { if err == nil { @@ -102,22 +121,23 @@ func wrapSubscriptionWriteError(stage string, err error) error { return &subscriptionWriteError{stage: stage, err: err} } -func observeSubscriptionDelivery(stats statistics.EngineStatistics, logger *zap.Logger, telemetry subscriptionTelemetryContext, report resolve.SubscriptionDeliveryReport) { - observeSubscription(stats, statistics.SubscriptionObservation{ +func (t *subscriptionDeliveryTracker) observe(telemetry subscriptionTelemetryContext, payload []byte, duration time.Duration, err error) { + if t == nil { + return + } + deliverySequence := t.sequence.Add(1) + observeSubscription(t.stats, statistics.SubscriptionObservation{ Kind: statistics.SubscriptionObservationDeliveryAttempt, Transport: telemetry.transport, FrameType: "next", Subprotocol: telemetry.subprotocol, }) - if report.Err == nil { + if err == nil { return } - if logger == nil { - logger = zap.NewNop() - } - stage, reason := classifySubscriptionWriteFailure(report.Err) - observeSubscription(stats, statistics.SubscriptionObservation{ + stage, reason := classifySubscriptionWriteFailure(err) + observeSubscription(t.stats, statistics.SubscriptionObservation{ Kind: statistics.SubscriptionObservationDeliveryFailure, Transport: telemetry.transport, FrameType: "next", @@ -125,26 +145,29 @@ func observeSubscriptionDelivery(stats statistics.EngineStatistics, logger *zap. FailureReason: reason, Subprotocol: telemetry.subprotocol, }) - logger.Warn("Subscription event delivery failed", + payloadHash := sha256.Sum256(payload) + fields := []zap.Field{ zap.String("transport", telemetry.transport), zap.String("websocket_subprotocol", telemetry.subprotocol), zap.String("request_id", telemetry.requestID), zap.String("operation_name", telemetry.operationName), - zap.Int64("connection_id", int64(report.ConnectionID)), - zap.Int64("subscription_id", report.SubscriptionID), - zap.Uint64("trigger_id", report.TriggerID), - zap.String("event_id", report.EventID), - zap.String("event_hash", report.EventHash), - zap.Int("event_bytes", report.EventBytes), - zap.String("event_source_type", report.SourceType), - zap.String("event_source_name", report.SourceName), - zap.String("event_source_id", report.SourceID), + zap.Int64("connection_id", int64(telemetry.connectionID)), + zap.String("subscription_id", t.subscription), + zap.Uint64("delivery_sequence", deliverySequence), + zap.String("payload_sha256", hex.EncodeToString(payloadHash[:])), + zap.Int("payload_bytes", len(payload)), zap.String("frame_type", "next"), zap.String("failure_stage", stage), zap.String("failure_reason", reason), zap.Int64("configured_write_timeout_ms", telemetry.writeTimeout.Milliseconds()), - zap.Error(report.Err), - ) + zap.Float64("write_duration_ms", float64(duration)/float64(time.Millisecond)), + zap.Error(err), + } + if t.failureLogged.CompareAndSwap(false, true) { + t.logger.Warn("Subscription event delivery failed", fields...) + return + } + t.logger.Debug("Subscription event delivery failed", fields...) } func observeSubscriptionFrame(stats statistics.EngineStatistics, logger *zap.Logger, telemetry subscriptionTelemetryContext, frameType string, err error) { @@ -206,7 +229,9 @@ func classifySubscriptionWriteFailure(err error) (stage, reason string) { return stage, "timeout" case errors.Is(err, context.Canceled): return stage, "context_canceled" - case errors.Is(err, net.ErrClosed), errors.Is(err, syscall.EPIPE), errors.Is(err, syscall.ECONNRESET): + case errors.Is(err, net.ErrClosed): + return stage, "connection_closed" + case errors.Is(err, syscall.EPIPE), errors.Is(err, syscall.ECONNRESET): return stage, "client_disconnected" case errors.Is(err, errors.ErrUnsupported): return stage, "unsupported" diff --git a/router/core/subscription_delivery_observability_test.go b/router/core/subscription_delivery_observability_test.go index 4c3a7555e9..c376d2f2a6 100644 --- a/router/core/subscription_delivery_observability_test.go +++ b/router/core/subscription_delivery_observability_test.go @@ -2,20 +2,41 @@ package core import ( "context" + "crypto/sha256" + "encoding/hex" + "encoding/json" "errors" "testing" + "time" "github.com/gobwas/ws" "github.com/stretchr/testify/require" "github.com/wundergraph/cosmo/router/internal/wsproto" "github.com/wundergraph/cosmo/router/pkg/statistics" - "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" "go.uber.org/zap" "go.uber.org/zap/zapcore" zapobserver "go.uber.org/zap/zaptest/observer" ) -func TestObserveSubscriptionDeliveryRecordsFailureWithoutPayload(t *testing.T) { +type failingSubscriptionProtocol struct { + writeErr error +} + +func (p *failingSubscriptionProtocol) Subprotocol() string { return wsproto.GraphQLWSSubprotocol } +func (p *failingSubscriptionProtocol) Initialize() (json.RawMessage, error) { + return nil, nil +} +func (p *failingSubscriptionProtocol) ReadMessage() (*wsproto.Message, error) { return nil, nil } +func (p *failingSubscriptionProtocol) Pong(*wsproto.Message) error { return nil } +func (p *failingSubscriptionProtocol) WriteGraphQLData(string, json.RawMessage, json.RawMessage) error { + return p.writeErr +} +func (p *failingSubscriptionProtocol) WriteGraphQLErrors(string, json.RawMessage, json.RawMessage) error { + return p.writeErr +} +func (p *failingSubscriptionProtocol) Complete(string) error { return p.writeErr } + +func TestSubscriptionDeliveryTrackerRecordsFailureWithoutPayload(t *testing.T) { logCore, logs := zapobserver.New(zapcore.DebugLevel) stats := statistics.NewEngineStats(t.Context(), zap.NewNop(), false) telemetry := subscriptionTelemetryContext{ @@ -24,28 +45,32 @@ func TestObserveSubscriptionDeliveryRecordsFailureWithoutPayload(t *testing.T) { operationName: "ProductUpdated", } - observeSubscriptionDelivery(stats, zap.New(logCore), telemetry, resolve.SubscriptionDeliveryReport{ - TriggerID: 3, - ConnectionID: 5, - SubscriptionID: 7, - EventID: "orders/2/19", - EventHash: "abc123", - EventBytes: 17, - SourceType: "kafka", - SourceName: "orders", - SourceID: "orders/2/19", - Err: wrapSubscriptionWriteError("flush", context.DeadlineExceeded), - }) + payload := []byte(`{"data":{"productUpdated":{"id":"1"}}}`) + tracker := newSubscriptionDeliveryTracker(stats, zap.New(logCore), "subscription-7") + tracker.observe(telemetry, payload, 25*time.Millisecond, wrapSubscriptionWriteError("flush", context.DeadlineExceeded)) report := stats.GetReport() require.Len(t, report.SubscriptionObservations, 2) + observations := make(map[statistics.SubscriptionObservationKind]statistics.SubscriptionObservationCount, 2) + for _, observation := range report.SubscriptionObservations { + observations[observation.Observation.Kind] = observation + } + require.Equal(t, uint64(1), observations[statistics.SubscriptionObservationDeliveryAttempt].Count) + require.Equal(t, uint64(1), observations[statistics.SubscriptionObservationDeliveryFailure].Count) + require.Equal(t, "flush", observations[statistics.SubscriptionObservationDeliveryFailure].Observation.FailureStage) + require.Equal(t, "timeout", observations[statistics.SubscriptionObservationDeliveryFailure].Observation.FailureReason) require.Equal(t, 1, logs.Len()) fields := logs.All()[0].ContextMap() - require.Equal(t, "orders/2/19", fields["event_id"]) - require.Equal(t, "abc123", fields["event_hash"]) + payloadHash := sha256.Sum256(payload) + require.Equal(t, "subscription-7", fields["subscription_id"]) + require.Equal(t, uint64(1), fields["delivery_sequence"]) + require.Equal(t, hex.EncodeToString(payloadHash[:]), fields["payload_sha256"]) + require.Equal(t, int64(len(payload)), fields["payload_bytes"]) + require.Equal(t, 25.0, fields["write_duration_ms"]) require.Equal(t, "flush", fields["failure_stage"]) require.Equal(t, "timeout", fields["failure_reason"]) require.NotContains(t, fields, "payload") + require.NotContains(t, fields, "event_source_id") require.NotContains(t, fields, "client_name") require.NotContains(t, fields, "client_version") } @@ -69,10 +94,44 @@ func TestSubscriptionDisconnectTrackerRecordsOnce(t *testing.T) { require.Equal(t, "client_closed", report.SubscriptionObservations[0].Observation.DisconnectReason) } +func TestWebsocketResponseWriterObservesFailedEventAtTransport(t *testing.T) { + logCore, logs := zapobserver.New(zapcore.DebugLevel) + stats := statistics.NewEngineStats(t.Context(), zap.NewNop(), false) + payload := []byte(`{"data":{"productUpdated":{"id":"1"}}}`) + rw := newWebsocketResponseWriter( + "subscription-1", + &failingSubscriptionProtocol{writeErr: context.DeadlineExceeded}, + false, + zap.New(logCore), + stats, + nil, + subscriptionTelemetryContext{ + transport: subscriptionTransportWebSocket, + subprotocol: wsproto.GraphQLWSSubprotocol, + requestID: "request-1", + operationName: "ProductUpdated", + }, + ) + + _, err := rw.Write(payload) + require.NoError(t, err) + require.ErrorIs(t, rw.Flush(), context.DeadlineExceeded) + + report := stats.GetReport() + require.Len(t, report.SubscriptionObservations, 2) + require.Equal(t, 1, logs.Len()) + fields := logs.All()[0].ContextMap() + require.Equal(t, "websocket", fields["transport"]) + require.Equal(t, "subscription-1", fields["subscription_id"]) + require.Equal(t, uint64(1), fields["delivery_sequence"]) + require.Equal(t, "write", fields["failure_stage"]) + require.Equal(t, "timeout", fields["failure_reason"]) +} + func TestWebsocketDisconnectReasonUsesOriginalError(t *testing.T) { initiator, reason := websocketDisconnectReason(context.DeadlineExceeded, wsproto.CloseKindNormal) require.Equal(t, "network", initiator) - require.Equal(t, "read_timeout", reason) + require.Equal(t, "timeout", reason) initiator, reason = websocketDisconnectReason(errClientTerminatedConnection, wsproto.CloseKindNormal) require.Equal(t, "client", initiator) @@ -91,8 +150,6 @@ func TestHttpFlushWriterMarksContextFailuresAsDeliveryErrors(t *testing.T) { writer := &HttpFlushWriter{ctx: ctx} _, err := writer.Write([]byte(`{"data":{}}`)) - var deliveryErr resolve.SubscriptionDeliveryError - require.ErrorAs(t, err, &deliveryErr) stage, reason := classifySubscriptionWriteFailure(err) require.Equal(t, "buffer", stage) require.Equal(t, "context_canceled", reason) diff --git a/router/core/subscription_response_writer.go b/router/core/subscription_response_writer.go index 4b03efdf67..2cfca556b0 100644 --- a/router/core/subscription_response_writer.go +++ b/router/core/subscription_response_writer.go @@ -61,6 +61,7 @@ type HttpFlushWriter struct { telemetry subscriptionTelemetryContext requestContext context.Context disconnect *subscriptionDisconnectTracker + delivery *subscriptionDeliveryTracker // apolloSubscriptionMultipartPrintBoundary if set to true will send the multipart boundary at the end of the message to allow // misbehaving client (like apollo client) to read the message just sent before the next one or the heartbeat apolloSubscriptionMultipartPrintBoundary bool @@ -103,7 +104,13 @@ func (f *HttpFlushWriter) Complete() { func (f *HttpFlushWriter) Write(p []byte) (n int, err error) { if err = f.ctx.Err(); err != nil { - return 0, wrapSubscriptionWriteError("buffer", err) + err = wrapSubscriptionWriteError("buffer", err) + if f.sse { + f.delivery.observe(f.telemetry, p, 0, err) + initiator, reason := disconnectReasonFromWriteError(err) + f.disconnect.disconnect(initiator, reason, err) + } + return 0, err } return f.buf.Write(p) @@ -145,7 +152,7 @@ func (f *HttpFlushWriter) Error(data []byte) { return } _, _ = f.buf.Write(data) - err := f.Flush() + err := f.flush("terminal_error") if f.sse { observeSubscriptionFrame(f.stats, f.logger, f.telemetry, "terminal_error", err) if err != nil { @@ -158,17 +165,6 @@ func (f *HttpFlushWriter) Error(data []byte) { f.cancel() } -func (f *HttpFlushWriter) ReportSubscriptionDelivery(report resolve.SubscriptionDeliveryReport) { - if !f.sse { - return - } - observeSubscriptionDelivery(f.stats, f.logger, f.telemetry, report) - if report.Err != nil { - initiator, reason := disconnectReasonFromWriteError(report.Err) - f.disconnect.disconnect(initiator, reason, report.Err) - } -} - func (f *HttpFlushWriter) subscriptionRequestEnded() { if !f.sse { return @@ -181,7 +177,17 @@ func (f *HttpFlushWriter) subscriptionRequestEnded() { } func (f *HttpFlushWriter) Flush() (err error) { + return f.flush("next") +} + +func (f *HttpFlushWriter) flush(frameType string) (err error) { if err = f.ctx.Err(); err != nil { + if f.sse && frameType == "next" { + err = wrapSubscriptionWriteError("buffer", err) + f.delivery.observe(f.telemetry, f.buf.Bytes(), 0, err) + initiator, reason := disconnectReasonFromWriteError(err) + f.disconnect.disconnect(initiator, reason, err) + } return err } @@ -219,10 +225,18 @@ func (f *HttpFlushWriter) Flush() (err error) { full := flushBreak + string(resp) + separation if f.sse { + started := time.Now() err = f.writeAndFlushSSE(func() error { _, writeErr := f.writer.Write([]byte(full)) return writeErr }) + if frameType == "next" { + f.delivery.observe(f.telemetry, []byte(full), time.Since(started), err) + if err != nil { + initiator, reason := disconnectReasonFromWriteError(err) + f.disconnect.disconnect(initiator, reason, err) + } + } } else { _, err = f.writer.Write([]byte(full)) if err == nil { @@ -288,6 +302,7 @@ func GetSubscriptionResponseWriter(ctx *resolve.Context, r *http.Request, w http } if flushWriter.sse { flushWriter.disconnect = newSubscriptionDisconnectTracker(flushWriter.stats, flushWriter.logger, flushWriter.telemetry) + flushWriter.delivery = newSubscriptionDeliveryTracker(flushWriter.stats, flushWriter.logger, "") } flushWriter.ctx, flushWriter.cancel = context.WithCancel(ctx.Context()) diff --git a/router/core/subscription_response_writer_test.go b/router/core/subscription_response_writer_test.go index f219412cfd..9b9dab0a0a 100644 --- a/router/core/subscription_response_writer_test.go +++ b/router/core/subscription_response_writer_test.go @@ -11,7 +11,11 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "github.com/wundergraph/cosmo/router/pkg/statistics" "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + zapobserver "go.uber.org/zap/zaptest/observer" ) type deadlineRecorder struct { @@ -204,6 +208,38 @@ func TestGetSubscriptionResponseWriter(t *testing.T) { require.ErrorIs(t, writer.Heartbeat(), flushErr) }) + t.Run("observes a failed SSE event at the transport writer", func(t *testing.T) { + recorder := &deadlineRecorder{ResponseRecorder: httptest.NewRecorder()} + req := httptest.NewRequest(http.MethodPost, "/graphql", nil) + req.Header.Set("Accept", sseMimeType) + logCore, logs := zapobserver.New(zapcore.DebugLevel) + stats := statistics.NewEngineStats(t.Context(), zap.NewNop(), false) + + _, writer, err := GetSubscriptionResponseWriter(resolve.NewContext(context.Background()), req, recorder, SubscriptionResponseWriterOptions{ + Logger: zap.New(logCore), + Stats: stats, + Telemetry: subscriptionTelemetryContext{ + transport: subscriptionTransportSSE, + requestID: "request-1", + operationName: "ProductUpdated", + }, + }) + require.NoError(t, err) + recorder.flushErr = context.DeadlineExceeded + + _, err = writer.Write([]byte(`{"data":{"productUpdated":{"id":"1"}}}`)) + require.NoError(t, err) + require.ErrorIs(t, writer.Flush(), context.DeadlineExceeded) + + require.Len(t, stats.GetReport().SubscriptionObservations, 4) + require.Equal(t, 1, logs.FilterMessage("Subscription event delivery failed").Len()) + fields := logs.FilterMessage("Subscription event delivery failed").All()[0].ContextMap() + require.Equal(t, "sse", fields["transport"]) + require.Equal(t, uint64(1), fields["delivery_sequence"]) + require.Equal(t, "flush", fields["failure_stage"]) + require.Equal(t, "timeout", fields["failure_reason"]) + }) + t.Run("propagates an SSE deadline error", func(t *testing.T) { recorder := &deadlineRecorder{ResponseRecorder: httptest.NewRecorder()} req := httptest.NewRequest(http.MethodPost, "/graphql", nil) diff --git a/router/core/websocket.go b/router/core/websocket.go index d42f5f76c3..513c588679 100644 --- a/router/core/websocket.go +++ b/router/core/websocket.go @@ -638,12 +638,12 @@ type websocketResponseWriter struct { propagateErrors bool subscriptions *sync.Map telemetry subscriptionTelemetryContext + delivery *subscriptionDeliveryTracker } var ( - _ http.ResponseWriter = (*websocketResponseWriter)(nil) - _ resolve.SubscriptionResponseWriter = (*websocketResponseWriter)(nil) - _ resolve.SubscriptionDeliveryReporter = (*websocketResponseWriter)(nil) + _ http.ResponseWriter = (*websocketResponseWriter)(nil) + _ resolve.SubscriptionResponseWriter = (*websocketResponseWriter)(nil) ) func newWebsocketResponseWriter(id string, protocol wsproto.Proto, propagateErrors bool, logger *zap.Logger, stats statistics.EngineStatistics, subscriptions *sync.Map, telemetry subscriptionTelemetryContext) *websocketResponseWriter { @@ -656,6 +656,7 @@ func newWebsocketResponseWriter(id string, protocol wsproto.Proto, propagateErro propagateErrors: propagateErrors, subscriptions: subscriptions, telemetry: telemetry, + delivery: newSubscriptionDeliveryTracker(stats, logger, id), } } @@ -742,6 +743,7 @@ func (rw *websocketResponseWriter) Flush() error { }) if err != nil { err = wrapSubscriptionWriteError("serialize", err) + rw.delivery.observe(rw.telemetry, payload, 0, err) rw.logger.Warn("Serializing response headers", zap.Error(err)) return err } @@ -757,7 +759,9 @@ func (rw *websocketResponseWriter) Flush() error { } } + started := time.Now() err = wrapSubscriptionWriteError("write", rw.protocol.WriteGraphQLData(rw.id, payload, extensions)) + rw.delivery.observe(rw.telemetry, payload, time.Since(started), err) rw.buf.Reset() if err != nil { return err @@ -766,10 +770,6 @@ func (rw *websocketResponseWriter) Flush() error { return nil } -func (rw *websocketResponseWriter) ReportSubscriptionDelivery(report resolve.SubscriptionDeliveryReport) { - observeSubscriptionDelivery(rw.stats, rw.logger, rw.telemetry, report) -} - func (rw *websocketResponseWriter) SubscriptionResponseWriter() resolve.SubscriptionResponseWriter { return rw } @@ -1469,12 +1469,14 @@ func websocketDisconnectReason(err error, closeKind wsproto.CloseKind) (initiato var syntaxErr *json.SyntaxError var typeErr *json.UnmarshalTypeError switch { - case errors.Is(err, errClientTerminatedConnection), errors.Is(err, io.EOF), errors.Is(err, net.ErrClosed): + case errors.Is(err, errClientTerminatedConnection), errors.Is(err, io.EOF): return "client", "client_closed" + case errors.Is(err, net.ErrClosed): + return "router", "connection_closed" case errors.As(err, &closedErr): return "client", "client_closed" case errors.As(err, &netErr) && netErr.Timeout(): - return "network", "read_timeout" + return "network", "timeout" case errors.As(err, &syntaxErr), errors.As(err, &typeErr): return "client", "protocol_error" case errors.As(err, &closeErr): diff --git a/router/go.mod b/router/go.mod index 230afe594a..16d12d9a44 100644 --- a/router/go.mod +++ b/router/go.mod @@ -180,6 +180,4 @@ require ( // Remember you can use Go workspaces to avoid using replace directives in multiple go.mod files // Use what is best for your personal workflow. See CONTRIBUTING.md for more information -// Temporary preview dependency for https://github.com/wundergraph/graphql-go-tools/pull/1640. -// Remove this replacement after the delivery reporting API is released upstream. -replace github.com/wundergraph/graphql-go-tools/v2 => github.com/mwisner/graphql-go-tools/v2 v2.16.0-subscription-delivery-diagnostics.1 +// replace github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 diff --git a/router/go.sum b/router/go.sum index 3be6644160..a3c79cf627 100644 --- a/router/go.sum +++ b/router/go.sum @@ -206,8 +206,6 @@ 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/nats.go v1.50.0 h1:5zAeQrTvyrKrWLJ0fu02W3br8ym57qf7csDzgLOpcds= github.com/nats-io/nats.go v1.50.0/go.mod h1:26HypzazeOkyO3/mqd1zZd53STJN0EjCYF9Uy2ZOBno= github.com/nats-io/nkeys v0.4.15 h1:JACV5jRVO9V856KOapQ7x+EY8Jo3qw1vJt/9Jpwzkk4= @@ -336,6 +334,8 @@ 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/yosida95/uritemplate/v3 v3.0.2 h1:Ed3Oyj9yrmi9087+NczuL5BwkIc4wvTb5zIM+UJPGz4= github.com/yosida95/uritemplate/v3 v3.0.2/go.mod h1:ILOh0sOhIJR3+L/8afwt/kE++YT040gmv5BQTMR2HP4= github.com/yuin/gopher-lua v1.1.1 h1:kYKnWBjvbNP4XLT3+bPEwAXJx262OhaHDWDVOPjL46M= diff --git a/router/pkg/metric/engine_metrics.go b/router/pkg/metric/engine_metrics.go index 63938f7c6b..26eecd89c9 100644 --- a/router/pkg/metric/engine_metrics.go +++ b/router/pkg/metric/engine_metrics.go @@ -60,7 +60,13 @@ func (i *engineInstruments) toList() []otelmetric.Observable { result = append(result, i.messagesSent) } if i.deliveryAttempts != nil { - result = append(result, i.deliveryAttempts, i.deliveryFailures, i.disconnects) + result = append(result, i.deliveryAttempts) + } + if i.deliveryFailures != nil { + result = append(result, i.deliveryFailures) + } + if i.disconnects != nil { + result = append(result, i.disconnects) } if i.resolversMaxConcurrent != nil { diff --git a/router/pkg/metric/engine_metrics_test.go b/router/pkg/metric/engine_metrics_test.go index 11efe9ff29..6647590946 100644 --- a/router/pkg/metric/engine_metrics_test.go +++ b/router/pkg/metric/engine_metrics_test.go @@ -5,6 +5,7 @@ import ( "testing" "github.com/stretchr/testify/require" + rotel "github.com/wundergraph/cosmo/router/pkg/otel" "github.com/wundergraph/cosmo/router/pkg/statistics" sdkmetric "go.opentelemetry.io/otel/sdk/metric" "go.opentelemetry.io/otel/sdk/metric/metricdata" @@ -40,13 +41,37 @@ func TestEngineMetricsExportsSubscriptionDeliveryAndDisconnectCounters(t *testin var resourceMetrics metricdata.ResourceMetrics require.NoError(t, reader.Collect(context.Background(), &resourceMetrics)) - names := make(map[string]bool) + type metricPoint struct { + value int64 + attributes map[string]string + } + points := make(map[string]metricPoint) for _, scope := range resourceMetrics.ScopeMetrics { for _, metric := range scope.Metrics { - names[metric.Name] = true + sum, ok := metric.Data.(metricdata.Sum[int64]) + if !ok || len(sum.DataPoints) == 0 { + continue + } + attrs := make(map[string]string) + for _, attr := range sum.DataPoints[0].Attributes.ToSlice() { + attrs[string(attr.Key)] = attr.Value.AsString() + } + points[metric.Name] = metricPoint{value: sum.DataPoints[0].Value, attributes: attrs} } } - require.True(t, names[subscriptionDeliveryAttemptsKey]) - require.True(t, names[subscriptionDeliveryFailuresKey]) - require.True(t, names[subscriptionDisconnectsKey]) + require.Equal(t, metricPoint{value: 1, attributes: map[string]string{ + string(rotel.WgSubscriptionTransport): "sse", + string(rotel.WgSubscriptionFrameType): "next", + }}, points[subscriptionDeliveryAttemptsKey]) + require.Equal(t, metricPoint{value: 1, attributes: map[string]string{ + string(rotel.WgSubscriptionTransport): "sse", + string(rotel.WgSubscriptionFrameType): "next", + string(rotel.WgSubscriptionFailureStage): "flush", + string(rotel.WgSubscriptionFailureReason): "timeout", + }}, points[subscriptionDeliveryFailuresKey]) + require.Equal(t, metricPoint{value: 1, attributes: map[string]string{ + string(rotel.WgSubscriptionTransport): "sse", + string(rotel.WgSubscriptionDisconnectInitiator): "router", + string(rotel.WgSubscriptionDisconnectReason): "write_timeout", + }}, points[subscriptionDisconnectsKey]) } diff --git a/router/pkg/pubsub/datasource/provider.go b/router/pkg/pubsub/datasource/provider.go index 9879864971..c1e9fea184 100644 --- a/router/pkg/pubsub/datasource/provider.go +++ b/router/pkg/pubsub/datasource/provider.go @@ -5,7 +5,6 @@ import ( "iter" "slices" - "github.com/google/uuid" "github.com/wundergraph/cosmo/router/pkg/metric" ) @@ -91,23 +90,6 @@ type StreamEvent interface { Clone() MutableStreamEvent } -// StreamEventMetadataProvider is an optional extension for preserving a -// source event's identity through subscription fan-out and hooks. -type StreamEventMetadataProvider interface { - StreamEventMetadata() EventMetadata -} - -type EventMetadata struct { - ID string - SourceType string - SourceName string - SourceID string -} - -func NewEventID() string { - return uuid.NewString() -} - // A MutableStreamEvent is a stream event that can be modified. type MutableStreamEvent interface { StreamEvent diff --git a/router/pkg/pubsub/datasource/subscription_event_observability_test.go b/router/pkg/pubsub/datasource/subscription_event_observability_test.go deleted file mode 100644 index a7a4b32b04..0000000000 --- a/router/pkg/pubsub/datasource/subscription_event_observability_test.go +++ /dev/null @@ -1,61 +0,0 @@ -package datasource - -import ( - "context" - "testing" - - "github.com/stretchr/testify/require" - "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" - "go.uber.org/zap" -) - -type metadataTestEvent struct { - data []byte - metadata EventMetadata -} - -func (e *metadataTestEvent) GetData() []byte { return e.data } -func (e *metadataTestEvent) Clone() MutableStreamEvent { return nil } -func (e *metadataTestEvent) StreamEventMetadata() EventMetadata { return e.metadata } - -type enrichedUpdaterRecorder struct { - events []resolve.SubscriptionEvent -} - -func (u *enrichedUpdaterRecorder) Update([]byte) {} -func (u *enrichedUpdaterRecorder) UpdateSubscription(resolve.SubscriptionIdentifier, []byte) {} -func (u *enrichedUpdaterRecorder) UpdateEvent(event resolve.SubscriptionEvent) { - u.events = append(u.events, event) -} -func (u *enrichedUpdaterRecorder) UpdateSubscriptionEvent(resolve.SubscriptionIdentifier, resolve.SubscriptionEvent) { -} -func (u *enrichedUpdaterRecorder) Complete() {} -func (u *enrichedUpdaterRecorder) Error([]byte) {} -func (u *enrichedUpdaterRecorder) Done() {} -func (u *enrichedUpdaterRecorder) CloseSubscription(resolve.SubscriptionIdentifier) {} -func (u *enrichedUpdaterRecorder) Subscriptions() map[context.Context]resolve.SubscriptionIdentifier { - return nil -} - -func TestSubscriptionEventUpdaterPreservesSourceMetadata(t *testing.T) { - recorder := &enrichedUpdaterRecorder{} - updater := NewSubscriptionEventUpdater(nil, Hooks{}, recorder, zap.NewNop(), nil) - - updater.Update([]StreamEvent{&metadataTestEvent{ - data: []byte(`{"id":1}`), - metadata: EventMetadata{ - ID: "orders/2/19", - SourceType: "kafka", - SourceName: "orders", - SourceID: "orders/2/19", - }, - }}) - - require.Equal(t, []resolve.SubscriptionEvent{{ - Data: []byte(`{"id":1}`), - ID: "orders/2/19", - SourceType: "kafka", - SourceName: "orders", - SourceID: "orders/2/19", - }}, recorder.events) -} diff --git a/router/pkg/pubsub/datasource/subscription_event_updater.go b/router/pkg/pubsub/datasource/subscription_event_updater.go index 9378451d98..77d01c407a 100644 --- a/router/pkg/pubsub/datasource/subscription_event_updater.go +++ b/router/pkg/pubsub/datasource/subscription_event_updater.go @@ -45,7 +45,7 @@ func (s *subscriptionEventUpdater) Update(events []StreamEvent) { if event == nil { continue } - s.updateEvent(event) + s.eventUpdater.Update(event.GetData()) } return } @@ -187,7 +187,7 @@ func (s *subscriptionEventUpdater) updateSubscription(subscriptionCtx context.Co if event == nil { continue } - s.updateSubscriptionEvent(subID, event) + s.eventUpdater.UpdateSubscription(subID, event.GetData()) } // In case there was an error we close the affected subscription. @@ -196,38 +196,6 @@ func (s *subscriptionEventUpdater) updateSubscription(subscriptionCtx context.Co } } -func (s *subscriptionEventUpdater) updateEvent(event StreamEvent) { - enriched, ok := s.eventUpdater.(resolve.SubscriptionEventUpdater) - if !ok { - s.eventUpdater.Update(event.GetData()) - return - } - enriched.UpdateEvent(resolveSubscriptionEvent(event)) -} - -func (s *subscriptionEventUpdater) updateSubscriptionEvent(id resolve.SubscriptionIdentifier, event StreamEvent) { - enriched, ok := s.eventUpdater.(resolve.SubscriptionEventUpdater) - if !ok { - s.eventUpdater.UpdateSubscription(id, event.GetData()) - return - } - enriched.UpdateSubscriptionEvent(id, resolveSubscriptionEvent(event)) -} - -func resolveSubscriptionEvent(event StreamEvent) resolve.SubscriptionEvent { - result := resolve.SubscriptionEvent{Data: event.GetData()} - metadataProvider, ok := event.(StreamEventMetadataProvider) - if !ok { - return result - } - metadata := metadataProvider.StreamEventMetadata() - result.ID = metadata.ID - result.SourceType = metadata.SourceType - result.SourceName = metadata.SourceName - result.SourceID = metadata.SourceID - return result -} - func (s *subscriptionEventUpdater) recoverPanic(subID resolve.SubscriptionIdentifier, err any) { s.logger. WithOptions(zap.AddStacktrace(zapcore.ErrorLevel)). diff --git a/router/pkg/pubsub/kafka/adapter.go b/router/pkg/pubsub/kafka/adapter.go index 7e95fc13a8..3ee51437f4 100644 --- a/router/pkg/pubsub/kafka/adapter.go +++ b/router/pkg/pubsub/kafka/adapter.go @@ -109,15 +109,8 @@ func (p *ProviderAdapter) topicPoller(ctx context.Context, client *kgo.Client, u DestinationName: r.Topic, }) - eventID := fmt.Sprintf("%s/%d/%d", r.Topic, r.Partition, r.Offset) updater.Update([]datasource.StreamEvent{ &Event{ - metadata: datasource.EventMetadata{ - ID: eventID, - SourceType: "kafka", - SourceName: r.Topic, - SourceID: eventID, - }, evt: &MutableEvent{ Data: r.Value, Headers: headers, diff --git a/router/pkg/pubsub/kafka/engine_datasource.go b/router/pkg/pubsub/kafka/engine_datasource.go index 5184358f68..6606b49015 100644 --- a/router/pkg/pubsub/kafka/engine_datasource.go +++ b/router/pkg/pubsub/kafka/engine_datasource.go @@ -16,15 +16,7 @@ import ( // Event implements datasource.StreamEvent type Event struct { - evt *MutableEvent - metadata datasource.EventMetadata -} - -func (e *Event) StreamEventMetadata() datasource.EventMetadata { - if e.metadata.ID == "" && e.evt != nil { - return e.evt.metadata - } - return e.metadata + evt *MutableEvent } func (e *Event) GetData() []byte { @@ -49,11 +41,7 @@ func (e *Event) GetHeaders() map[string][]byte { } func (e Event) Clone() datasource.MutableStreamEvent { - clone, _ := e.evt.Clone().(*MutableEvent) - if clone != nil { - clone.metadata = e.metadata - } - return clone + return e.evt.Clone() } func cloneHeaders(src map[string][]byte) map[string][]byte { @@ -69,14 +57,11 @@ func cloneHeaders(src map[string][]byte) map[string][]byte { // MutableEvent implements datasource.MutableEvent type MutableEvent struct { - Key []byte `json:"key"` - Data json.RawMessage `json:"data"` - Headers map[string][]byte `json:"headers"` - metadata datasource.EventMetadata + Key []byte `json:"key"` + Data json.RawMessage `json:"data"` + Headers map[string][]byte `json:"headers"` } -func (e *MutableEvent) StreamEventMetadata() datasource.EventMetadata { return e.metadata } - func (e *MutableEvent) GetData() []byte { return e.Data } @@ -255,7 +240,7 @@ func (s *PublishDataSource) Load(ctx context.Context, headers http.Header, input return nil, err } - if err := s.pubSub.Publish(ctx, publishData.PublishEventConfiguration(), []datasource.StreamEvent{&Event{evt: &publishData.Event}}); err != nil { + if err := s.pubSub.Publish(ctx, publishData.PublishEventConfiguration(), []datasource.StreamEvent{&Event{&publishData.Event}}); err != nil { // err will not be returned but only logged inside PubSubProvider.Publish to avoid a "unable to fetch from subgraph" error return []byte(`{"__typename": "edfs__PublishResult", "success": false}`), nil } diff --git a/router/pkg/pubsub/nats/adapter.go b/router/pkg/pubsub/nats/adapter.go index 752825445d..a8ba5c3c7e 100644 --- a/router/pkg/pubsub/nats/adapter.go +++ b/router/pkg/pubsub/nats/adapter.go @@ -158,22 +158,8 @@ func (p *ProviderAdapter) Subscribe(ctx context.Context, cfg datasource.Subscrip DestinationName: msg.Subject(), }) - metadata, metadataErr := msg.Metadata() - eventID := datasource.NewEventID() - if metadataErr == nil { - streamName := metadata.Stream - if streamName == "" { - streamName = subConf.StreamConfiguration.StreamName - } - eventID = fmt.Sprintf("%s/%d", streamName, metadata.Sequence.Stream) - } updater.Update([]datasource.StreamEvent{ - &Event{metadata: datasource.EventMetadata{ - ID: eventID, - SourceType: "nats", - SourceName: msg.Subject(), - SourceID: eventID, - }, evt: &MutableEvent{ + &Event{evt: &MutableEvent{ Data: msg.Data(), Headers: map[string][]string(msg.Headers()), }}, @@ -222,14 +208,8 @@ func (p *ProviderAdapter) Subscribe(ctx context.Context, cfg datasource.Subscrip ProviderType: metric.ProviderTypeNats, DestinationName: msg.Subject, }) - eventID := datasource.NewEventID() updater.Update([]datasource.StreamEvent{ - &Event{metadata: datasource.EventMetadata{ - ID: eventID, - SourceType: "nats", - SourceName: msg.Subject, - SourceID: eventID, - }, evt: &MutableEvent{ + &Event{evt: &MutableEvent{ Data: msg.Data, Headers: map[string][]string(msg.Header), }}, diff --git a/router/pkg/pubsub/nats/adapter_consume_test.go b/router/pkg/pubsub/nats/adapter_consume_test.go index 0089e944fc..c775c6a70a 100644 --- a/router/pkg/pubsub/nats/adapter_consume_test.go +++ b/router/pkg/pubsub/nats/adapter_consume_test.go @@ -36,9 +36,6 @@ func TestProviderAdapterStreamSubscribe(t *testing.T) { msg.EXPECT().Subject().Return("employeeUpdated.12") msg.EXPECT().Data().Return([]byte(`{"id":13}`)) msg.EXPECT().Headers().Return(nil) - msg.EXPECT().Metadata().Return(&jetstream.MsgMetadata{ - Sequence: jetstream.SequencePair{Stream: 42}, - }, nil) msg.EXPECT().Ack().RunAndReturn(func() error { cancel(); return nil }).Once() batch := NewMockMessageBatch(t) diff --git a/router/pkg/pubsub/nats/engine_datasource.go b/router/pkg/pubsub/nats/engine_datasource.go index b6cfece3e3..6739c418ba 100644 --- a/router/pkg/pubsub/nats/engine_datasource.go +++ b/router/pkg/pubsub/nats/engine_datasource.go @@ -15,15 +15,7 @@ import ( ) type Event struct { - evt *MutableEvent - metadata datasource.EventMetadata -} - -func (e *Event) StreamEventMetadata() datasource.EventMetadata { - if e.metadata.ID == "" && e.evt != nil { - return e.evt.metadata - } - return e.metadata + evt *MutableEvent } func (e *Event) GetData() []byte { @@ -41,21 +33,14 @@ func (e *Event) GetHeaders() map[string][]string { } func (e Event) Clone() datasource.MutableStreamEvent { - clone, _ := e.evt.Clone().(*MutableEvent) - if clone != nil { - clone.metadata = e.metadata - } - return clone + return e.evt.Clone() } type MutableEvent struct { - Data json.RawMessage `json:"data"` - Headers map[string][]string `json:"headers"` - metadata datasource.EventMetadata + Data json.RawMessage `json:"data"` + Headers map[string][]string `json:"headers"` } -func (e *MutableEvent) StreamEventMetadata() datasource.EventMetadata { return e.metadata } - func (e *MutableEvent) GetData() []byte { if e == nil { return nil @@ -75,14 +60,13 @@ func (e *MutableEvent) Clone() datasource.MutableStreamEvent { return nil } return &MutableEvent{ - Data: slices.Clone(e.Data), - Headers: cloneHeaders(e.Headers), - metadata: e.metadata, + Data: slices.Clone(e.Data), + Headers: cloneHeaders(e.Headers), } } func (e *MutableEvent) ToStreamEvent() datasource.StreamEvent { - return &Event{evt: e, metadata: e.metadata} + return &Event{evt: e} } func cloneHeaders(src map[string][]string) map[string][]string { diff --git a/router/pkg/pubsub/redis/adapter.go b/router/pkg/pubsub/redis/adapter.go index 6ebb2cc5b1..606a473e96 100644 --- a/router/pkg/pubsub/redis/adapter.go +++ b/router/pkg/pubsub/redis/adapter.go @@ -161,14 +161,8 @@ func (p *ProviderAdapter) Subscribe(ctx context.Context, conf datasource.Subscri ProviderType: metric.ProviderTypeRedis, DestinationName: msg.Channel, }) - eventID := datasource.NewEventID() updater.Update([]datasource.StreamEvent{ - &Event{metadata: datasource.EventMetadata{ - ID: eventID, - SourceType: "redis", - SourceName: msg.Channel, - SourceID: eventID, - }, evt: &MutableEvent{ + &Event{evt: &MutableEvent{ Data: []byte(msg.Payload), }}, }) diff --git a/router/pkg/pubsub/redis/engine_datasource.go b/router/pkg/pubsub/redis/engine_datasource.go index e6c621b577..55eee83e20 100644 --- a/router/pkg/pubsub/redis/engine_datasource.go +++ b/router/pkg/pubsub/redis/engine_datasource.go @@ -15,15 +15,7 @@ import ( ) type Event struct { - evt *MutableEvent - metadata datasource.EventMetadata -} - -func (e *Event) StreamEventMetadata() datasource.EventMetadata { - if e.metadata.ID == "" && e.evt != nil { - return e.evt.metadata - } - return e.metadata + evt *MutableEvent } func (e *Event) GetData() []byte { @@ -34,20 +26,13 @@ func (e *Event) GetData() []byte { } func (e *Event) Clone() datasource.MutableStreamEvent { - clone, _ := e.evt.Clone().(*MutableEvent) - if clone != nil { - clone.metadata = e.metadata - } - return clone + return e.evt.Clone() } type MutableEvent struct { - Data json.RawMessage `json:"data"` - metadata datasource.EventMetadata + Data json.RawMessage `json:"data"` } -func (e *MutableEvent) StreamEventMetadata() datasource.EventMetadata { return e.metadata } - func (e *MutableEvent) GetData() []byte { if e == nil { return nil @@ -68,8 +53,7 @@ func (e *MutableEvent) Clone() datasource.MutableStreamEvent { } return &MutableEvent{ - Data: slices.Clone(e.Data), - metadata: e.metadata, + Data: slices.Clone(e.Data), } }