search

jaegertracing / jaeger

CNCF Jaeger, a Distributed Tracing Platform
https://www.jaegertracing.io/
Apache License 2.0
19.95k stars 2.37k forks source link

Prometheus 'Label value is not valid UTF-8' cause API timeout #2944

Open wucao opened 3 years ago

wucao commented 3 years ago

Describe the bug Prometheus 'Label value is not valid UTF-8' cause API request timeout.

To Reproduce Steps to reproduce the behavior:

  1. docker run -d -e COLLECTOR_ZIPKIN_HOST_PORT=:9411 -p 5775:5775/udp -p 6831:6831/udp -p 6832:6832/udp -p 5778:5778 -p 16686:16686 -p 14268:14268 -p 14250:14250 -p 9411:9411 jaegertracing/all-in-one:1.22
  2. curl http://localhost:9411/%C0%AE%C0%AE
  3. Then all the other requests to http://localhost:9411/ will be timeout.

log:

2021/04/18 06:51:16 http: panic serving 172.17.0.1:33336: label value "/\xc0\xae\xc0\xae" is not valid UTF-8
goroutine 195 [running]:
net/http.(*conn).serve.func1(0xc000489f40)
    net/http/server.go:1801 +0x147
panic(0x1392360, 0xc0002c3630)
    runtime/panic.go:975 +0x47a
github.com/prometheus/client_golang/prometheus.(*HistogramVec).WithLabelValues(0xc0004fc500, 0xc000575770, 0x3, 0x3, 0xc000575650, 0xc000575770)
    github.com/prometheus/client_golang@v1.5.1/prometheus/histogram.go:489 +0xda
github.com/uber/jaeger-lib/metrics/prometheus.(*Factory).Timer(0xc0000edc20, 0x15b70ed, 0x15, 0xc000575620, 0x15bbfcd, 0x19, 0x0, 0x0, 0x0, 0x1512b80, ...)
    github.com/uber/jaeger-lib@v2.4.0+incompatible/metrics/prometheus/factory.go:181 +0x2ce
github.com/uber/jaeger-lib/metrics/fork.(*Factory).Timer(0xc0003fe870, 0x15b70ed, 0x15, 0xc000575620, 0x15bbfcd, 0x19, 0x0, 0x0, 0x0, 0xc0006799f5, ...)
    github.com/uber/jaeger-lib@v2.4.0+incompatible/metrics/fork/fork.go:48 +0x65
github.com/jaegertracing/jaeger/pkg/httpmetrics.buildTimer(...)
    github.com/jaegertracing/jaeger/pkg/httpmetrics/metrics.go:111
github.com/jaegertracing/jaeger/pkg/httpmetrics.(*requestDurations).record(0xc00056c090, 0xc0000bbc80, 0x3, 0xc00057a858, 0x5, 0xc00057a940, 0x3, 0x10578)
    github.com/jaegertracing/jaeger/pkg/httpmetrics/metrics.go:101 +0x465
github.com/jaegertracing/jaeger/pkg/httpmetrics.Wrap.func1(0x1e1c2c0, 0xc000158380, 0xc00014ea00)
    github.com/jaegertracing/jaeger/pkg/httpmetrics/metrics.go:63 +0x1fe
net/http.HandlerFunc.ServeHTTP(0xc00050de60, 0x1e1c2c0, 0xc000158380, 0xc00014ea00)
    net/http/server.go:2042 +0x44
github.com/rs/cors.(*Cors).Handler.func1(0x1e1c2c0, 0xc000158380, 0xc00014ea00)
    github.com/rs/cors@v1.7.0/cors.go:219 +0x1b9
net/http.HandlerFunc.ServeHTTP(0xc00050de80, 0x1e1c2c0, 0xc000158380, 0xc00014ea00)
    net/http/server.go:2042 +0x44
net/http.serverHandler.ServeHTTP(0xc0000d0380, 0x1e1c2c0, 0xc000158380, 0xc00014ea00)
    net/http/server.go:2843 +0xa3
net/http.(*conn).serve(0xc000489f40, 0x1e225c0, 0xc00025a400)
    net/http/server.go:1925 +0x8ad
created by net/http.(*Server).Serve
    net/http/server.go:2969 +0x36c

Expected behavior Other requests not timeout.

Screenshots null

Version (please complete the following information):

What troubleshooting steps did you try? The error is reported by Prometheus, so I add -e METRICS_BACKEND=expvar to disable Prometheus.

Additional context null

yurishkuro commented 3 years ago

We need to make the name sanitizing more strict. Right now it only swaps a couple of characters, but perhaps we should flip that and only allow a fixed set of characters (like alpha-num + forward-slash) and override everything else.

https://github.com/jaegertracing/jaeger-lib/blob/06ab55c11590042246ad0c7925b3b39d73a13d4a/metrics/prometheus/factory.go#L109

yurishkuro commented 3 years ago

Alternatively, we could avoid calling prom_client methods that panic and instead call those that return errors, in this case hist.GetMetricWithLabelValues instead of hist.WithLabelValues. Then use some kind of fallback. Even better if our own API was returning errors, but that would be breaking change.

https://github.com/prometheus/client_golang/blob/0400fc44d42dd0bca7fb16e87ea0313bb2eb8c53/prometheus/histogram.go#L487

jpkrohling commented 3 years ago

Sanitizing would fix the issue at hand, calling methods that return errors would be a good solution for the unknown issues. Question: is this causing the collector to panic, or are we recovering somehow?

Valgueiro commented 2 years ago

Do you have any updates on this? I have the same problem 😢 .

I was able to change the METRICS_BACKEND to expvar and I think it is working correctly now, but I'm not sure if there is any performance overhead doing so.

yurishkuro commented 1 year ago

I have a narrowly scoped fix #4051 that will address the specific problem with collector's http endpoints.

It still leaves a broader issue open that some external inputs (such as service names) are used as Prometheus labels and could cause panics. I would prefer to address that more generally when we migrate all metrics to OTEL. We'd probably still want to keep the metrics factory abstraction, but at least chance its API to return errors from factories, so that these issues could be handled gracefully without panics.

evict commented 1 month ago

I am running jaegertracing/all-in-one:1.45.0 with Otel, and I am having the same issue when \x85 is being passed as a value. This is the stacktrace:

panic: label value "label__3d\x85_this_will_panic-repro" is not valid UTF-8

goroutine 14097 [running]:
github.com/prometheus/client_golang/prometheus.(*CounterVec).WithLabelValues(...)
    github.com/prometheus/client_golang@v1.15.0/prometheus/counter.go:274
github.com/jaegertracing/jaeger/internal/metrics/prometheus.(*Factory).Counter(0xc000676be0, {{0x17bb0f7, 0x8}, 0xc02563a4b0, {0x0, 0x0}})
    github.com/jaegertracing/jaeger/internal/metrics/prometheus/factory.go:144 +0x5f1
github.com/jaegertracing/jaeger/internal/metrics/fork.(*Factory).Counter(0x156c7a0?, {{0x17bb0f7, 0x8}, 0xc02563a4b0, {0x0, 0x0}})
    github.com/jaegertracing/jaeger/internal/metrics/fork/fork.go:43 +0x42
github.com/jaegertracing/jaeger/cmd/collector/app.(*spanCountsBySvc).countByServiceName(0xc000bb6c98, {0xc022ea3500?, 0x0?}, 0x0)
    github.com/jaegertracing/jaeger/cmd/collector/app/metrics.go:331 +0x207
github.com/jaegertracing/jaeger/cmd/collector/app.metricsBySvc.countSpansByServiceName(...)
    github.com/jaegertracing/jaeger/cmd/collector/app/metrics.go:242
github.com/jaegertracing/jaeger/cmd/collector/app.metricsBySvc.ReportServiceNameForSpan({{{0xc000678cc0, 0xc000678e10, {0x1deaba0, 0xc000678c00}, 0xc000573218, 0xfa0, {0x17bb0f7, 0x8}}}, {{0xc000678f60, 0xc000679710, ...}, ...}}, ...)
    github.com/jaegertracing/jaeger/cmd/collector/app/metrics.go:233 +0xc9
github.com/jaegertracing/jaeger/cmd/collector/app.(*spanProcessor).enqueueSpan(0xc0001ae3f0, 0xc02b38da40, {0x17b443c, 0x5}, {0x17b2cb7?, 0x0?}, {0x0, 0x0})
    github.com/jaegertracing/jaeger/cmd/collector/app/span_processor.go:233 +0x205
github.com/jaegertracing/jaeger/cmd/collector/app.(*spanProcessor).ProcessSpans(0xc0001ae3f0, {0xc008155c68?, 0x1, 0xc0255bf140?}, {{0x17b443c, 0x5}, {0x17b2cb7, 0x4}, {0x0, 0x0}})
    github.com/jaegertracing/jaeger/cmd/collector/app/span_processor.go:194 +0x145
github.com/jaegertracing/jaeger/cmd/collector/app/handler.(*batchConsumer).consume(0xc0005a6ba0, {0x1de9138?, 0xc02563a480?}, 0xc01f2ade80)
    github.com/jaegertracing/jaeger/cmd/collector/app/handler/grpc_handler.go:88 +0x2ac
github.com/jaegertracing/jaeger/cmd/collector/app/handler.(*consumerDelegate).consume(0xc0005a6ba0, {0x1de9138, 0xc02563a480}, {0x1579fc0?})
    github.com/jaegertracing/jaeger/cmd/collector/app/handler/otlp_receiver.go:168 +0x8a
go.opentelemetry.io/collector/consumer.ConsumeTracesFunc.ConsumeTraces(...)
    go.opentelemetry.io/collector/consumer@v0.76.1/traces.go:36
go.opentelemetry.io/collector/receiver/otlpreceiver/internal/trace.(*Receiver).Export(0xc0005b64b0, {0x1de9138, 0xc02563a3f0}, {0x0?})
    go.opentelemetry.io/collector/receiver/otlpreceiver@v0.76.1/internal/trace/otlp.go:52 +0xdb
go.opentelemetry.io/collector/pdata/ptrace/ptraceotlp.rawTracesServer.Export({{0x1ddff40?, 0xc0005b64b0?}}, {0x1de9138?, 0xc02563a3f0?}, 0x170a500?)
    go.opentelemetry.io/collector/pdata@v1.0.0-rcv0011/ptrace/ptraceotlp/grpc.go:94 +0xd1
go.opentelemetry.io/collector/pdata/internal/data/protogen/collector/trace/v1._TraceService_Export_Handler.func1({0x1de9138, 0xc02563a3f0}, {0x170f080?, 0xc023aeb170})
    go.opentelemetry.io/collector/pdata@v1.0.0-rcv0011/internal/data/protogen/collector/trace/v1/trace_service.pb.go:310 +0x78
go.opentelemetry.io/collector/config/configgrpc.enhanceWithClientInformation.func1({0x1de9138?, 0xc02563a390?}, {0x170f080, 0xc023aeb170}, 0x0?, 0xc023aeb188)
    go.opentelemetry.io/collector@v0.76.1/config/configgrpc/configgrpc.go:411 +0x4c
google.golang.org/grpc.getChainUnaryHandler.func1({0x1de9138, 0xc02563a390}, {0x170f080, 0xc023aeb170})
    google.golang.org/grpc@v1.54.0/server.go:1164 +0xb9
go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc.UnaryServerInterceptor.func1({0x1de9138, 0xc02563a2d0}, {0x170f080, 0xc023aeb170}, 0xc0096762a0, 0xc01f2adb00)
    go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc@v0.40.0/interceptor.go:342 +0x528
google.golang.org/grpc.chainUnaryInterceptors.func1({0x1de9138, 0xc02563a2d0}, {0x170f080, 0xc023aeb170}, 0xc03add5a58?, 0x157ad40?)
    google.golang.org/grpc@v1.54.0/server.go:1155 +0x8f
go.opentelemetry.io/collector/pdata/internal/data/protogen/collector/trace/v1._TraceService_Export_Handler({0x154cba0?, 0xc0005a8860}, {0x1de9138, 0xc02563a2d0}, 0xc03266bdc0, 0xc0001abf00)
    go.opentelemetry.io/collector/pdata@v1.0.0-rcv0011/internal/data/protogen/collector/trace/v1/trace_service.pb.go:312 +0x138
google.golang.org/grpc.(*Server).processUnaryRPC(0xc000268780, {0x1df1e40, 0xc0007f5a00}, 0xc025600360, 0xc0005b94a0, 0x29284d0, 0x0)
    google.golang.org/grpc@v1.54.0/server.go:1345 +0xdf3
google.golang.org/grpc.(*Server).handleStream(0xc000268780, {0x1df1e40, 0xc0007f5a00}, 0xc025600360, 0x0)
    google.golang.org/grpc@v1.54.0/server.go:1722 +0xa36
google.golang.org/grpc.(*Server).serveStreams.func1.2()
    google.golang.org/grpc@v1.54.0/server.go:966 +0x98
created by google.golang.org/grpc.(*Server).serveStreams.func1
    google.golang.org/grpc@v1.54.0/server.go:964 +0x28a

Unfortunately the pods will crash and won't recover automatically. :sweat_smile: Any chance we can ship the fix here as well?