From 1c8418db9ac6ccc1de524db0d9893744ba015743 Mon Sep 17 00:00:00 2001 From: Tyler Helmuth <12352919+TylerHelmuth@users.noreply.github.com> Date: Mon, 25 Nov 2024 16:22:20 -0700 Subject: [PATCH] [pkg/ottl] Move debug log into Statement.Execute (#36456) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #### 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. #### 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 service@v0.114.0/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 service@v0.114.0/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 service@v0.114.0/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 ottl@v0.114.0/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 ottl@v0.114.0/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 ottl@v0.114.0/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 otelcol@v0.114.0/collector.go:328 Received signal from OS {"signal": "interrupt"} 2024-11-19T12:29:48.931-0700 info service@v0.114.0/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 service@v0.114.0/service.go:317 Shutdown complete. ``` --- .chloggen/ottl-improve-telemetry.yaml | 27 +++++++++++++++++++++++++++ pkg/ottl/parser.go | 24 +++++++++++++++--------- pkg/ottl/parser_test.go | 10 ++++++---- 3 files changed, 48 insertions(+), 13 deletions(-) create mode 100644 .chloggen/ottl-improve-telemetry.yaml diff --git a/.chloggen/ottl-improve-telemetry.yaml b/.chloggen/ottl-improve-telemetry.yaml new file mode 100644 index 000000000000..ce3b070712ae --- /dev/null +++ b/.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: [] diff --git a/pkg/ottl/parser.go b/pkg/ottl/parser.go index 4856279181d1..fade87d2982d 100644 --- a/pkg/ottl/parser.go +++ b/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) diff --git a/pkg/ottl/parser_test.go b/pkg/ottl/parser_test.go index 9e2e09a10e5f..726f531bfb81 100644 --- a/pkg/ottl/parser_test.go +++ b/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,