Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

OTTL 'log' function needed for debugging complex transform pipelines #30932

Closed
ringerc opened this issue Jan 31, 2024 · 8 comments
Closed

OTTL 'log' function needed for debugging complex transform pipelines #30932

ringerc opened this issue Jan 31, 2024 · 8 comments
Assignees
Labels
enhancement New feature or request never stale Issues marked with this label will be never staled and automatically removed pkg/ottl priority:p2 Medium processor/transform Transform processor

Comments

@ringerc
Copy link

ringerc commented Jan 31, 2024

Component(s)

processor/transform

Is your feature request related to a problem? Please describe.

It's difficult to inspect and diagnose the behaviour of complex transform processor pipelines because of the lack of a means of inspecting the state and execution partway through the pipeline.

Answering questions like "why does this 'where' clause not match" is considerably more difficult than might be expected.

Describe the solution you'd like

An OTTL debug_log function that writes its argument(s) out in json form to the otel collector log stream would be very helpful. If passed multiple arguments it would log each in turn. If passed a path, it would serialize and log all children of the path, following the usual access rules.

It would take a key/value pairing of log field label to log field value, and emit them through the otel collector's logger, so if json logging is turned on the results would be distinct json logging keys.

E.g.

  transform/afterdiscovery-vendor:
    metric_statements:
      - context: resource
        statements:
          - |
            set(attributes["foo"], true)
            where attributes["bar"] == "baz"
          - debug_log("attribute foo", attributes["foo"], "attribute bar", attributes["bar"])

For use in the filter processor, logging converter variants may make sense. These would take their first argument and return it unchanged, then take all additional parameters as data to emit as logs.

Describe alternatives you've considered

Presently debugging complex pipelines often involves commenting out various parts, or splitting them up into two separate processors linked by a connector with a debug exporter in the middle. It's wholly impractical.

Ideally some form of attachable debugger could be added, where it could establish a socket to the running collector and place probes dynamically. This is far beyond what's practical to add to the OTTL stack at present however.

Sometimes it's possible to get the info needed by using set to apply various attributes to carry the info required, then inspect with a debug exporter. But this quickly fall down for more complex transforms.

Additional context

No response

@ringerc ringerc added enhancement New feature or request needs triage New item requiring triage labels Jan 31, 2024
Copy link
Contributor

Pinging code owners:

See Adding Labels via Comments if you do not have permissions to add labels yourself.

@github-actions github-actions bot added the processor/transform Transform processor label Jan 31, 2024
@TylerHelmuth
Copy link
Member

@ringerc maybe instead of parameters a function like debug could print the current TransformContext as json (exluding the metric slice from the metric context)?

Ultimately what I'd really like to do some time is add tracing to OTTL/transformprocessor. It would be great to create a span for each statement and record in the trace how the telemetry was change with each statement. Since the collector can export its spans now this is doable.

@TylerHelmuth TylerHelmuth added priority:p2 Medium pkg/ottl and removed needs triage New item requiring triage labels Jan 31, 2024
Copy link
Contributor

Pinging code owners for pkg/ottl: @TylerHelmuth @kentquirk @bogdandrutu @evan-bradley. See Adding Labels via Comments if you do not have permissions to add labels yourself.

@ringerc
Copy link
Author

ringerc commented Jan 31, 2024

@TylerHelmuth Sounds viable, though very noisy in the logs if the context is large.

This was prompted by wrestling a quite complex transform pipeline that adds different attributes for different target monitoring platform vendors.

I'm hoping to get some time to actually work on the collector itself soon.

Copy link
Contributor

github-actions bot commented Apr 1, 2024

This issue has been inactive for 60 days. It will be closed in 60 days if there is no activity. To ping code owners by adding a component label, see Adding Labels via Comments, or if you are unsure of which component this issue relates to, please ping @open-telemetry/collector-contrib-triagers. If this issue is still relevant, please ping the code owners or leave a comment explaining why it is still relevant. Otherwise, please close it.

Pinging code owners:

See Adding Labels via Comments if you do not have permissions to add labels yourself.

@github-actions github-actions bot added the Stale label Apr 1, 2024
@TylerHelmuth
Copy link
Member

It seems I made a duplicate with #31912, lets keep the discussion here.

A highlight from that issue is that I think it would be nice to be able to print the TransformContext after every statement without having to manually add debug statements via a dedicated function.

@TylerHelmuth TylerHelmuth added help wanted Extra attention is needed never stale Issues marked with this label will be never staled and automatically removed and removed Stale labels Apr 2, 2024
@TylerHelmuth
Copy link
Member

We should consider if a solution can be added specifically to OTTL so that any component that uses OTTL can benefit. It might be enough to add some debug logs to Execute and Eval.

@TylerHelmuth TylerHelmuth self-assigned this May 29, 2024
@TylerHelmuth TylerHelmuth removed the help wanted Extra attention is needed label May 29, 2024
TylerHelmuth added a commit that referenced this issue Jun 10, 2024
**Description:**
Adds debug logging to `StatementSequence.Execute` to allow printing the
state of the `TransformContext` after each statement.

Example logs:

```
2024-05-28T16:19:29.198-0600    debug   [email protected]/parser.go:265     initial TransformContext        {"kind": "processor", "name": "transform", "pipeline": "logs", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "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": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
2024-05-28T16:19:29.199-0600    debug   [email protected]/parser.go:268     after transformation    {"kind": "processor", "name": "transform", "pipeline": "logs", "statement": "set(attributes[\"test\"], \"pass\")", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "dropped_attribute_count": 0, "name": "", "version": ""}, "log_record": {"attributes": {"log.file.name": "test.log", "test": "pass"}, "body": "test", "dropped_attribute_count": 0, "flags": 0, "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
```

Formatted json

```json
{
    "kind": "processor",
    "name": "transform",
    "pipeline": "logs",
    "statement": "set(attributes[\"test\"], \"pass\")",
    "tCtx": {
        "resource": {
            "attributes": {},
            "dropped_attribute_count": 0
        },
        "instrumentation_scope": {
            "attributes": {},
            "dropped_attribute_count": 0,
            "name": "",
            "version": ""
        },
        "log_record": {
            "attributes": {
                "log.file.name": "test.log",
                "test": "pass"
            },
            "body": "test",
            "dropped_attribute_count": 0,
            "flags": 0,
            "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC",
            "severity_number": 0,
            "severity_text": "",
            "span_id": "",
            "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC",
            "trace_id": ""
        },
        "cache": {}
    }
}
```

**Link to tracking Issue:** <Issue number if applicable>
Related to
#30932
ChrsMark pushed a commit to ChrsMark/opentelemetry-collector-contrib that referenced this issue Jun 11, 2024
**Description:**
Adds debug logging to `StatementSequence.Execute` to allow printing the
state of the `TransformContext` after each statement.

Example logs:

```
2024-05-28T16:19:29.198-0600    debug   [email protected]/parser.go:265     initial TransformContext        {"kind": "processor", "name": "transform", "pipeline": "logs", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "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": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
2024-05-28T16:19:29.199-0600    debug   [email protected]/parser.go:268     after transformation    {"kind": "processor", "name": "transform", "pipeline": "logs", "statement": "set(attributes[\"test\"], \"pass\")", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "dropped_attribute_count": 0, "name": "", "version": ""}, "log_record": {"attributes": {"log.file.name": "test.log", "test": "pass"}, "body": "test", "dropped_attribute_count": 0, "flags": 0, "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
```

Formatted json

```json
{
    "kind": "processor",
    "name": "transform",
    "pipeline": "logs",
    "statement": "set(attributes[\"test\"], \"pass\")",
    "tCtx": {
        "resource": {
            "attributes": {},
            "dropped_attribute_count": 0
        },
        "instrumentation_scope": {
            "attributes": {},
            "dropped_attribute_count": 0,
            "name": "",
            "version": ""
        },
        "log_record": {
            "attributes": {
                "log.file.name": "test.log",
                "test": "pass"
            },
            "body": "test",
            "dropped_attribute_count": 0,
            "flags": 0,
            "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC",
            "severity_number": 0,
            "severity_text": "",
            "span_id": "",
            "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC",
            "trace_id": ""
        },
        "cache": {}
    }
}
```

**Link to tracking Issue:** <Issue number if applicable>
Related to
open-telemetry#30932
t00mas pushed a commit to t00mas/opentelemetry-collector-contrib that referenced this issue Jun 18, 2024
**Description:**
Adds debug logging to `StatementSequence.Execute` to allow printing the
state of the `TransformContext` after each statement.

Example logs:

```
2024-05-28T16:19:29.198-0600    debug   [email protected]/parser.go:265     initial TransformContext        {"kind": "processor", "name": "transform", "pipeline": "logs", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "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": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
2024-05-28T16:19:29.199-0600    debug   [email protected]/parser.go:268     after transformation    {"kind": "processor", "name": "transform", "pipeline": "logs", "statement": "set(attributes[\"test\"], \"pass\")", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "dropped_attribute_count": 0, "name": "", "version": ""}, "log_record": {"attributes": {"log.file.name": "test.log", "test": "pass"}, "body": "test", "dropped_attribute_count": 0, "flags": 0, "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
```

Formatted json

```json
{
    "kind": "processor",
    "name": "transform",
    "pipeline": "logs",
    "statement": "set(attributes[\"test\"], \"pass\")",
    "tCtx": {
        "resource": {
            "attributes": {},
            "dropped_attribute_count": 0
        },
        "instrumentation_scope": {
            "attributes": {},
            "dropped_attribute_count": 0,
            "name": "",
            "version": ""
        },
        "log_record": {
            "attributes": {
                "log.file.name": "test.log",
                "test": "pass"
            },
            "body": "test",
            "dropped_attribute_count": 0,
            "flags": 0,
            "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC",
            "severity_number": 0,
            "severity_text": "",
            "span_id": "",
            "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC",
            "trace_id": ""
        },
        "cache": {}
    }
}
```

**Link to tracking Issue:** <Issue number if applicable>
Related to
open-telemetry#30932
@TylerHelmuth
Copy link
Member

Since we're tracking trace work via #33433, I consider this closed via #33274

LucaLanziani pushed a commit to LucaLanziani/opentelemetry-collector-contrib that referenced this issue Jun 20, 2024
**Description:**
Adds debug logging to `StatementSequence.Execute` to allow printing the
state of the `TransformContext` after each statement.

Example logs:

```
2024-05-28T16:19:29.198-0600    debug   [email protected]/parser.go:265     initial TransformContext        {"kind": "processor", "name": "transform", "pipeline": "logs", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "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": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
2024-05-28T16:19:29.199-0600    debug   [email protected]/parser.go:268     after transformation    {"kind": "processor", "name": "transform", "pipeline": "logs", "statement": "set(attributes[\"test\"], \"pass\")", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "dropped_attribute_count": 0, "name": "", "version": ""}, "log_record": {"attributes": {"log.file.name": "test.log", "test": "pass"}, "body": "test", "dropped_attribute_count": 0, "flags": 0, "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
```

Formatted json

```json
{
    "kind": "processor",
    "name": "transform",
    "pipeline": "logs",
    "statement": "set(attributes[\"test\"], \"pass\")",
    "tCtx": {
        "resource": {
            "attributes": {},
            "dropped_attribute_count": 0
        },
        "instrumentation_scope": {
            "attributes": {},
            "dropped_attribute_count": 0,
            "name": "",
            "version": ""
        },
        "log_record": {
            "attributes": {
                "log.file.name": "test.log",
                "test": "pass"
            },
            "body": "test",
            "dropped_attribute_count": 0,
            "flags": 0,
            "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC",
            "severity_number": 0,
            "severity_text": "",
            "span_id": "",
            "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC",
            "trace_id": ""
        },
        "cache": {}
    }
}
```

**Link to tracking Issue:** <Issue number if applicable>
Related to
open-telemetry#30932
cparkins pushed a commit to AmadeusITGroup/opentelemetry-collector-contrib that referenced this issue Jul 11, 2024
**Description:**
Adds debug logging to `StatementSequence.Execute` to allow printing the
state of the `TransformContext` after each statement.

Example logs:

```
2024-05-28T16:19:29.198-0600    debug   [email protected]/parser.go:265     initial TransformContext        {"kind": "processor", "name": "transform", "pipeline": "logs", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "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": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
2024-05-28T16:19:29.199-0600    debug   [email protected]/parser.go:268     after transformation    {"kind": "processor", "name": "transform", "pipeline": "logs", "statement": "set(attributes[\"test\"], \"pass\")", "tCtx": {"resource": {"attributes": {}, "dropped_attribute_count": 0}, "instrumentation_scope": {"attributes": {}, "dropped_attribute_count": 0, "name": "", "version": ""}, "log_record": {"attributes": {"log.file.name": "test.log", "test": "pass"}, "body": "test", "dropped_attribute_count": 0, "flags": 0, "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC", "severity_number": 0, "severity_text": "", "span_id": "", "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC", "trace_id": ""}, "cache": {}}}
```

Formatted json

```json
{
    "kind": "processor",
    "name": "transform",
    "pipeline": "logs",
    "statement": "set(attributes[\"test\"], \"pass\")",
    "tCtx": {
        "resource": {
            "attributes": {},
            "dropped_attribute_count": 0
        },
        "instrumentation_scope": {
            "attributes": {},
            "dropped_attribute_count": 0,
            "name": "",
            "version": ""
        },
        "log_record": {
            "attributes": {
                "log.file.name": "test.log",
                "test": "pass"
            },
            "body": "test",
            "dropped_attribute_count": 0,
            "flags": 0,
            "observed_time_unix_nano": "2024-05-28 22:19:29.098833 +0000 UTC",
            "severity_number": 0,
            "severity_text": "",
            "span_id": "",
            "time_unix_nano": "1970-01-01 00:00:00 +0000 UTC",
            "trace_id": ""
        },
        "cache": {}
    }
}
```

**Link to tracking Issue:** <Issue number if applicable>
Related to
open-telemetry#30932
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request never stale Issues marked with this label will be never staled and automatically removed pkg/ottl priority:p2 Medium processor/transform Transform processor
Projects
None yet
Development

No branches or pull requests

2 participants