[processor/transform] Instrument the transform processor to emit traces

.chloggen/ottl-emit-traces.yaml

@@ -0,0 +1,27 @@
+# Use this changelog template to create an entry for release notes.
+
+# One of 'breaking', 'deprecation', 'new_component', 'enhancement', 'bug_fix'
+change_type: enhancement
+
+# The name of the component, or a single word describing the area of concern, (e.g. filelogreceiver)
+component: pkg/ottl
+
+# A brief description of the change.  Surround your text with quotes ("") if it needs to start with a backtick (`).
+note: Emit traces for statement sequence executions to troubleshoot OTTL statements/conditions
+
+# Mandatory: One or more tracking issues related to the change. You can use the PR number here if no issue exists.
+issues: [33433]
+
+# (Optional) One or more lines of additional information to render under the primary note.
+# These lines will be padded with 2 spaces and then inserted directly into the document.
+# Use pipe (|) for multiline entries.
+subtext:
+
+# If your change doesn't affect end users or the exported elements of any package,
+# you should instead start your pull request title with [chore] or use the "Skip Changelog" label.
+# Optional: The change log or logs in which this entry should be included.
+# e.g. '[user]' or '[user, api]'
+# Include 'user' if the change is relevant to end users.
+# Include 'api' if there is a change to a library API.
+# Default: '[user]'
+change_logs: []

pkg/ottl/README.md

@@ -151,3 +151,21 @@ service:
 2024-05-29T16:38:09.600-0600    debug   [email protected]/parser.go:268     TransformContext after statement execution      {"kind": "processor", "name": "transform", "pipeline": "logs", "statement": "set(instrumentation_scope.attributes[\"test\"], [\"pass\"])", "condition matched": true, "TransformContext": {"resource": {"attributes": {"test": "pass"}, "dropped_attribute_count": 0}, "scope": {"attributes": {"test": ["pass"]}, "dropped_attribute_count": 0, "name": "", "version": ""}, "log_record": {"attributes": {"log.file.name": "test.log"}, "body": "test", "dropped_attribute_count": 0, "flags": 0, "observed_time_unix_nano": 1717022289500721000, "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": 0, "trace_id": ""}, "cache": {}}}
 2024-05-29T16:38:09.601-0600    debug   [email protected]/parser.go:268     TransformContext after statement execution      {"kind": "processor", "name": "transform", "pipeline": "logs", "statement": "set(attributes[\"test\"], true)", "condition matched": true, "TransformContext": {"resource": {"attributes": {"test": "pass"}, "dropped_attribute_count": 0}, "scope": {"attributes": {"test": ["pass"]}, "dropped_attribute_count": 0, "name": "", "version": ""}, "log_record": {"attributes": {"log.file.name": "test.log", "test": true}, "body": "test", "dropped_attribute_count": 0, "flags": 0, "observed_time_unix_nano": 1717022289500721000, "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": 0, "trace_id": ""}, "cache": {}}}
 ```
+
+If configured to do so, the collector also emits traces for the execution of OTTL statement sequences.
+These traces contain spans for the execution of each statement, including the statement itself and whether it has
+been applied or not. To make use of this, enable the self monitoring of the collector by setting the
+`--feature-gates=telemetry.useOtelWithSDKConfigurationForInternalTelemetry` flag, and using the following configuration
+to export the traces to e.g. an OTLP API endpoint:
+
+```yaml
+service:
+  telemetry:
+    traces:
+      processors:
+        - batch:
+            exporter:
+              otlp:
+                protocol: http/protobuf
+                endpoint: ${env:OTLP_ENDPOINT}/v1/traces
+```

pkg/ottl/go.mod

@@ -13,6 +13,8 @@ require (
 	github.com/stretchr/testify v1.9.0
 	go.opentelemetry.io/collector/component v0.102.2-0.20240611143128-7dfb57b9ad1c
 	go.opentelemetry.io/collector/pdata v1.9.1-0.20240611143128-7dfb57b9ad1c
+	go.opentelemetry.io/otel v1.27.0
+	go.opentelemetry.io/otel/sdk v1.27.0
 	go.opentelemetry.io/otel/trace v1.27.0
 	go.uber.org/goleak v1.3.0
 	go.uber.org/zap v1.27.0
@@ -36,10 +38,8 @@ require (
 	github.com/prometheus/common v0.54.0 // indirect
 	github.com/prometheus/procfs v0.15.0 // indirect
 	go.opentelemetry.io/collector/config/configtelemetry v0.102.2-0.20240611143128-7dfb57b9ad1c // indirect
-	go.opentelemetry.io/otel v1.27.0 // indirect
 	go.opentelemetry.io/otel/exporters/prometheus v0.49.0 // indirect
 	go.opentelemetry.io/otel/metric v1.27.0 // indirect
-	go.opentelemetry.io/otel/sdk v1.27.0 // indirect
 	go.opentelemetry.io/otel/sdk/metric v1.27.0 // indirect
 	go.uber.org/multierr v1.11.0 // indirect
 	golang.org/x/sys v0.21.0 // indirect

pkg/ottl/parser.go

@@ -7,12 +7,22 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"sync"
 
 	"github.com/alecthomas/participle/v2"
 	"go.opentelemetry.io/collector/component"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/codes"
+	"go.opentelemetry.io/otel/trace"
+	"go.opentelemetry.io/otel/trace/noop"
 	"go.uber.org/zap"
 )
 
+const (
+	logAttributeTraceID = "trace_id"
+	logAttributeSpanID  = "span_id"
+)
+
 // Statement holds a top level Statement for processing telemetry data. A Statement is a combination of a function
 // invocation and the boolean expression to match telemetry for invoking the function.
 type Statement[K any] struct {
@@ -231,6 +241,8 @@ type StatementSequence[K any] struct {
 	statements        []*Statement[K]
 	errorMode         ErrorMode
 	telemetrySettings component.TelemetrySettings
+	tracer            trace.Tracer
+	tracerOnce        sync.Once
 }
 
 type StatementSequenceOption[K any] func(*StatementSequence[K])
@@ -250,6 +262,10 @@ func NewStatementSequence[K any](statements []*Statement[K], telemetrySettings c
 		statements:        statements,
 		errorMode:         PropagateError,
 		telemetrySettings: telemetrySettings,
+		tracer:            &noop.Tracer{},
+	}
+	if telemetrySettings.TracerProvider != nil {
+		s.tracer = telemetrySettings.TracerProvider.Tracer("ottl")
 	}
 	for _, op := range options {
 		op(&s)
@@ -262,23 +278,78 @@ func NewStatementSequence[K any](statements []*Statement[K], telemetrySettings c
 // When the ErrorMode of the StatementSequence is `ignore`, errors are logged and execution continues to the next statement.
 // When the ErrorMode of the StatementSequence is `silent`, errors are not logged and execution continues to the next statement.
 func (s *StatementSequence[K]) Execute(ctx context.Context, tCtx K) error {
-	s.telemetrySettings.Logger.Debug("initial TransformContext", zap.Any("TransformContext", tCtx))
+	ctx, sequenceSpan := s.getTracer().Start(ctx, "ottl/StatementSequenceExecution")
+	defer sequenceSpan.End()
+	s.telemetrySettings.Logger.Debug(
+		"initial TransformContext",
+		zap.Any("TransformContext", tCtx),
+		zap.String(logAttributeTraceID, sequenceSpan.SpanContext().TraceID().String()),
+		zap.String(logAttributeSpanID, sequenceSpan.SpanContext().SpanID().String()),
+	)
 	for _, statement := range s.statements {
-		_, condition, err := statement.Execute(ctx, tCtx)
-		s.telemetrySettings.Logger.Debug("TransformContext after statement execution", zap.String("statement", statement.origText), zap.Bool("condition matched", condition), zap.Any("TransformContext", tCtx))
+		statementCtx, statementSpan := s.getTracer().Start(ctx, "ottl/StatementExecution")
+		statementSpan.SetAttributes(
+			attribute.KeyValue{
+				Key:   "statement",
+				Value: attribute.StringValue(statement.origText),
+			},
+		)
+		_, condition, err := statement.Execute(statementCtx, tCtx)
+		statementSpan.SetAttributes(
+			attribute.KeyValue{
+				Key:   "condition_matched",
+				Value: attribute.BoolValue(condition),
+			},
+		)
+		s.telemetrySettings.Logger.Debug(
+			"TransformContext after statement execution",
+			zap.String("statement", statement.origText),
+			zap.Bool("condition matched", condition),
+			zap.Any("TransformContext", tCtx),
+			zap.String(logAttributeTraceID, statementSpan.SpanContext().TraceID().String()),
+			zap.String(logAttributeSpanID, statementSpan.SpanContext().SpanID().String()),
+		)
 		if err != nil {
+			statementSpan.RecordError(err)
+			errMsg := fmt.Sprintf("failed to execute statement '%s': %v", statement.origText, err)
+			statementSpan.SetStatus(codes.Error, errMsg)
 			if s.errorMode == PropagateError {
+				sequenceSpan.SetStatus(codes.Error, errMsg)
+				statementSpan.End()
 				err = fmt.Errorf("failed to execute statement: %v, %w", statement.origText, err)
 				return err
 			}
 			if s.errorMode == IgnoreError {
-				s.telemetrySettings.Logger.Warn("failed to execute statement", zap.Error(err), zap.String("statement", statement.origText))
+				s.telemetrySettings.Logger.Warn(
+					"failed to execute statement",
+					zap.Error(err),
+					zap.String("statement", statement.origText),
+					zap.String(logAttributeTraceID, statementSpan.SpanContext().TraceID().String()),
+					zap.String(logAttributeSpanID, statementSpan.SpanContext().SpanID().String()),
+				)
 			}
+		} else {
+			statementSpan.SetStatus(codes.Ok, "statement executed successfully")
 		}
+		statementSpan.End()
 	}
+	sequenceSpan.SetStatus(codes.Ok, "statement sequence executed successfully")
 	return nil
 }
 
+func (s *StatementSequence[K]) getTracer() trace.Tracer {
+	s.tracerOnce.Do(func() {
+		if s.tracer == nil {
+			if s.telemetrySettings.TracerProvider != nil {
+				s.tracer = s.telemetrySettings.TracerProvider.Tracer("ottl")
+			} else {
+				s.tracer = &noop.Tracer{}
+			}
+		}
+	})
+	return s.tracer
+}
+
 // ConditionSequence represents a list of Conditions that will be evaluated sequentially for a TransformContext
 // and will handle errors returned by conditions based on an ErrorMode.
 // By default, the conditions are ORed together, but they can be ANDed together using the WithLogicOperation option.