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

Specs inconsistent Enabled API for Logger #5769

Closed
bogdandrutu opened this issue Sep 3, 2024 · 11 comments · Fixed by #5791 · May be fixed by #5770
Closed

Specs inconsistent Enabled API for Logger #5769

bogdandrutu opened this issue Sep 3, 2024 · 11 comments · Fixed by #5791 · May be fixed by #5770
Assignees
Labels
area:logs Part of OpenTelemetry logs bug Something isn't working pkg:API Related to an API package

Comments

@bogdandrutu
Copy link
Member

Description

Current definition of the Logger.Enabled says in the specs:

To help users avoid performing computationally expensive operations when
generating a LogRecord, a Logger SHOULD provide this Enabled API.

There are currently no required parameters for this API. Parameters can be
added in the future, therefore, the API MUST be structured in a way for
parameters to be added.

See the current implementation here. This means that users must construct the Record before checking if it is enabled, at this point this API is useless since I can call directly emit which can drop the Record. This API must not require the record to be passed.

Expected behavior

It should not require to construct a Record to check if the logger is enabled.

@bogdandrutu bogdandrutu added the bug Something isn't working label Sep 3, 2024
@MrAlias
Copy link
Contributor

MrAlias commented Sep 3, 2024

You can construct a partial record and check that though in the referenced implementation. If you only want to check severity, you only set the severity of the record passed. This means performing the actual complex work of determining other fields may be avoided.

@bogdandrutu
Copy link
Member Author

bogdandrutu commented Sep 3, 2024

You can construct a partial record and check that though in the referenced implementation. If you only want to check severity, you only set the severity of the record passed. This means performing the actual complex work of determining other fields may be avoided.

Even if that is an use-case, I think that should be done via "options" not required. I would imagine having an option "WithSeverity" for example to do this.

@bogdandrutu
Copy link
Member Author

bogdandrutu commented Sep 3, 2024

@MrAlias Another inconsistency is that the API was not extensible, per the specs requirement.

@bogdandrutu
Copy link
Member Author

bogdandrutu commented Sep 3, 2024

If you only want to check severity, you only set the severity of the record passed. This means performing the actual complex work of determining other fields may be avoided.

This is also a problem because you may lose events here. Think if one of the Filter processor accepts only records with body == "foo". This processor will return that the logger is disabled if I check for logger.Enabled(ctx, log.Recors{Severity: INFO} because the body is empty. So I cannot actually use with partial records, unless I am missing something.

@pellared
Copy link
Member

pellared commented Sep 3, 2024

Think if one of the Filter processor accepts only records with body == "foo".

The processor should first check if body is not empty using https://pkg.go.dev/go.opentelemetry.io/otel/log#Value.Empty before doing the actual filtering to check if any value was assigned.

However, there may be actually a problem if the body is actually empty and we would like to e.g. filter out log records with empty bodies. I think, we were discussing it with @MrAlias, but I cannot find the conclusion anywhere. There was indeed an idea to create a separate struct for Enabled input that would be able to distinguish "unset fields" vs "fields set to empty". Maybe we thought that it is YAGNI?

@bogdandrutu
Copy link
Member Author

However, there may be actually a problem if the body is actually empty and we would like to e.g. filter out log records with empty bodies.

This opens another problem, because that may pass records that should not pass the filter processor.

There was indeed an idea to create a separate struct for Enabled input that would be able to distinguish "unset fields" vs "fields set to empty". Maybe we thought that it is YAGNI?

Ideally this should be optional to pass, and ideal not Record. Hence the API is not consistent with specs.

@pellared pellared added area:logs Part of OpenTelemetry logs pkg:API Related to an API package labels Sep 3, 2024
@pellared
Copy link
Member

pellared commented Sep 4, 2024

This opens another problem, because that may pass records that should not pass the filter processor.

I also want to call out that the same problem exists for Emit because the Record also does not allow distinguishing unset fields from fields explicitly set to a "zero value".

@pellared
Copy link
Member

pellared commented Sep 4, 2024

Based on convo in #5770 (comment).

I would prefer this in specs before adding support to be honest.

I agree. What do you think of something like the following?

The API SHOULD accept the same set of parameters as [Emit a LogRecord](#emit-a-logrecord):

- [Timestamp](./data-model.md#field-timestamp)
- [Observed Timestamp](./data-model.md#field-observedtimestamp)
- The [Context](../context/README.md) associated with the `LogRecord`. The API
  MAY implicitly use the current Context as a default
  behavior.
- [Severity Number](./data-model.md#field-severitynumber)
- [Severity Text](./data-model.md#field-severitytext)
- [Body](./data-model.md#field-body)
- [Attributes](./data-model.md#field-attributes)

Other parameters that are not accepted by [Emit a LogRecord](#emit-a-logrecord)
can be added in the future, therefore, the API MUST be
structured in a way for parameters to be added.

All parameters MUST be optional.

It MUST be possible to distinguish between
an unset parameter value from a parameter value set explicitly to
a default value of given type.

@MrAlias, thoughts?

@pellared
Copy link
Member

pellared commented Sep 4, 2024

Side note: Whatever we decide. I think we should have a section in https://github.com/open-telemetry/opentelemetry-go/blob/main/log/DESIGN.md for Logger.Enabled that documents the design decisions.

Reference: #5071 (comment)

@pellared
Copy link
Member

pellared commented Sep 5, 2024

Based on the discussion during SIG meeting I plan to

  1. Make a PR that would change Enabled to accept a newly created EnabledParam type. The type would accept setting the severity level and getting its value together with a bool telling whether it was actually set (by the bridge) or not.
  2. Make a PR in spec defining the Enabled parameters.

@pellared
Copy link
Member

pellared commented Sep 6, 2024

I created a PoC (Spike) here: #5791
I would welcome some initial review. If this seems good then I will probably start with a PR for DESIGN.md describing the design decisions.

pellared added a commit that referenced this issue Sep 13, 2024
Fixes #5769

Related spec PR:
open-telemetry/opentelemetry-specification#4203

Remark: A follow-up in contrib is required and afterwards here to fix
the `example/dice`.

Benchstat results for `sdk/log` (`log` has no benchmarks related to
Enabled):

```
goos: linux
goarch: amd64
pkg: go.opentelemetry.io/otel/sdk/log
cpu: Intel(R) Core(TM) i9-10885H CPU @ 2.40GHz
                                  │    old.txt    │               new.txt                │
                                  │    sec/op     │    sec/op     vs base                │
BatchProcessorOnEmit-16              398.8n ± 10%   395.6n ± 12%        ~ (p=0.971 n=10)
Processor/Simple-16                  882.2n ±  8%   869.8n ±  9%        ~ (p=0.811 n=10)
Processor/Batch-16                   1.478µ ±  3%   1.485µ ±  5%        ~ (p=0.646 n=10)
Processor/SetTimestampSimple-16      847.8n ±  1%   844.6n ±  3%        ~ (p=0.247 n=10)
Processor/SetTimestampBatch-16       1.480µ ±  3%   1.473µ ±  4%        ~ (p=0.700 n=10)
Processor/AddAttributesSimple-16     930.0n ±  1%   933.8n ±  1%        ~ (p=0.172 n=10)
Processor/AddAttributesBatch-16      1.624µ ±  2%   1.639µ ±  2%        ~ (p=0.839 n=10)
Processor/SetAttributesSimple-16     903.4n ±  1%   895.1n ±  1%        ~ (p=0.190 n=10)
Processor/SetAttributesBatch-16      1.554µ ±  4%   1.529µ ±  3%        ~ (p=0.159 n=10)
LoggerNewRecord/5_attributes-16      346.0n ±  2%   343.3n ±  2%        ~ (p=0.448 n=10)
LoggerNewRecord/10_attributes-16     1.608µ ±  6%   1.503µ ±  2%   -6.53% (p=0.007 n=10)
LoggerEnabled-16                    34.305n ±  8%   6.706n ±  1%  -80.45% (p=0.000 n=10)
LoggerProviderLogger-16              636.9n ± 10%   605.8n ±  3%        ~ (p=0.105 n=10)
WalkAttributes/1_attributes-16       5.363n ±  3%   4.540n ± 14%  -15.34% (p=0.002 n=10)
WalkAttributes/10_attributes-16      5.436n ±  7%   4.461n ±  2%  -17.95% (p=0.000 n=10)
WalkAttributes/100_attributes-16     5.126n ±  9%   4.465n ±  1%  -12.90% (p=0.000 n=10)
WalkAttributes/1000_attributes-16    5.316n ±  9%   4.502n ±  5%  -15.32% (p=0.002 n=10)
SetAddAttributes/SetAttributes-16    220.5n ± 18%   192.6n ± 11%  -12.67% (p=0.007 n=10)
SetAddAttributes/AddAttributes-16    165.3n ± 21%   127.3n ± 22%  -22.96% (p=0.011 n=10)
SimpleProcessorOnEmit-16             2.159n ±  9%   2.167n ±  9%        ~ (p=0.739 n=10)
geomean                              178.3n         154.5n        -13.31%

                        │    old.txt    │             new.txt             │
                        │      B/s      │      B/s       vs base          │
BatchProcessorOnEmit-16   76.52Mi ± 11%   77.14Mi ± 14%  ~ (p=0.971 n=10)

                                  │    old.txt     │                new.txt                │
                                  │      B/op      │     B/op      vs base                 │
BatchProcessorOnEmit-16               0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/Simple-16                   417.0 ± 0%       417.0 ± 0%       ~ (p=1.000 n=10) ¹
Processor/Batch-16                  1.093Ki ± 1%     1.088Ki ± 1%       ~ (p=0.254 n=10)
Processor/SetTimestampSimple-16       417.0 ± 0%       417.0 ± 0%       ~ (p=1.000 n=10) ¹
Processor/SetTimestampBatch-16      1.095Ki ± 1%     1.084Ki ± 2%       ~ (p=0.361 n=10)
Processor/AddAttributesSimple-16      417.0 ± 0%       417.0 ± 0%       ~ (p=1.000 n=10) ¹
Processor/AddAttributesBatch-16     1.085Ki ± 1%     1.086Ki ± 1%       ~ (p=1.000 n=10)
Processor/SetAttributesSimple-16      465.0 ± 0%       465.0 ± 0%       ~ (p=1.000 n=10) ¹
Processor/SetAttributesBatch-16     1.129Ki ± 1%     1.125Ki ± 1%       ~ (p=0.084 n=10)
LoggerNewRecord/5_attributes-16       0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
LoggerNewRecord/10_attributes-16      610.0 ± 0%       610.0 ± 0%       ~ (p=1.000 n=10) ¹
LoggerEnabled-16                      0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
LoggerProviderLogger-16               359.0 ± 6%       346.0 ± 3%       ~ (p=0.117 n=10)
WalkAttributes/1_attributes-16        0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
WalkAttributes/10_attributes-16       0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
WalkAttributes/100_attributes-16      0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
WalkAttributes/1000_attributes-16     0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
SetAddAttributes/SetAttributes-16     48.00 ± 0%       48.00 ± 0%       ~ (p=1.000 n=10) ¹
SetAddAttributes/AddAttributes-16     0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
SimpleProcessorOnEmit-16              0.000 ± 0%       0.000 ± 0%       ~ (p=1.000 n=10) ¹
geomean                                          ²                 -0.27%                ²
¹ all samples are equal
² summaries must be >0 to compute geomean

                                  │   old.txt    │               new.txt               │
                                  │  allocs/op   │ allocs/op   vs base                 │
BatchProcessorOnEmit-16             0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/Simple-16                 1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/Batch-16                  1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/SetTimestampSimple-16     1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/SetTimestampBatch-16      1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/AddAttributesSimple-16    1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/AddAttributesBatch-16     1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/SetAttributesSimple-16    2.000 ± 0%     2.000 ± 0%       ~ (p=1.000 n=10) ¹
Processor/SetAttributesBatch-16     2.000 ± 0%     2.000 ± 0%       ~ (p=1.000 n=10) ¹
LoggerNewRecord/5_attributes-16     0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
LoggerNewRecord/10_attributes-16    4.000 ± 0%     4.000 ± 0%       ~ (p=1.000 n=10) ¹
LoggerEnabled-16                    0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
LoggerProviderLogger-16             1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
WalkAttributes/1_attributes-16      0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
WalkAttributes/10_attributes-16     0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
WalkAttributes/100_attributes-16    0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
WalkAttributes/1000_attributes-16   0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
SetAddAttributes/SetAttributes-16   1.000 ± 0%     1.000 ± 0%       ~ (p=1.000 n=10) ¹
SetAddAttributes/AddAttributes-16   0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
SimpleProcessorOnEmit-16            0.000 ± 0%     0.000 ± 0%       ~ (p=1.000 n=10) ¹
geomean                                        ²               +0.00%                ²
¹ all samples are equal
² summaries must be >0 to compute geomean
```
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:logs Part of OpenTelemetry logs bug Something isn't working pkg:API Related to an API package
Projects
Status: Done
3 participants