feat: otel traces + interceptor #2144

safeer · 2024-07-24T00:41:35Z

otel interceptor that propagates spans and logs FTL attributes

deniseli · 2024-07-24T17:35:24Z

internal/rpc/otel_interceptor.go

+	responseSize metric.Int64Histogram
+}
+
+func createInstruments(meter metric.Meter) (instruments, error) {


It would be nice if we didn't lose all the instruments whenever one of their instantiations fails. What do you think about refactoring the code here and above to look something like below? This would also have the helpful maintainability effect of parceling the computation of each metric value into its own function, so it's easier to figure out what logic is used for what. WrapUnary is somewhat long at the moment, and it's easy to imagine how it could grow longer.

func (i *otelInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFunc { return func(ctx context.Context, request connect.AnyRequest) (connect.AnyResponse, error) { ... recordDuration(ctx, attributes, requestStartTime) recordRequestSize(...) recordResponseSize(...) return response, err } } func recordDuration(ctx context.Context, attributes []attribute.KeyValue, requestStartTime time.Time) { recordHist(ctx, attributes, histDetails{ name: "duration", unit: "ms", desc: "...", val: time.Since(requestStartTime).Milliseconds(), }) } type histDetails struct { name string unit string desc string val int64 } func recordHist(ctx context.Context, attributes []attribute.KeyValue, details histDetails) { logger := log.FromContext(ctx) // just log the error instead of exiting the function early hist, err := meter.Int64Histogram(details.name, metric.WithUnit(details.unit), metric.WithDescription(details.desc)) if err != nil { logger.Errorf(...) } hist.Record(ctx, details.val, metric.WithAttributes(attributes...)) }

We ended up deciding to panic on metric instantiation error after all to make sure we don't miss any errors in development, but the rest of this still holds :)

deniseli · 2024-07-24T17:49:03Z

internal/rpc/otel_interceptor.go

+const (
+	otelFtlRequestKey = "ftl.requestKey"
+	otelFtlVerbRef    = "ftl.verb.ref"
+	otelFtlVerbModule = "ftl.verb.module"
+	otelFtlEventName  = "ftl.message"
+)


Niiiice! For reference, Jon's PR from yesterday added a few attributes wrapped in functions. I really like your way of doing const keys here since these attributes all have type string, and this is simpler/shorter than doing functions here, but we should clearly define the pattern at some point so it's clear when to follow/use each. Possibly: for interceptor trace attributes, which are kind of their own thing, we follow this pattern (const keys), but for metrics scattered across many directories, we'll use the functions from the linked PR?

Ahh I didn't see Jon's go in. I don't mind using that function pattern at all, happy to switch it, the consistency might be nice

We ended up changing his file back to consts so what you have here is perfect :D

deniseli

This is awesome :D

deniseli · 2024-07-29T21:05:53Z

internal/rpc/otel_interceptor.go

+	otelFtlRequestKey       = "ftl.requestKey"
+	otelFtlVerbRef          = "ftl.verb.ref"
+	otelFtlVerbModule       = "ftl.verb.module"


nittiest of nits: Jon appended Attribute to each of these variable names so I started doing that too. Kinda wondered about just doing Attr instead of brevity but either works

deniseli · 2024-07-29T21:07:15Z

internal/rpc/otel_interceptor.go

+	}
+	requestKey, err := RequestKeyFromContext(ctx)
+	if err != nil {
+		logger.Debugf("failed to get request key: %s", err)


Since request key is so valuable, do you think we should raise this log level to Warn or even Error? I'm not sure personally

The err case is only really hit if there is a request key that we're unable to parse. It is indicative of an issue though, so good call bumping the sev

deniseli · 2024-07-29T21:09:28Z

internal/rpc/otel_interceptor.go

+			trace.WithAttributes(
+				requestSpan,
+				otelMessageIDKey.Int(1),
+				otelMessageSizeKey.Int(requestSize),


How does this work when requestSize is undefined? I assume message size attr just won't show up, but figured I'd ask just in case it's wonky :)

Fixed, good catch on defining requestSize :)

deniseli · 2024-07-29T21:11:08Z

internal/rpc/otel_interceptor.go

+		span.AddEvent(otelMessageEvent,
+			trace.WithAttributes(
+				requestSpan,
+				otelMessageIDKey.Int(1),


What's message ID for?

Doing this for consistency across the rpc interceptors. The individual messages are all shown in the span event, and their ID's must be unique, in the unary case there is one request and one response

deniseli · 2024-07-29T21:13:10Z

internal/rpc/otel_interceptor.go

+	if err != nil {
+		panic(fmt.Errorf("failed to create response size metric: %w", err))
+	}
+	requestsPerRPC, err := meter.Int64Histogram("requests_per_rpc", metric.WithUnit("1"))


Did you find any docs on how unit is supposed to be set for counts? I wasn't sure if we should just leave it out. "1" makes sense intuitively but I'm mostly wondering if this is how we're supposed to do it for all the count metrics

Yup, docs say that for counts the unit should be "1" 🤷

That's so interesting. Seems like some sort of shorthand, but it is what they recommend :)

deniseli · 2024-07-29T21:15:05Z

internal/rpc/otel_interceptor.go

+		ctx, span := tracer.Start(ctx, name, traceOpts...)
+		defer span.End()
+
+		var requestSize int


Should this default to 0 if there's no request object? If not, we should probably mention in the description of this metric that it's only recorded for RPCs with a non-null request.

deniseli · 2024-07-29T21:19:37Z

internal/rpc/otel_interceptor.go

+}
+
+func statusCodeAttribute(protocol string, err error) attribute.KeyValue {
+	statusCodeKey := fmt.Sprintf("rpc.%s.status_code", protocol)


Do we need to lowercase protocol, or is it always guaranteed to be consistent case?

Using the raw value from the Connection and Spec, so for consistency I'm not lowering here, but in our use it's always just "grpc" anyway

wesbillman · 2024-07-29T22:04:40Z

backend/controller/controller.go

@@ -1022,6 +1022,7 @@ func (s *Service) callWithRequest(
 		}
 	}

+	ctx = rpc.WithRequestName(ctx, requestKey)


nit: Should this be rpc.WithRequestKey?

wesbillman · 2024-07-29T22:08:16Z

internal/rpc/otel_interceptor.go

+
+	span := trace.SpanFromContext(ctx)
+	span.AddEvent(otelMessageEvent, trace.WithAttributes(attrs...))
+	return err // nolint:wrapcheck


no we want to nolint all these err or should we wrap them?

Good question; the interceptor just logs errors as they pass through, and it didn't feel quite right to attach this context to the trace; all errors that flow through rpc would then have some otel error: string attached

wesbillman · 2024-07-29T22:12:56Z

internal/rpc/otel_interceptor.go

+	if err != nil {
+		panic(fmt.Errorf("failed to create response size metric: %w", err))
+	}
+	requestsPerRPC, err := meter.Int64Histogram("requests_per_rpc", metric.WithUnit("1"))


That's so interesting. Seems like some sort of shorthand, but it is what they recommend :)

deniseli · 2024-07-29T22:25:09Z

Linking issue: #2194

…ptor

ftl-robot mentioned this pull request Jul 24, 2024

Dashboard #728

Open

safeer changed the title ~~feat: otel traces~~ feat: otel traces + interceptor Jul 24, 2024

safeer requested review from deniseli and jonathanj-square July 24, 2024 00:46

deniseli reviewed Jul 24, 2024

View reviewed changes

safeer force-pushed the saf/otel-traceid-2 branch from d3665aa to e30c0dc Compare July 29, 2024 19:41

safeer requested a review from wesbillman July 29, 2024 19:50

safeer marked this pull request as ready for review July 29, 2024 19:50

safeer requested a review from alecthomas as a code owner July 29, 2024 19:50

safeer requested review from a team and matt2e and removed request for a team July 29, 2024 19:50

deniseli approved these changes Jul 29, 2024

View reviewed changes

safeer force-pushed the saf/otel-traceid-2 branch from 52f5688 to a9f5a54 Compare July 29, 2024 21:49

wesbillman approved these changes Jul 29, 2024

View reviewed changes

safeer force-pushed the saf/otel-traceid-2 branch from 42e4ef7 to ce5d526 Compare July 29, 2024 22:46

safeer and others added 11 commits July 29, 2024 15:51

fix: init observability client in cmd_serve

4898897

feat: otel traces

77d73b8

span propagation

128503c

streaming client interceptor

9a5b327

streaming server interceptor, consolidate otel code into otel_interce…

0f07f91

…ptor

cleanup otel interceptor

ab92406

fix breaking changes from otel 1.27 -> 1.28

3446e1d

rename attr vars, set requestSize

6fc384f

context WithRequestName -> WithRequestKey

b6b9875

fix echo go.mod go.sum

f902622

chore(autofmt): Automated formatting

1e8872f

safeer force-pushed the saf/otel-traceid-2 branch from bac631b to 1e8872f Compare July 29, 2024 22:51

safeer merged commit f31dd1f into main Jul 29, 2024
61 checks passed

safeer deleted the saf/otel-traceid-2 branch July 29, 2024 23:17

safeer mentioned this pull request Aug 5, 2024

otel: check attribute for all calls: trace_id #2024

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: otel traces + interceptor #2144

feat: otel traces + interceptor #2144

safeer commented Jul 24, 2024 •

edited

Loading

deniseli Jul 24, 2024

safeer Jul 24, 2024

deniseli Jul 26, 2024

deniseli Jul 24, 2024

safeer Jul 24, 2024

deniseli Jul 26, 2024

deniseli left a comment

deniseli Jul 29, 2024

deniseli Jul 29, 2024

safeer Jul 29, 2024

deniseli Jul 29, 2024

safeer Jul 29, 2024

deniseli Jul 29, 2024

safeer Jul 29, 2024

deniseli Jul 29, 2024

safeer Jul 29, 2024

wesbillman Jul 29, 2024

deniseli Jul 29, 2024

deniseli Jul 29, 2024

safeer Jul 29, 2024

wesbillman Jul 29, 2024

wesbillman Jul 29, 2024

safeer Jul 29, 2024

wesbillman Jul 29, 2024

deniseli commented Jul 29, 2024

feat: otel traces + interceptor #2144

feat: otel traces + interceptor #2144

Conversation

safeer commented Jul 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

deniseli left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

deniseli commented Jul 29, 2024

safeer commented Jul 24, 2024 •

edited

Loading