🐛 [Bug]: OTeL duplicate and wrong counter metrics are generated infinitely

[oliverdding]

Bug Description

I have raised a bug issue in opentelemetry-go SDK repository.

When using fiber to manually reporting request count with delta temporality, the server will keep reporting wrong attributes value and wrong datapoint size infinitely.

• demo code

While using go http library or something else, everything work as expected so I got the right request count.

How to Reproduce

See my demo repository:

https://github.com/oliverdding/otel-test

Start with:

docker compose up -d --build

Or you can run go cmd program manually with:

docker compose up -d otel-collector

Expected Behavior

There should be ten datapoints, with app_id from 1 to 10.

Fiber Version

v2.49.2

Code Snippet (optional)

package main

import (
	"context"
	"fmt"
	"math/rand"
	"net/http"
	"os"
	"time"

	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc"
	"go.opentelemetry.io/otel/metric"
	sdkmetric "go.opentelemetry.io/otel/sdk/metric"
	"go.opentelemetry.io/otel/sdk/metric/metricdata"
	"go.opentelemetry.io/otel/sdk/resource"
	semconv "go.opentelemetry.io/otel/semconv/v1.18.0"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

var (
	logger *zap.Logger
)

func init() {
	var cfg zap.Config
	cfg = zap.NewDevelopmentConfig()

	// set time format
	cfg.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.DateTime)
	// add color for console
	cfg.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
	logger = zap.New(zapcore.NewCore(zapcore.NewConsoleEncoder(cfg.EncoderConfig), zapcore.NewMultiWriteSyncer(zapcore.AddSync(os.Stdout)), zapcore.DebugLevel))
}

func preferDeltaTemporalitySelector(kind sdkmetric.InstrumentKind) metricdata.Temporality {
	switch kind {
	case sdkmetric.InstrumentKindCounter,
		sdkmetric.InstrumentKindObservableCounter,
		sdkmetric.InstrumentKindHistogram:
		return metricdata.DeltaTemporality
	default:
		return metricdata.CumulativeTemporality
	}
}

func initProvider(ctx context.Context) func() {
	res, err := resource.New(ctx,
		resource.WithFromEnv(),
		resource.WithProcess(),
		resource.WithTelemetrySDK(),
		resource.WithHost(),
		resource.WithAttributes(
			semconv.ServiceName("client"),
			semconv.ServiceNamespace("demo"),
			semconv.ServiceVersion("0.1.0"),
		),
	)
	if err != nil {
		logger.Fatal("failed to create resource", zap.Error(err))
	}

	otelAgentAddr, ok := os.LookupEnv("OTEL_EXPORTER_OTLP_ENDPOINT")
	if !ok {
		otelAgentAddr = "127.0.0.1:4317"
	}
	metricExp, err := otlpmetricgrpc.New(
		ctx,
		otlpmetricgrpc.WithInsecure(),
		otlpmetricgrpc.WithEndpoint(otelAgentAddr),
		otlpmetricgrpc.WithCompressor("gzip"),
		otlpmetricgrpc.WithTemporalitySelector(preferDeltaTemporalitySelector),
	)

	meterProvider := sdkmetric.NewMeterProvider(
		sdkmetric.WithResource(res),
		sdkmetric.WithReader(
			sdkmetric.NewPeriodicReader(
				metricExp,
				sdkmetric.WithInterval(2*time.Second),
			),
		),
	)
	otel.SetMeterProvider(meterProvider)

	return func() {
		cxt, cancel := context.WithTimeout(ctx, time.Second)
		defer cancel()
		// pushes any last exports to the receiver
		if err := meterProvider.Shutdown(cxt); err != nil {
			otel.Handle(err)
		}
	}
}

var (
	rng       = rand.New(rand.NewSource(time.Now().UnixNano()))
	meter     metric.Meter
	appIDList = []string{"1024", "568", "106", "1025", "197"}
)

func main() {
	ctx := context.Background()
	otelShutdownHook := initProvider(ctx)
	defer otelShutdownHook()

	meter = otel.Meter("demo-server")

	requestLatency, _ := meter.Float64Histogram(
		"demo_client/request_latency",
		metric.WithDescription("The latency of requests processed"),
	)

	requestCount, _ := meter.Int64Counter(
		"demo_client/request_counts",
		metric.WithDescription("The number of requests processed"),
	)

	for {
		appID := appIDList[rng.Intn(len(appIDList))]
		startTime := time.Now()
		makeHelloRequest(ctx, appID)
		latencyMs := float64(time.Since(startTime)) / 1e6
		requestLatency.Record(ctx, latencyMs, metric.WithAttributes(attribute.String("interface", "hello"), attribute.String("app_id", appID)))
		requestCount.Add(ctx, 1, metric.WithAttributes(attribute.String("interface", "hello"), attribute.String("app_id", appID)))

		fmt.Printf("Latency: %.3fms\n", latencyMs)
		time.Sleep(time.Duration(1) * time.Second)

	}
}

func makeHelloRequest(ctx context.Context, appID string) {
	demoServerAddr, ok := os.LookupEnv("DEMO_SERVER_ENDPOINT")
	if !ok {
		demoServerAddr = "0.0.0.0:2333"
	}

	// Trace an HTTP client by wrapping the transport
	client := http.Client{
		Transport: otelhttp.NewTransport(http.DefaultTransport),
	}

	// Make sure we pass the context to the request to avoid broken traces.
	req, err := http.NewRequestWithContext(ctx, "GET", fmt.Sprintf("http://%s/hello/%s", demoServerAddr, appID), nil)
	if err != nil {
		logger.Fatal("failed to create request", zap.Error(err))
	}

	// All requests made with this client will create spans.
	res, err := client.Do(req)
	if err != nil {
		logger.Fatal("failed to execute request", zap.Error(err))
	}
	res.Body.Close()
}

Checklist:

• I agree to follow Fiber's Code of Conduct.
• I have checked for existing issues that describe my problem prior to opening this one.
• I understand that improperly formatted bug reports may be closed without explanation.

[welcome]

Thanks for opening your first issue here! 🎉 Be sure to follow the issue template! If you need help or want to chat with us, join us on Discord https://gofiber.io/discord

[efectn]

I think this issue can be moved to contrib repo.

[oliverdding]

@efectn I have reported an related issue there: open-telemetry/opentelemetry-go#4563

[pellared]

This is incorrect usage of Fiber.

See https://pkg.go.dev/github.com/gofiber/fiber/v2#Ctx.Params

Returned value is only valid within the handler. Do not store any references. Make copies or use the Immutable setting to use the value outside the Handler.

[ReneWerner87]

This is incorrect usage of Fiber.

See https://pkg.go.dev/github.com/gofiber/fiber/v2#Ctx.Params

Returned value is only valid within the handler. Do not store any references. Make copies or use the Immutable setting to use the value outside the Handler.

Can you share the line you are referring to?

[pellared]

Sorry I accidently send a comment when I was answering here open-telemetry/opentelemetry-go#4563 😉

Can you share the line you are referring to?

The issue is here: https://github.com/oliverdding/otel-test/blob/1bb67cf571d89d836d20b44f6278ae166a008d6b/cmd/server/main.go#L132-L136

You should make a copy of appID in the handler as the metrics are exported asynchronously.

appID = strings.Clone(appID)
requestCount.Add(c.UserContext(), 1, metric.WithAttributes(attribute.String("app_id", appID)))

[oliverdding]

Oh😢, it's my fault...

Thanks for pointing out @pellared