[pkg/ottl] Move debug log into Statement.Execute (open-telemetry#36456)

#### Description

@tdarwin noticed that the routingconnector wasnt emitting ottl logs when
debug logging was enabled. This turned out to be because we added the
debug statement to `StatementSequence.Execute` but the routingconnector
uses `Statement.Execute`, but it only works with single statements.

This PR moves the debug log into the `Statement.Execute` function so
that more components benefit from the debug logs.

<!--Describe what testing was performed and which tests were added.-->
#### Testing

Tested locally using this config:

```yaml
receivers:
  otlpjsonfile:
    include:
      - /Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json

connectors:
  routing:
    default_pipelines: [traces/a]
    table:
      - statement: route() where attributes["service.name"] == "checkpoint-test"
        pipelines: [traces/b]

processors:
  transform:
    error_mode: ignore
    trace_statements:
      - context: resource
        statements:
          - set(attributes["test"], "pass")


exporters:
  debug/a:
  debug/b:

service:
  telemetry:
    logs:
      level: debug
  pipelines:
    traces:
      receivers:
        - otlpjsonfile
      exporters:
        - routing
    traces/a:
      receivers:
        - routing
      exporters:
        - debug/a
    traces/b:
      receivers:
        - routing
      processors:
        - transform
      exporters:
        - debug/b
```

The collector spit out these logs:

```
❯ ./bin/otelcontribcol_darwin_arm64 --config ./local/config.yaml
2024-11-19T12:29:41.671-0700    info    [email protected]/service.go:166 Setting up own telemetry...
2024-11-19T12:29:41.671-0700    info    telemetry/metrics.go:70 Serving metrics {"address": "localhost:8888", "metrics level": "Normal"}
2024-11-19T12:29:41.672-0700    info    builders/builders.go:26 Development component. May change in the future.        {"kind": "exporter", "data_type": "traces", "name": "debug/b"}
2024-11-19T12:29:41.672-0700    debug   builders/builders.go:24 Alpha component. May change in the future.      {"kind": "processor", "name": "transform", "pipeline": "traces/b"}
2024-11-19T12:29:41.672-0700    info    builders/builders.go:26 Development component. May change in the future.        {"kind": "exporter", "data_type": "traces", "name": "debug/a"}
2024-11-19T12:29:41.672-0700    debug   builders/builders.go:24 Alpha component. May change in the future.      {"kind": "connector", "name": "routing", "exporter_in_pipeline": "traces", "receiver_in_pipeline": "traces"}
2024-11-19T12:29:41.673-0700    debug   builders/builders.go:24 Alpha component. May change in the future.      {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces"}
2024-11-19T12:29:41.673-0700    info    [email protected]/service.go:238 Starting otelcontribcol...      {"Version": "0.114.0-dev", "NumCPU": 10}
2024-11-19T12:29:41.673-0700    info    extensions/extensions.go:39     Starting extensions...
2024-11-19T12:29:41.673-0700    info    [email protected]/service.go:261 Everything is ready. Begin running and processing data.
2024-11-19T12:29:41.875-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:41.875-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.076-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.076-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.275-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.275-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.474-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.474-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.675-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.675-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.875-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:42.875-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.076-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.076-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.274-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.274-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.475-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.475-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.675-0700    debug   fileconsumer/file.go:125        matched files   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:43.675-0700    debug   fileconsumer/file.go:157        Consuming files {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "paths": ["/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"]}
2024-11-19T12:29:44.474-0700    info    fileconsumer/file.go:265        Started watching file   {"kind": "receiver", "name": "otlpjsonfile", "data_type": "traces", "component": "fileconsumer", "path": "/Users/tylerhelmuth/projects/opentelemetry-collector-contrib/local/test.json"}
2024-11-19T12:29:44.475-0700    debug   [email protected]/parser.go:34      TransformContext after statement execution      {"kind": "connector", "name": "routing", "exporter_in_pipeline": "traces", "receiver_in_pipeline": "traces", "statement": "route() where attributes[\"service.name\"] == \"checkpoint-test\"", "condition matched": true, "TransformContext": {"resource": {"attributes": {"service.name": "checkpoint-test", "platform.env": "prd"}, "dropped_attribute_count": 0}, "cache": {}}}
2024-11-19T12:29:44.475-0700    debug   [email protected]/parser.go:340     initial TransformContext before executing StatementSequence     {"kind": "processor", "name": "transform", "pipeline": "traces/b", "TransformContext": {"resource": {"attributes": {"service.name": "checkpoint-test", "platform.env": "prd"}, "dropped_attribute_count": 0}, "cache": {}}}
2024-11-19T12:29:44.475-0700    debug   [email protected]/parser.go:34      TransformContext after statement execution      {"kind": "processor", "name": "transform", "pipeline": "traces/b", "statement": "set(attributes[\"test\"], \"pass\")", "condition matched": true, "TransformContext": {"resource": {"attributes": {"service.name": "checkpoint-test", "platform.env": "prd", "test": "pass"}, "dropped_attribute_count": 0}, "cache": {}}}
2024-11-19T12:29:44.475-0700    info    Traces  {"kind": "exporter", "data_type": "traces", "name": "debug/b", "resource spans": 1, "spans": 1}
^C2024-11-19T12:29:48.931-0700  info    [email protected]/collector.go:328       Received signal from OS {"signal": "interrupt"}
2024-11-19T12:29:48.931-0700    info    [email protected]/service.go:303 Starting shutdown...
2024-11-19T12:29:48.931-0700    info    extensions/extensions.go:66     Stopping extensions...
2024-11-19T12:29:48.931-0700    info    [email protected]/service.go:317 Shutdown complete.
```

Author: TylerHelmuth

.chloggen/ottl-improve-telemetry.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: Move debug log to `Statement.Execute` so that components using it instead of `StatementSequence` also get debug logs.
+
+# Mandatory: One or more tracking issues related to the change. You can use the PR number here if no issue exists.
+issues: [36456]
+
+# (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/parser.go

@@ -18,9 +18,10 @@ import (
 // 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 {
-	function  Expr[K]
-	condition BoolExpr[K]
-	origText  string
+	function          Expr[K]
+	condition         BoolExpr[K]
+	origText          string
+	telemetrySettings component.TelemetrySettings
 }
 
 // Execute is a function that will execute the statement's function if the statement's condition is met.
@@ -29,6 +30,11 @@ type Statement[K any] struct {
 // In addition, the functions return value is always returned.
 func (s *Statement[K]) Execute(ctx context.Context, tCtx K) (any, bool, error) {
 	condition, err := s.condition.Eval(ctx, tCtx)
+	defer func() {
+		if s.telemetrySettings.Logger != nil {
+			s.telemetrySettings.Logger.Debug("TransformContext after statement execution", zap.String("statement", s.origText), zap.Bool("condition matched", condition), zap.Any("TransformContext", tCtx))
+		}
+	}()
 	if err != nil {
 		return nil, false, err
 	}
@@ -150,9 +156,10 @@ func (p *Parser[K]) ParseStatement(statement string) (*Statement[K], error) {
 		return nil, err
 	}
 	return &Statement[K]{
-		function:  function,
-		condition: expression,
-		origText:  statement,
+		function:          function,
+		condition:         expression,
+		origText:          statement,
+		telemetrySettings: p.telemetrySettings,
 	}, nil
 }
 
@@ -332,10 +339,9 @@ 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))
+	s.telemetrySettings.Logger.Debug("initial TransformContext before executing StatementSequence", zap.Any("TransformContext", tCtx))
 	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))
+		_, _, err := statement.Execute(ctx, tCtx)
 		if err != nil {
 			if s.errorMode == PropagateError {
 				err = fmt.Errorf("failed to execute statement: %v, %w", statement.origText, err)

pkg/ottl/parser_test.go

@@ -2382,8 +2382,9 @@ func Test_Statement_Execute(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			statement := Statement[any]{
-				condition: BoolExpr[any]{tt.condition},
-				function:  Expr[any]{exprFunc: tt.function},
+				condition:         BoolExpr[any]{tt.condition},
+				function:          Expr[any]{exprFunc: tt.function},
+				telemetrySettings: componenttest.NewNopTelemetrySettings(),
 			}
 
 			result, condition, err := statement.Execute(context.Background(), nil)
@@ -2497,8 +2498,9 @@ func Test_Statements_Execute_Error(t *testing.T) {
 			statements := StatementSequence[any]{
 				statements: []*Statement[any]{
 					{
-						condition: BoolExpr[any]{tt.condition},
-						function:  Expr[any]{exprFunc: tt.function},
+						condition:         BoolExpr[any]{tt.condition},
+						function:          Expr[any]{exprFunc: tt.function},
+						telemetrySettings: componenttest.NewNopTelemetrySettings(),
 					},
 				},
 				errorMode:         tt.errorMode,