feat(diag-logger): introduce a new global level api.diag for internal diagnostic logging

[MSNev]

Which problem is this PR solving?

• Provides solution for [API] Introduce a new global level api.diag for internal Diagnostic Logging (Part 1) #1877 and [Environments] ConsoleLogger does not handle all console environments #1847
• Overall introduction is to better support minification and remove boilerplate code currently used as part of performing diagnostic logging.

Short description of the changes

• introduces new api level object, classes and functions

  • api.diag global logger
  • api.DiagLogLevel - Also provides extended diagnostic levels for internal diagnostic logging.
  • api.DiagConsoleLogger - A ConsoleLogger includes fixes for [Environments] ConsoleLogger does not handle all console environments #1847
  • api.noopDiagLogger(): DiagLogger - A replacement for api.NoopLogger (from [API Suggestion] Provide getLogger helper and remove NoopLogger class implementation #1754)
  • api.diagLogLevelFilter(): DiagLogger (helper to wrap any DiagLogger instance with a DiagLogLevel filtering)

• Tags the following as deprecated to be removed in a future PR for [API] Introduce a new global level api.diag for internal Diagnostic Logging (Part 2) #1878

  • api.Logger
  • api.NoopLogger
  • core.ConsoleLogger
  • core.LogLevel

Replaces internal self contained usages which do not affect compatibility or functionality, also updated the examples.

[MSNev]

As a DiagLogger implements the same functions as Logger, this is just updating to show usage and provide a simple concrete compatibility example.

[MSNev]

Using an embedded array to avoid a for..in loop that could lead to incorrect functionality if the end-user is using some library that decorates objects. e.g. like ember.js and prototype.js

[codecov]

Codecov Report

Merging #1880 (1365412) into main (000a8ac) will increase coverage by 0.17%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##             main    #1880      +/-   ##
==========================================
+ Coverage   92.73%   92.91%   +0.17%     
==========================================
  Files         172      176       +4     
  Lines        5964     6072     +108     
  Branches     1268     1289      +21     
==========================================
+ Hits         5531     5642     +111     
+ Misses        433      430       -3     

Impacted Files	Coverage Δ
packages/opentelemetry-api/src/trace/NoopLogger.ts	100.00% <ø> (ø)
...ges/opentelemetry-core/src/common/ConsoleLogger.ts	95.00% <ø> (ø)
packages/opentelemetry-core/src/common/types.ts	100.00% <ø> (ø)
packages/opentelemetry-api/src/api/diag.ts	100.00% <100.00%> (ø)
packages/opentelemetry-api/src/api/global-utils.ts	100.00% <100.00%> (ø)
...ckages/opentelemetry-api/src/diag/consoleLogger.ts	100.00% <100.00%> (ø)
packages/opentelemetry-api/src/diag/logLevel.ts	100.00% <100.00%> (ø)
packages/opentelemetry-api/src/diag/logger.ts	100.00% <100.00%> (ø)
...telemetry-core/src/common/logging-error-handler.ts	100.00% <100.00%> (ø)
... and 5 more

[MSNev]

Created the DiagAPI as the global instance, although this could have some unexpected side effects (which I think is also true for context, propagation and trace.

Specific Scenario:
An application includes multiple "components" with each component importing and using OT... As these are registered on the global instance there will be unexpected interactions between the different components usage of the global API's. This is probably mostly an issue for browser based scenario's vs server side node based etc.

The solution to the above would be to introduce some form of API context that is used and passed around to all API operations etc.

[dyladan]

In this case, a mismatched API version should call a noop implementation. This is what the other API types do

[MSNev]

Which it will as when DiagAPI registers itself it supplies a NoopDiagAPI fallback.

[MSNev]

But the scenario I'm pointing out is that you could have many components using the SAME version of the API, so the Noop doesn't come into play here as everything is registered as a global.

[dyladan]

Hmm I wonder if a simpler solution would be to prevent different signals from using different API versions. This is what is proposed in #1772

[MSNev]

Code for handling #1847

[dyladan]

Thanks this is a much more manageable PR. Looks like you really spent a lot of time filling out the featureset. My only major concern is the inclusion of "forced" logs, which IMO should not be allowed. I understand the usecase, but for a tracing system I would expect INFO level logs to be used as startup logs and anything that happens during operation to be TRACE level, which would also solve this usecase. The risk of the feature is that a forced log may break a user application if they are not expecting an instrumentation to call it.

[dyladan]

Is there a way we can cause this to fail lint if used?

[MSNev]

Not sure I understand why? -- I did see bart's comment on renaming to VERBOSE which makes a lot of sense to avoid overloading "Trace" yet again.

[dyladan]

To avoid letting it get checked in. If it fails lint it will fail CI. It says right in the docstring it should only be used for development.

[MSNev]

I think I understand what your talking about, I don't think we want to block this level of message being added... The comment is that when being "used" it is not recommended that they deploy to a production system with this setting as it would (possible) cause a bucket load of internal logging...

[dyladan]

This seems quite dangerous. We should at the very least mention that this should not be used in any core or instrumentation components and that this is meant for the end user only.

[MSNev]

Not really, the end-user should not be using the DiagLogger as it's for the API, SDK or Contrib packages as it's a diagnostic logger for OT to use... And the DiagLogger will/should only be used by end-users when during development to diagnose why something isn't working.

[vmarchaud]

I really dont like this, i don't think any of the component should be able to force log something. If i have a specific level in place to make diagostics i don't expect having log coming where i explicitly dont want them, even if its to give me some informations (that in my case i dont want).

[MSNev]

By default the logger is a Noop, and the diagnostic logger is for us to help end-users (and most likely component implementers) diagnose and find why something in OT is not working. Based on history it is extremely useful to not just "know" what version of the component they are using but also to have it validated within any log / output from this that they will provide (because we will be requesting this). Which is also why I added the description of when this should be used.

[dyladan]

I had the same concern and it was addressed at the SIG. By default nothing will be logged, even the "forcedInfo." Maybe it is a bad name and we should call it "startupInfo" or something one level higher than info? Then users can decide if they want all info, or startup info only.

[vmarchaud]

Then users can decide if they want all info, or startup info only.

I don't see how they can do this since there are no level for this "forcedInfo" (or "startupInfo") ? Maybe i'm missing something ?

[MSNev]

Not exactly the purpose, but I think a reasonable compromise -- so it would be between WARN and INFO..
Potentially called "STARTUPINFO"

[dyladan]

Then users can decide if they want all info, or startup info only.

I don't see how they can do this since there are no level for this "forcedInfo" (or "startupInfo") ? Maybe i'm missing something ?

The current implementation logs it as INFO level even if the configured log level is WARN or ERROR. I'm suggesting we add a STARTUPINFO level which would live between INFO and WARN instead.

[vmarchaud]

I fine with this

[dyladan]

Personally, I don't really see the value in INFO level logs in the diagnostic logger. During normal operation the sdk/api shouldn't log. But, as stated below, it is easier to include levels now we may not need later than it is to add them later.

[dyladan]

In this case, a mismatched API version should call a noop implementation. This is what the other API types do

[dyladan]

In general this seems very full featured, but I wonder if we really need such a full featured logger. Telemetry should aim to be as lightweight as possible and logging should really only be used in unusual scenarios. A few things that stick out at me:

1. many logging levels, but in general I only see real utility for 4 (error, info, warn, debug). Even info is of questionable value in a telemetry system since telemetry should never log when it is behaving properly
2. the unusual method of creating the logger with for loops. Is this for minification purposes or just to eliminate code duplication? If it is for minification, can you provide an estimate as to how much is actually saved?
3. Why have the level filter separate from the logger itself? Is there some reason checking the level inside the function itself is an issue?

[obecny]

for me diagLogLevelFilter is confusing. I would move this functionality to chaining

  logger: new DiagConsoleLogger().setLogLevel(DiagConsoleLogger.LOG_LEVEL.DEBUG)

or if we don't want to have static LOG_LEVEL

  logger: new DiagConsoleLogger().setLogLevel(DiagLogLevel.DEBUG)

[MSNev]

If we follow the same factory model (as with the NoopLogger) this would become (perhaps)
logger: createLogLevelDiagLogger(DiagLogLevel.DEBUG, new DiagConsoleLogger())

The DiagnosticAPI does already of a setLogLevel() to enforce a global default logging level. As part of the SDK there is a Global LOG_LEVEL but it hangs off environment so that s a different discussion.

[MSNev]

Additionally, once we only use diag this will become

diag.setLogger(new DiagConsoleLogger());
diag.setLogLevel(DiagLogLevel.DEBUG);

And then it would need to be added here.

[obecny]

tbh it looks strange that you still have to create a new DiagConsoleLogger() which you then have to put to the "factory" to create a new LogLevelDiagLogger. Why do I have to create a 2 instances of 2 different classes to be able to have a logger with desired log level.

Things like
logger: new ConsoleLogger(LogLevel.DEBUG)
is self explanatory easy and intuitive, why can't we have
one of:

logger: createDiagConsoleLogger(DiagLogLevel.DEBUG)
// or
logger: new DiagConsoleLogger(DiagLogLevel.DEBUG)
// or
logger: new DiagConsoleLogger().setLogLevel(DiagLogLevel.DEBUG)

comparing to

logger: createLogLevelDiagLogger(DiagLogLevel.DEBUG, new DiagConsoleLogger())

[MSNev]

This is part of the design to reduce code duplication, doing it this way NO DiagLogger (except the DiagLogger returned by createLogLevelDiagLogger()) needs to add any code to enforce log level filtering.

So ALL log level filtering is in a single location and anyone who wants to create their own DiagLogger (file, database, event logger, etc) just doesn't need to worry about it.

The only other solution to achieve the same would be to introduce a Base class that everyone would need to extend and this has a couple of implications, not just on size but the actual function implementation of the Base class would need to be prototype level OR we force every implementor to save / call the base instance level functions.

[MSNev]

And generally, aren't we also saying that the code moving forward (and unless absolutely necessary) would not create it's own instances and instead would use the api.diag instance -- this will be a migration process and

diag.setLogger(new DiagConsoleLogger());
diag.setLogLevel(DiagLogLevel.DEBUG);

[dyladan]

Personally, I think this distinction makes sense and it is similar to previous loggers i've seen. I think confusion may primarily come from the naming. What I have seen in the past is LoggingDestination or LogSink. Here's a very simplified example to help explain what is going on and why it is implemented this way.

// A LogSink is a destination where logs will be sent.
// A LogSink can assume any logs it receives have already had all appropriate filtering applied (e.g. log level filtering)
interface LogSink {
    debug(...args): void;

    info(...args): void;

    warn(...args): void;

    error(...args): void;

    critical(...args): void;
}

enum LogLevel {
    DEBUG = 0,
    INFO = 10,
    WARN = 20,
    ERROR = 30,
    CRITICAL = 40,
}

// Logger class is what users call log methods on.
// It is in charge of doing any required filtering and sending it to the configured sink.
class Logger {
    constructor(
        private level: LogLevel,
        private sink: LogSink,
    ) { }

    debug(...args) {
        if (this.level < LogLevel.DEBUG)
        this.sink.debug(...args)
    }

    info(...args) {
        if (this.level < LogLevel.INFO)
        this.sink.info(...args)
    }

    warn(...args) {
        if (this.level < LogLevel.WARN)
        this.sink.warn(...args)
    }

    error(...args) {
        if (this.level < LogLevel.ERROR)
        this.sink.error(...args)
    }

    critical(...args) {
        if (this.level < LogLevel.CRITICAL)
        this.sink.critical(...args)
    }
}


// console sink does not need to do any filtering. this is already done
class ConsoleLogSink implements LogSink {
    debug(...args) {
        console.log(...args);
    };

    info(...args) {
        console.log(...args);
    };

    warn(...args) {
        console.error(...args);
    };

    error(...args) {
        console.error(...args);
    };

    critical(...args) {
        console.error(...args);
    };
}


// file sink does not need to do any filtering. this is already done
class FileLogSink implements LogSink {
    constructor(private filename: string) { }

    debug(...args) {
        fs.appendFileSync(this.filename, format(...args))
    };

    info(...args) {
        fs.appendFileSync(this.filename, format(...args))
    };

    warn(...args) {
        fs.appendFileSync(this.filename, format(...args))
    };

    error(...args) {
        fs.appendFileSync(this.filename, format(...args))
    };

    critical(...args) {
        fs.appendFileSync(this.filename, format(...args))
    };
}


// User can now use either logging sink/destination without them both having to implement filtering based on log levels
const fileLogger = new Logger(LogLevel.INFO, new FileLogSink("info.log"));
const consoleLogger = new Logger(LogLevel.CRITICAL, new ConsoleLogSink());

[obecny]

thx the "sink" approach / explanation is clear and straightforward

[MSNev]

Note: Created new issue #1903 for considering how we add a "is logging level enabled" check.

[dyladan]

@open-telemetry/javascript-maintainers @open-telemetry/javascript-approvers please review PRs that affect the API. I want to merge what we have so I can move the code to the API repository this week.

[vmarchaud]

I really dont like this, i don't think any of the component should be able to force log something. If i have a specific level in place to make diagostics i don't expect having log coming where i explicitly dont want them, even if its to give me some informations (that in my case i dont want).

[vmarchaud]

why do we have so many different level ? Can't we use error/warn/info/debug like most logger do ? As a end user i directly give the library that i use to log (pino in my case) to otel, having some many levels (that i dont personally think we really need) means that i will need to do some code to translate those into level my logger understand.

[MSNev]

The comment on the number of logging levels depends on your history, most of the logging systems I have used (and created) actually have more than this. .Net, log4j.
As a diagnostic logger, especially for a system where we don't want to publish new version regularly (esp once we become stable) it is extremely useful to have multiple levels to diagnose internal failures for different scenarios -- without needing to debug with the end-user or release a "special" version with extra debugging (diagnostic logging) included.

[vmarchaud]

The comment on the number of logging levels depends on your history, most of the logging systems I have used (and created) actually have more than this. .Net, log4j.

I understand but don't think its a valid point, the goal is not have a many level as possible.

As a diagnostic logger, especially for a system where we don't want to publish new version regularly (esp once we become stable) it is extremely useful to have multiple levels to diagnose internal failures for different scenarios -- without needing to debug with the end-user or release a "special" version with extra debugging (diagnostic logging) included.

Again i understand that we need to avoid publishing the api often but i stand my point: its about having just what we need.

For exemple, why differenciate terminal/critial and error which is generic enough, the level doesn't provide much (specially since it will be mostly likely serialized as a number) what is important is the error message.
Also what the difference between verbose and debug ? currently debug is used for what you describe as verbose

I don't see the point of having a lot of level "in case we might need them", specially since my original problem is still there, the less level we have the more likely it can be plugged with whatever logger the end user is already using

[dyladan]

I had the same thought about the number of log levels but came to the same conclusion. It may be difficult to add levels later if we need them and this gives us a fair bit of control when trying to debug. One change I might make is to make the levels 10, 20, 30, ... instead of 1, 2, 3, .... This would make it much easier to insert a log level between existing levels (like startupinfo) later as level 25 or 35 or something without breaking deployed loggers.

[MSNev]

why differenciate terminal/critial and error

I think I added this as the description on the levels, terminal and critical are important level events

Also what the difference between verbose and debug

Again see the descriptions, for history verbose was originally called trace

I don't see the point of having a lot of level "in case we might need them"

They are not "in case", when used properly they are extremely useful.

the less level we have the more likely it can be plugged with whatever logger the end user is already using

This was considered and the LogLevel logger handles this here as part of the followup PR to remove the Logger (which will be a breaking change) this can either be removed or retained to support this scenario.

One change I might make is to make the levels 10, 20, 30, ...

I did originally consider this (as part of the pre-decessor PR to this one), however, to keep backward compatibility the numeric value of the existing LogLevel and DiagLogLevel where matched -- As this would be a breaking change, I'm happy to make this change as part of the followup breaking PR.

Timing wise, my plan was to publish the followup breaking change PR after we publish the next API release, so that this can be "waiting" for the next release and in the meantime I can also take the task to update Contrib.

[MSNev]

Which timeline wise (I'm assuming) would be after @dyladan has created the new Api Repo.

[MSNev]

Adding ranges (0..10..20..) as there was no "space" for the Startup level, this will break numeric compatibility between LogLevel and DiagLogLevel -- this WILL cuase some confusion and compatibility issues with the Environment OTEL_LOG_LEVEL -- But this will be "fixed" as part of the followup PR.

[vmarchaud]

But, as stated below, it is easier to include levels now we may not need later than it is to add them later.

(answering here for @dyladan comment here) : I think this drill down to a different opinion about software design, i would prefer have basic levels (like said here) and design so we can add more later (0..10..20 are a good way to do this) only if we fill the need for more.

Anyway if the consensus is more to have a lot in the first place i don't mind.