duplicate and wrong counter metrics are generated infinitely #4563
Comments
Closed
3 tasks
|
@oliverdding I made a shortcut in your repro steps FiberI simplified the code and replaced the usage of package main
import (
"context"
"time"
"github.com/gofiber/fiber/v2"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/exporters/stdout/stdoutmetric"
"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"
)
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)
if err != nil {
panic(err)
}
metricExp, err := stdoutmetric.New(
stdoutmetric.WithTemporalitySelector(preferDeltaTemporalitySelector),
)
if err != nil {
panic(err)
}
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 (
meter metric.Meter
requestCount metric.Int64Counter
)
func main() {
ctx := context.Background()
otelShutdownHook := initProvider(ctx)
defer otelShutdownHook()
meter = otel.Meter("demo-server")
app := fiber.New(fiber.Config{
AppName: "demo-server",
CaseSensitive: true,
DisableKeepalive: true,
EnablePrintRoutes: true,
})
requestCount, _ = meter.Int64Counter(
"demo_server/request_counts",
metric.WithDescription("The number of requests received"),
)
app.Get("/hello/:app_id", helloHandler)
app.Listen("0.0.0.0:2333")
}
func helloHandler(c *fiber.Ctx) error {
appID := c.Params("app_id")
requestCount.Add(c.UserContext(), 1, metric.WithAttributes(attribute.String("interface", "hello"), attribute.String("app_id", appID)))
return nil
}Then I executed for i in {1..10}; do curl 127.0.0.1:2333/hello?id=${i}; doneI got the similar (incorrect) result (just the output is formatted differently): net/httpI decided to simplify and rewrite package main
import (
"context"
"io"
"log"
"net/http"
"time"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/exporters/stdout/stdoutmetric"
"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"
)
func initProvider(ctx context.Context) func() {
res, err := resource.New(ctx)
if err != nil {
panic(err)
}
metricExp, err := stdoutmetric.New(stdoutmetric.WithTemporalitySelector(preferDeltaTemporalitySelector))
if err != nil {
panic(err)
}
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 (
meter metric.Meter
requestCount metric.Int64Counter
)
func preferDeltaTemporalitySelector(kind sdkmetric.InstrumentKind) metricdata.Temporality {
switch kind {
case sdkmetric.InstrumentKindCounter,
sdkmetric.InstrumentKindObservableCounter,
sdkmetric.InstrumentKindHistogram:
return metricdata.DeltaTemporality
default:
return metricdata.CumulativeTemporality
}
}
func main() {
ctx := context.Background()
otelShutdownHook := initProvider(ctx)
defer otelShutdownHook()
meter = otel.Meter("demo-server")
requestCount, _ = meter.Int64Counter(
"demo_server/request_counts",
metric.WithDescription("The number of requests received"),
)
http.HandleFunc("/hello", hello)
log.Fatal(http.ListenAndServe(":2333", nil))
}
func hello(w http.ResponseWriter, r *http.Request) {
appID := r.URL.Query().Get("id")
requestCount.Add(r.Context(), 1, metric.WithAttributes(attribute.String("interface", "hello"), attribute.String("app_id", appID)))
if _, err := io.WriteString(w, appID+"\n"); err != nil {
log.Printf("Write failed: %v\n", err)
}
}Then I executed for i in {1..10}; do curl 127.0.0.1:2333/hello?id=${i}; doneAnd I got the following output which IMO is correct: {
"Resource": null,
"ScopeMetrics": []
}
{
"Resource": null,
"ScopeMetrics": [
{
"Scope": {
"Name": "demo-server",
"Version": "",
"SchemaURL": ""
},
"Metrics": [
{
"Name": "demo_server/request_counts",
"Description": "The number of requests received",
"Unit": "",
"Data": {
"DataPoints": [
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "5"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "6"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "8"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "10"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "1"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "2"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "4"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "3"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "7"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
},
{
"Attributes": [
{
"Key": "app_id",
"Value": {
"Type": "STRING",
"Value": "9"
}
},
{
"Key": "interface",
"Value": {
"Type": "STRING",
"Value": "hello"
}
}
],
"StartTime": "2023-09-28T19:59:11.6206094+02:00",
"Time": "2023-09-28T19:59:13.619949141+02:00",
"Value": 1
}
],
"Temporality": "DeltaTemporality",
"IsMonotonic": true
}
}
]
}
]
}
{
"Resource": null,
"ScopeMetrics": []
}Right now, I have no clue what is wrong, but maybe you will find something before I get time to look at it further. |
This did not reproduce the issue. All expected attributes (1 through 10) are present. |
|
Is this an issue with the collector? |
|
@oliverdding I found the root cause. From https://pkg.go.dev/github.com/gofiber/fiber/v2#Ctx.Params
You should make a copy of appID = strings.Clone(appID)
requestCount.Add(c.UserContext(), 1, metric.WithAttributes(attribute.String("interface", "hello"), attribute.String("app_id", appID)))Please close the issue if you agree that this a proper fix. |
MrAlias
added
invalid
|
That is the point! It's my misusing of fiber... Thanks for your patience @pellared , you are so kind! |
Thank you. I am happy that I was able to help you. I would also not expect such behavior from fiber. |
pellared
removed
the
response needed
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Description
I wrote a simple http server demo (with fiber) which would receive http request and reporting request count with delta counter to otel collector, where logging exporter would print all the request.
When sending http request one by one, everything worked as expected. But when calling
for i in {1..10}; do curl 127.0.0.1:2333/hello/${i}; done, I found that the attributes are wrong (should be ten datapoint with app_id from 1 to 10, but got 7 datapoint with all app_id = 9), and the go SDK kept reporting metrics infinitely.Logs example:
Environment
Steps To Reproduce
server.go
go.mod
Expected behavior
There should be ten datapoints, with app_id from 1 to 10.
The text was updated successfully, but these errors were encountered: