Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add info/debug logging to the metric SDK #4315

Merged
merged 6 commits into from Jul 17, 2023

Conversation

MrAlias
Copy link
Contributor

@MrAlias MrAlias commented Jul 14, 2023

Resolves #3722

Info log the creation of a MeterProvider and Meter. Debug log the collection from the periodic and manual reader as well as the exports of the Prometheus, stdout, and OTLP exporters. For reference, info/debug logging is not enable by default so this change will not show unless a user enables it.

Verification

Manually tested using the following modified version of the view example:

package main

import (
	"context"
	"fmt"
	"log"
	"net/http"
	"os"
	"os/signal"
	"time"

	"github.com/go-logr/stdr"
	"github.com/prometheus/client_golang/prometheus/promhttp"

	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc"
	"go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp"
	otelprom "go.opentelemetry.io/otel/exporters/prometheus"
	"go.opentelemetry.io/otel/exporters/stdout/stdoutmetric"
	api "go.opentelemetry.io/otel/metric"
	"go.opentelemetry.io/otel/sdk/instrumentation"
	"go.opentelemetry.io/otel/sdk/metric"
	"go.opentelemetry.io/otel/sdk/metric/aggregation"
)

const meterName = "github.com/open-telemetry/opentelemetry-go/example/view"

type discarder struct{}

func (discarder) Encode(any) error { return nil }

func main() {
	stdr.SetVerbosity(10)
	otel.SetLogger(stdr.New(log.Default()))

	ctx := context.Background()

	// The exporter embeds a default OpenTelemetry Reader, allowing it to be used in WithReader.
	exporter, err := otelprom.New()
	if err != nil {
		log.Fatal(err)
	}

	interval := time.Second * 3

	enc := discarder{}
	stdexp, err := stdoutmetric.New(stdoutmetric.WithEncoder(enc))
	if err != nil {
		log.Fatal(err)
	}
	r0 := metric.NewPeriodicReader(stdexp, metric.WithInterval(interval))

	og, err := otlpmetricgrpc.New(context.Background(), otlpmetricgrpc.WithInsecure())
	if err != nil {
		log.Fatal(err)
	}
	r1 := metric.NewPeriodicReader(og, metric.WithInterval(interval))

	oh, err := otlpmetrichttp.New(context.Background(), otlpmetrichttp.WithInsecure())
	if err != nil {
		log.Fatal(err)
	}
	r2 := metric.NewPeriodicReader(oh, metric.WithInterval(interval))

	provider := metric.NewMeterProvider(
		metric.WithReader(r0),
		metric.WithReader(r1),
		metric.WithReader(r2),
		metric.WithReader(exporter),
		// View to customize histogram buckets and rename a single histogram instrument.
		metric.WithView(metric.NewView(
			metric.Instrument{
				Name:  "custom_histogram",
				Scope: instrumentation.Scope{Name: meterName},
			},
			metric.Stream{
				Name: "bar",
				Aggregation: aggregation.ExplicitBucketHistogram{
					Boundaries: []float64{64, 128, 256, 512, 1024, 2048, 4096},
				},
			},
		)),
	)
	meter := provider.Meter(meterName)

	// Start the prometheus HTTP server and pass the exporter Collector to it
	go serveMetrics()

	opt := api.WithAttributes(
		attribute.Key("A").String("B"),
		attribute.Key("C").String("D"),
	)

	counter, err := meter.Float64Counter("foo", api.WithDescription("a simple counter"))
	if err != nil {
		log.Fatal(err)
	}
	counter.Add(ctx, 5, opt)

	histogram, err := meter.Float64Histogram("custom_histogram", api.WithDescription("a histogram with custom buckets and rename"))
	if err != nil {
		log.Fatal(err)
	}
	histogram.Record(ctx, 136, opt)
	histogram.Record(ctx, 64, opt)
	histogram.Record(ctx, 701, opt)
	histogram.Record(ctx, 830, opt)

	ctx, _ = signal.NotifyContext(ctx, os.Interrupt)
	<-ctx.Done()
}

func serveMetrics() {
	http.Handle("/metrics", promhttp.Handler())
	err := http.ListenAndServe(":2222", nil)
	if err != nil {
		fmt.Printf("error serving http: %v", err)
		return
	}
}
module go.opentelemetry.io/otel/example/view

go 1.19

require (
	github.com/go-logr/stdr v1.2.2
	github.com/prometheus/client_golang v1.16.0
	go.opentelemetry.io/otel v1.16.0
	go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v0.39.0
	go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v0.0.0-00010101000000-000000000000
	go.opentelemetry.io/otel/exporters/prometheus v0.39.0
	go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v0.39.0
	go.opentelemetry.io/otel/metric v1.16.0
	go.opentelemetry.io/otel/sdk v1.16.0
	go.opentelemetry.io/otel/sdk/metric v0.39.0
)

require (
	github.com/beorn7/perks v1.0.1 // indirect
	github.com/cenkalti/backoff/v4 v4.2.1 // indirect
	github.com/cespare/xxhash/v2 v2.2.0 // indirect
	github.com/go-logr/logr v1.2.4 // indirect
	github.com/golang/protobuf v1.5.3 // indirect
	github.com/grpc-ecosystem/grpc-gateway/v2 v2.16.0 // indirect
	github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect
	github.com/prometheus/client_model v0.4.0 // indirect
	github.com/prometheus/common v0.42.0 // indirect
	github.com/prometheus/procfs v0.10.1 // indirect
	go.opentelemetry.io/otel/exporters/otlp/internal/retry v1.16.0 // indirect
	go.opentelemetry.io/otel/exporters/otlp/otlpmetric v0.39.0 // indirect
	go.opentelemetry.io/otel/trace v1.16.0 // indirect
	go.opentelemetry.io/proto/otlp v0.20.0 // indirect
	golang.org/x/net v0.10.0 // indirect
	golang.org/x/sys v0.10.0 // indirect
	golang.org/x/text v0.9.0 // indirect
	google.golang.org/genproto/googleapis/api v0.0.0-20230530153820-e85fd2cbaebc // indirect
	google.golang.org/genproto/googleapis/rpc v0.0.0-20230530153820-e85fd2cbaebc // indirect
	google.golang.org/grpc v1.56.2 // indirect
	google.golang.org/protobuf v1.31.0 // indirect
)

replace go.opentelemetry.io/otel => ../..

replace go.opentelemetry.io/otel/exporters/prometheus => ../../exporters/prometheus

replace go.opentelemetry.io/otel/exporters/stdout/stdoutmetric => ../../exporters/stdout/stdoutmetric

replace go.opentelemetry.io/otel/exporters/otlp/otlpmetric => ../../exporters/otlp/otlpmetric

replace go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc => ../../exporters/otlp/otlpmetric/otlpmetricgrpc

replace go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp => ../../exporters/otlp/otlpmetric/otlpmetrichttp

replace go.opentelemetry.io/otel/sdk => ../../sdk

replace go.opentelemetry.io/otel/sdk/metric => ../../sdk/metric

replace go.opentelemetry.io/otel/metric => ../../metric

replace go.opentelemetry.io/otel/trace => ../../trace

Got:

go run .
2023/07/14 11:54:45 "level"=4 "msg"="MeterProvider created" "Resource"={"Attributes":{"telemetry.sdk.language":"go","telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0","service.name":"unknown_service:view"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"} "Readers"=[{"Type":"PeriodicReader","Exporter":{"Type":"STDOUT"},"Registered":true,"Shutdown":false,"Interval":"3s","Timeout":"30s"},{"Type":"PeriodicReader","Exporter":{"Type":"OTLP/gRPC"},"Registered":true,"Shutdown":false,"Interval":"3s","Timeout":"30s"},{"Type":"PeriodicReader","Exporter":{"Type":"OTLP/HTTP"},"Registered":true,"Shutdown":false,"Interval":"3s","Timeout":"30s"},{"Type":"Prometheus exporter","Registered":true,"Shutdown":false}] "Views"=1
2023/07/14 11:54:45 "level"=4 "msg"="Meter created" "Name"="github.com/open-telemetry/opentelemetry-go/example/view" "Version"="" "SchemaURL"=""
2023/07/14 11:54:46 "level"=8 "msg"="ManualReader collection" "Data"={"Resource":{"Attributes":{"service.name":"unknown_service:view","telemetry.sdk.language":"go","telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262397925 -0700 PDT m=+0.002935408","Time":"2023-07-14 11:54:46.529854515 -0700 PDT m=+1.270392097","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262424397 -0700 PDT m=+0.002961880","Time":"2023-07-14 11:54:46.529859278 -0700 PDT m=+1.270396856","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}
2023/07/14 11:54:46 "level"=8 "msg"="Prometheus exporter export" "Data"={"Resource":{"Attributes":{"service.name":"unknown_service:view","telemetry.sdk.language":"go","telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262397925 -0700 PDT m=+0.002935408","Time":"2023-07-14 11:54:46.529854515 -0700 PDT m=+1.270392097","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"C":"D","A":"B"},"StartTime":"2023-07-14 11:54:45.262424397 -0700 PDT m=+0.002961880","Time":"2023-07-14 11:54:46.529859278 -0700 PDT m=+1.270396856","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}
2023/07/14 11:54:48 "level"=8 "msg"="PeriodicReader collection" "Data"={"Resource":{"Attributes":{"service.name":"unknown_service:view","telemetry.sdk.language":"go","telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262396289 -0700 PDT m=+0.002933772","Time":"2023-07-14 11:54:48.263244711 -0700 PDT m=+3.003782420","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"C":"D","A":"B"},"StartTime":"2023-07-14 11:54:45.262422888 -0700 PDT m=+0.002960371","Time":"2023-07-14 11:54:48.263250052 -0700 PDT m=+3.003787603","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}
2023/07/14 11:54:48 "level"=8 "msg"="PeriodicReader collection" "Data"={"Resource":{"Attributes":{"telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0","service.name":"unknown_service:view","telemetry.sdk.language":"go"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262394295 -0700 PDT m=+0.002931778","Time":"2023-07-14 11:54:48.263262682 -0700 PDT m=+3.003800212","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262421226 -0700 PDT m=+0.002958709","Time":"2023-07-14 11:54:48.263265964 -0700 PDT m=+3.003803496","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}
2023/07/14 11:54:48 "level"=8 "msg"="PeriodicReader collection" "Data"={"Resource":{"Attributes":{"telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0","service.name":"unknown_service:view","telemetry.sdk.language":"go"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262390221 -0700 PDT m=+0.002927709","Time":"2023-07-14 11:54:48.263338283 -0700 PDT m=+3.003875833","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"C":"D","A":"B"},"StartTime":"2023-07-14 11:54:45.262417607 -0700 PDT m=+0.002955096","Time":"2023-07-14 11:54:48.263341931 -0700 PDT m=+3.003879482","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}
2023/07/14 11:54:48 "level"=8 "msg"="STDOUT exporter export" "Data"={"Resource":{"Attributes":{"service.name":"unknown_service:view","telemetry.sdk.language":"go","telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262390221 -0700 PDT m=+0.002927709","Time":"2023-07-14 11:54:48.263338283 -0700 PDT m=+3.003875833","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"C":"D","A":"B"},"StartTime":"2023-07-14 11:54:45.262417607 -0700 PDT m=+0.002955096","Time":"2023-07-14 11:54:48.263341931 -0700 PDT m=+3.003879482","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}
2023/07/14 11:54:48 "level"=8 "msg"="OTLP/gRPC exporter export" "Data"={"Resource":{"Attributes":{"service.name":"unknown_service:view","telemetry.sdk.language":"go","telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262394295 -0700 PDT m=+0.002931778","Time":"2023-07-14 11:54:48.263262682 -0700 PDT m=+3.003800212","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"C":"D","A":"B"},"StartTime":"2023-07-14 11:54:45.262421226 -0700 PDT m=+0.002958709","Time":"2023-07-14 11:54:48.263265964 -0700 PDT m=+3.003803496","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}
2023/07/14 11:54:48 "level"=8 "msg"="OTLP/HTTP exporter export" "Data"={"Resource":{"Attributes":{"service.name":"unknown_service:view","telemetry.sdk.language":"go","telemetry.sdk.name":"opentelemetry","telemetry.sdk.version":"1.16.0"},"SchemaURL":"https://opentelemetry.io/schemas/1.17.0"},"ScopeMetrics":[{"Scope":{"Name":"github.com/open-telemetry/opentelemetry-go/example/view","Version":"","SchemaURL":""},"Metrics":[{"Name":"foo","Description":"a simple counter","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262396289 -0700 PDT m=+0.002933772","Time":"2023-07-14 11:54:48.263244711 -0700 PDT m=+3.003782420","Value":5}],"Temporality":"CumulativeTemporality","IsMonotonic":true}},{"Name":"bar","Description":"a histogram with custom buckets and rename","Unit":"","Data":{"DataPoints":[{"Attributes":{"A":"B","C":"D"},"StartTime":"2023-07-14 11:54:45.262422888 -0700 PDT m=+0.002960371","Time":"2023-07-14 11:54:48.263250052 -0700 PDT m=+3.003787603","Count":4,"Bounds":[64,128,256,512,1024,2048,4096],"BucketCounts":[1,0,1,0,2,0,0,0],"Min":{},"Max":{},"Sum":1731}],"Temporality":"CumulativeTemporality"}}]}]}

@MrAlias MrAlias added pkg:SDK Related to an SDK package area:metrics Part of OpenTelemetry Metrics labels Jul 14, 2023
@codecov
Copy link

codecov bot commented Jul 14, 2023

Codecov Report

Merging #4315 (f289318) into main (fdbcb9a) will decrease coverage by 0.2%.
The diff coverage is 75.3%.

Additional details and impacted files

Impacted file tree graph

@@           Coverage Diff           @@
##            main   #4315     +/-   ##
=======================================
- Coverage   83.6%   83.4%   -0.2%     
=======================================
  Files        183     184      +1     
  Lines      14227   14350    +123     
=======================================
+ Hits       11903   11979     +76     
- Misses      2098    2145     +47     
  Partials     226     226             
Impacted Files Coverage Δ
exporters/prometheus/exporter.go 82.7% <12.5%> (-3.9%) ⬇️
sdk/metric/manual_reader.go 76.2% <13.3%> (-8.9%) ⬇️
sdk/metric/periodic_reader.go 84.0% <13.6%> (-9.1%) ⬇️
exporters/stdout/stdoutmetric/exporter.go 90.1% <50.0%> (-1.7%) ⬇️
...porters/otlp/otlpmetric/otlpmetricgrpc/exporter.go 47.6% <60.0%> (+0.5%) ⬆️
...porters/otlp/otlpmetric/otlpmetrichttp/exporter.go 47.6% <60.0%> (+0.5%) ⬆️
sdk/metric/pipeline.go 92.7% <92.3%> (+1.2%) ⬆️
sdk/metric/instrument.go 91.7% <100.0%> (ø)
sdk/metric/internal/aggregate/aggregate.go 100.0% <100.0%> (ø)
sdk/metric/internal/aggregate/filter.go 100.0% <100.0%> (ø)
... and 5 more

@MrAlias MrAlias changed the title Add debug logging to the metric SDK Add info/debug logging to the metric SDK Jul 14, 2023
@MrAlias MrAlias marked this pull request as ready for review July 14, 2023 19:04
Copy link
Contributor

@MadVikingGod MadVikingGod left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks good.

Not all logr adapters (zapr or logrusr, I can't remember which) will marshal deeply nested MarshalLog structs or slices of MarshalLog. I think it is fine to avoid working around those implementations.

@MrAlias MrAlias merged commit 7467923 into open-telemetry:main Jul 17, 2023
21 of 22 checks passed
@MrAlias MrAlias deleted the debug-log-metric-sdk branch July 17, 2023 14:57
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:metrics Part of OpenTelemetry Metrics pkg:SDK Related to an SDK package
Projects
No open projects
Development

Successfully merging this pull request may close these issues.

Add debug logging to metric signal
5 participants