Skip to content

Commit

Permalink
[pkg/ottl] Move debug log into Statement.Execute (#36456)
Browse files Browse the repository at this point in the history 
#### 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.
```
  • Loading branch information
@TylerHelmuth
TylerHelmuth authored Nov 25, 2024
1 parent 5698c9d commit 9953e97
Show file tree
Hide file tree
Showing 3 changed files with 48 additions and 13 deletions.
27 changes: 27 additions & 0 deletions .chloggen/ottl-improve-telemetry.yaml
View file
Original file line number Diff line number Diff line change
@@ -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: []
24 changes: 15 additions & 9 deletions pkg/ottl/parser.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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
}
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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)
Expand Down
10 changes: 6 additions & 4 deletions pkg/ottl/parser_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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,
Expand Down

0 comments on commit 9953e97

Please sign in to comment.