修复 Hertz + OpenTelemetry 链路追踪中的数据竞争问题

0 阅读3分钟

修复 Hertz + OpenTelemetry 链路追踪中的数据竞争问题

问题背景

在使用 CloudWeGo Hertz 框架配合 hertz-contrib/obs-opentelemetry 进行链路追踪时,当使用 WithShouldIgnore 选项时,会触发数据竞争警告:

HERTZ: Race detected.
Please be aware that the protocol.Request passed to handler is only valid before the handler returns.
DO NOT attempt to keep and access protocol.Request after the handler returns.

使用 Go 的 -race 检测器运行时,还会发现 DATA RACE 错误。

问题复现

复现代码

创建 main.go

package main

import (
    "context"
    "strings"

    "github.com/cloudwego/hertz/pkg/app"
    "github.com/cloudwego/hertz/pkg/app/server"
    "github.com/hertz-contrib/obs-opentelemetry/provider"
    hertztracing "github.com/hertz-contrib/obs-opentelemetry/tracing"
)

func main() {
    p := provider.NewOpenTelemetryProvider(
        provider.WithServiceName("test-service"),
        provider.WithExportEndpoint("localhost:4317"),
        provider.WithInsecure(),
    )
    defer p.Shutdown(context.Background())

    // 使用 WithShouldIgnore 过滤健康检查等路径
    tracer, cfg := hertztracing.NewServerTracer(
        hertztracing.WithShouldIgnore(func(ctx context.Context, c *app.RequestContext) bool {
            return strings.HasPrefix(string(c.Path()), "/health")
        }),
    )

    h := server.Default(tracer, server.WithHostPorts("127.0.0.1:8080"))
    h.Use(hertztracing.ServerMiddleware(cfg))

    h.GET("/health", func(ctx context.Context, c *app.RequestContext) {
        c.String(200, "ok")
    })

    h.GET("/api/test", func(ctx context.Context, c *app.RequestContext) {
        c.String(200, "test")
    })

    h.Spin()
}

复现步骤

# 1. 使用 -race 标志运行
go run -race main.go

# 2. 发送请求
curl http://127.0.0.1:8080/health
curl http://127.0.0.1:8080/api/test

# 3. 观察控制台输出,会看到竞态警告

根因分析

经过调试,发现两个独立的问题:

问题 1: serverTracer.Start() 中的 shouldIgnore 调用

// tracing/tracer_server.go - 原代码
func (s *serverTracer) Start(ctx context.Context, c *app.RequestContext) context.Context {
    if s.config.shouldIgnore(ctx, c) {  // <- 问题在这里
        return ctx
    }
    // ...
}

原因serverTracer.Start() 通过 server.WithTracer() 注册,它在请求解析之前就被调用。

此时:

  • 请求头和 body 可能还未完全解析
  • shouldIgnore 函数访问 c.Path() 等字段可能触发数据竞争

重要发现ServerMiddleware 中已经有相同的 shouldIgnore 检查,所以 Start() 中的检查是冗余的。

问题 2: span.End() 后访问 span 属性

// tracing/tracer_server.go - 原代码
span.End(oteltrace.WithTimestamp(getEndTimeOrNow(ti)))

metricsAttributes := extractMetricsAttributesFromSpan(span)  // <- 数据竞争风险

原因span.End() 调用后,OpenTelemetry exporter 可能在另一个 goroutine 中开始处理这个 span。此时再访问 span 的属性会导致数据竞争。

修复方案

修复 1: 删除 Start() 中的 shouldIgnore 检查

func (s *serverTracer) Start(ctx context.Context, c *app.RequestContext) context.Context {
    // NOTE: Do not call shouldIgnore here. At this point the request may not be
    // fully parsed yet, accessing RequestContext fields can cause data races.
    // The shouldIgnore check is performed in ServerMiddleware instead.
    tc := &internal.TraceCarrier{}
    tc.SetTracer(s.config.tracer)
    return internal.WithTraceCarrier(ctx, tc)
}

修复 2: 在 span.End() 之前提取 metrics 属性

func (s *serverTracer) Finish(ctx context.Context, c *app.RequestContext) {
    // ... 省略前面的代码 ...

    // Extract metrics attributes before span.End() to avoid data race
    // with the exporter which may process the span in another goroutine.
    metricsAttributes := extractMetricsAttributesFromSpan(span)

    span.End(oteltrace.WithTimestamp(getEndTimeOrNow(ti)))

    s.counters[ServerRequestCount].Add(ctx, 1, metric.WithAttributes(metricsAttributes...))
    s.histogramRecorder[ServerLatency].Record(ctx, elapsedTime, metric.WithAttributes(metricsAttributes...))
}

完整 diff

diff --git a/tracing/tracer_server.go b/tracing/tracer_server.go
--- a/tracing/tracer_server.go
+++ b/tracing/tracer_server.go
@@ -76,9 +76,10 @@ func (s *serverTracer) createMeasures() {
 }

 func (s *serverTracer) Start(ctx context.Context, c *app.RequestContext) context.Context {
-	if s.config.shouldIgnore(ctx, c) {
-		return ctx
-	}
+	// NOTE: Do not call shouldIgnore here. At this point the request may not be
+	// fully parsed yet, accessing RequestContext fields can cause data races.
+	// The shouldIgnore check is performed in ServerMiddleware instead.
 	tc := &internal.TraceCarrier{}
 	tc.SetTracer(s.config.tracer)

@@ -135,10 +136,13 @@ func (s *serverTracer) Finish(ctx context.Context, c *app.RequestContext) {
 		recordErrorSpanWithStack(span, httpErr, panicMsg, panicStack)
 	}

+	// Extract metrics attributes before span.End() to avoid data race
+	// with the exporter which may process the span in another goroutine.
+	metricsAttributes := extractMetricsAttributesFromSpan(span)
+
 	span.End(oteltrace.WithTimestamp(getEndTimeOrNow(ti)))

-	metricsAttributes := extractMetricsAttributesFromSpan(span)
 	s.counters[ServerRequestCount].Add(ctx, 1, metric.WithAttributes(metricsAttributes...))
 	s.histogramRecorder[ServerLatency].Record(ctx, elapsedTime, metric.WithAttributes(metricsAttributes...))
 }

验证方法

# 在 tracing 目录下运行测试
cd tracing
go test -race ./...

# 应该看到类似输出:
# ok  	github.com/hertz-contrib/obs-opentelemetry/tracing	1.778s

修复后的执行流程

请求到达
    ↓
serverTracer.Start()        ← 仅创建 TraceCarrier,不访问请求数据
    ↓
请求解析完成
    ↓
ServerMiddleware            ← shouldIgnore 检查在这里进行
    ↓
c.Next(ctx)                 ← handler 执行
    ↓
handler 返回
    ↓
serverTracer.Finish()
    ↓
extractMetricsAttributes()  ← 在 span.End() 之前调用
    ↓
span.End()                  ← span 提交给 exporter

关键要点

  1. serverTracer.Start() 调用时机:在请求解析之前,此时访问 RequestContext 字段是不安全的
  2. shouldIgnore 检查位置:应该在 ServerMiddleware 中进行,而不是在 Start()
  3. span.End() 后的数据竞争:不要在 span.End() 之后访问 span 的任何属性

参考资料

相关链接