pusher failed to consume trace data due to "context canceled"

[dastrobu]

Is your feature request related to a problem? Please describe.

We encountered the log message msg="pusher failed to consume trace data" err="context canceled" and had significant difficulty identifying the cause. The root cause was not related to the reasons documented in the troubleshooting guide.

The metric tempo_discarded_spans_total indicated that spans were being discarded, but the logs did not clarify the reason.

We ended up patching Grafana Tempo and even the Go SDK to gather more information about the discarded spans. I would like to propose improvements to observability in this area.

Here is what we did:

1. Additional Logging in Distributor

   We added extra logging to distributor.go to identify which spans were causing issues:

   if err != nil {
      logSpans(batches, &LogReceivedSpansConfig{ // TODO should be LogDiscardedSpansConfig
          Enabled:              true,
          IncludeAllAttributes: true,
          FilterByStatusError:  false,
      }, d.logger)
      return nil, err
   }

   I propose adding a LogDiscardedSpansConfig in addition to LogReceivedSpansConfig to log discarded spans that are causing issues. I can open a PR for this if you think it is a good idea.

2. Context Cancellation Debugging

   It was extremely challenging to determine why the Context was canceled. This is a weak spot in Go, in my opinion. We had to patch the Go SDK to get more information about context cancellation.

   We added stack traces to context.go:

   func (c *cancelCtx) cancel(removeFromParent bool, err, cause error) {
   if err == nil {
       panic("context: internal error: missing cancel error")
   }
   if err == Canceled {
       stack := debug.Stack()
       s := string(stack)
       err = fmt.Errorf("%w stack: %v", err, s)
   }

   This led to the following logs:

   level=error ts=2024-06-20T06:05:40.085835663Z caller=rate_limited_logger.go:27 msg="pusher failed to consume trace data" err="context canceled stack:
   goroutine 869 [running]:
   runtime/debug.Stack()
      /opt/hostedtoolcache/go/1.22.2/x64/src/runtime/debug/stack.go:24 +0x6b
   context.(*cancelCtx).cancel(0xc047f05a90, 0x1, {0x42ee3a0, 0xc000130c20}, {0x0, 0x0})
      /opt/hostedtoolcache/go/1.22.2/x64/src/context/context.go:546 +0x8a
   context.WithCancel.func1()
      /opt/hostedtoolcache/go/1.22.2/x64/src/context/context.go:240 +0x34
   google.golang.org/grpc/internal/transport.(*http2Server).closeStream(0xc0438ad380, 0xc047e65b00, 0x0, 0x0, 0x0)
      /home/runner/actions-runner/_work/grafana-tempo/grafana-tempo/vendor/google.golang.org/grpc/internal/transport/http2_server.go:1313 +0x39
   google.golang.org/grpc/internal/transport.(*http2Server).handleRSTStream(0xc0438ad380, 0xc047da5d60)
      /home/runner/actions-runner/_work/grafana-tempo/grafana-tempo/vendor/google.golang.org/grpc/internal/transport/http2_server.go:833 +0x94
   google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams(0xc0438ad380, {0x43139d0, 0xc04410f830}, 0xc04410f8c0)
      /home/runner/actions-runner/_work/grafana-tempo/grafana-tempo/vendor/google.golang.org/grpc/internal/transport/http2_server.go:685 +0xaa9
   google.golang.org/grpc.(*Server).serveStreams(0xc000670a00, {0x43139d0, 0xc04410f830}, {0x432e560, 0xc0438ad380}, {0x432a618, 0xc0410f96d0})
      /home/runner/actions-runner/_work/grafana-tempo/grafana-tempo/vendor/google.golang.org/grpc/server.go:1013 +0x4f3
   google.golang.org/grpc.(*Server).handleRawConn.func1()
      /home/runner/actions-runner/_work/grafana-tempo/grafana-tempo/vendor/google.golang.org/grpc/server.go:949 +0x92
   created by google.golang.org/grpc.(*Server).handleRawConn in goroutine 866
      /home/runner/actions-runner/_work/grafana-tempo/grafana-tempo/vendor/google.golang.org/grpc/server.go:948 +0x389

   As you can see, the context was closed due to an RST frame sent by the client. See handleRSTStream and closeStream.

   Therefore, Grafana Tempo is behaving correctly, but it was extremely difficult to determine why the context was canceled.

3. Confusing Metric Labels

   The discarded spans are added to the tempo_discarded_spans_total metric with the reason reasonInternalError: distributor.go#L440, which was also confusing.

Describe the solution you'd like

I propose two improvements:

1. Add a LogDiscardedSpansConfig to the distributor to log discarded spans causing issues.

   distributor:
    config:
      log_discarded_spans:
        enabled: true
      log_received_spans:
        # ...

   This should be easily doable.

2. Add a new reason label to tempo_discarded_spans_total to indicate when the client's fault causes traces to be discarded. I am unsure how to implement this, though.

Describe alternatives you've considered

Switching to Jaeger 😉.

Additional context

Grafana was deployed using the tempo-distributed Helm chart.

[joe-elliott]

Thank you for the very detailed issue. Please don't switch to Jaeger ;).

I propose adding a LogDiscardedSpansConfig in addition to LogReceivedSpansConfig to log discarded spans that are causing issues. I can open a PR for this if you think it is a good idea.

100%. I think this is a great idea and would love a PR.

It was extremely challenging to determine why the Context was canceled. This is a weak spot in Go, in my opinion.

Yes. I have mostly recently felt this pain the frontend/read path.

Therefore, Grafana Tempo is behaving correctly, but it was extremely difficult to determine why the context was canceled.

Thank you for digging so deep. This is impressive research and a great contribution to the project.

Add a new reason label to tempo_discarded_spans_total to indicate when the client's fault causes traces to be discarded. I am unsure how to implement this, though.

I don't have a good answer for this either. Perhaps we can log the cancel cause (added in go 1.20): https://pkg.go.dev/context#WithCancelCause

I don't think much uses this yet but we could slowly add causes in our code. Also presumably go will also add causes to the framework. Perhaps this will grow in value over time?

[dastrobu]

@joe-elliott, thanks for your feedback.

100%. I think this is a great idea and would love a PR.

See #3964 – it took a few days to get it right (hopefully).

I don't have a good answer for this either. Perhaps we can log the cancel cause.

True, but for the particular case I encountered, we would need to convince the google.golang.org/grpc team to add this. Nevertheless, I'd second adding a cause to all Tempo internal context cancellations in some cases.

[dastrobu]

The grpc team is considering to add the cancel cause, see https://github.com/grpc/grpc-go/issues/7541#issuecomment-2301665760.

[dastrobu]

Found another issue, which would need to be fixed to get the cancel cause reported. batch.go would need bo the changed:

    case <-ctx.Done():
-       return ctx.Err()
+       return context.Cause(ctx)
    }

When I find time, I might open an issue/PR to https://github.com/grafana/dskit.

[dastrobu]

@joe-elliott I created https://github.com/grafana/dskit/issues/576 and https://github.com/grafana/dskit/pull/577 in dskit. But I am not sure if there is a process to encourage someone to look at it.