[NO-TICKET] Reduce startup logs verbosity

[ivoanjo]

What does this PR do?

With the change in #3441 to print the library configuration on every configuration, we were concerned that it may generate noisy logs.

This PR improves the situation by:

• Tweaking the date format (using a few less characters)
• Introducing a extra_fields argument in the EnvironmentLogger, and using it to avoid the need for a separate profiler logger entry.

Thus changing this:

$ bundle exec ruby -e "require 'ddtrace'; 2.times { Datadog.configure { } }"
I, [2024-02-08T10:29:37.145777 #394977]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - PROFILING - {"profiling_enabled":false}
I, [2024-02-08T10:29:37.150765 #394977]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - CORE - {"date":"2024-02-08T10:29:37+00:00","os_name":"x86_64-pc-linux-gnu","version":"1.20.0","lang":"ruby","lang_version":"3.1.4","env":null,"service":"-e","dd_version":null,"debug":false,"tags":null,"runtime_metrics_enabled":false,"vm":"ruby-3.1.4","health_metrics_enabled":false}
I, [2024-02-08T10:29:37.152910 #394977]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - PROFILING - {"profiling_enabled":false}
I, [2024-02-08T10:29:37.153244 #394977]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - CORE - {"date":"2024-02-08T10:29:37+00:00","os_name":"x86_64-pc-linux-gnu","version":"1.20.0","lang":"ruby","lang_version":"3.1.4","env":null,"service":"-e","dd_version":null,"debug":false,"tags":null,"runtime_metrics_enabled":false,"vm":"ruby-3.1.4","health_metrics_enabled":false}

into

I, [2024-02-08T10:29:19.137025 #394537]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - CORE - {"date":"2024-02-08T10:29:19Z","os_name":"x86_64-pc-linux-gnu","version":"1.20.0","lang":"ruby","lang_version":"3.1.4","env":null,"service":"-e","dd_version":null,"debug":false,"tags":null,"runtime_metrics_enabled":false,"vm":"ruby-3.1.4","health_metrics_enabled":false,"profiling_enabled":false}
I, [2024-02-08T10:29:19.139572 #394537]  INFO -- ddtrace: [ddtrace] DATADOG CONFIGURATION - CORE - {"date":"2024-02-08T10:29:19Z","os_name":"x86_64-pc-linux-gnu","version":"1.20.0","lang":"ruby","lang_version":"3.1.4","env":null,"service":"-e","dd_version":null,"debug":false,"tags":null,"runtime_metrics_enabled":false,"vm":"ruby-3.1.4","health_metrics_enabled":false,"profiling_enabled":false}

Motivation:

Startup logs are useful, but should be as minimal as possible.

Additional Notes:

I've introduced this change in a generic way -- e.g. the core only needs to know that components can return extra fields, and fold them into the things that get reported by the environment logger.

How to test the change?

Change includes test coverage; you can also use the example above:

bundle exec ruby -e "require 'ddtrace'; 2.times { Datadog.configure { } }"

to see it running locally.

For Datadog employees:

• If this PR touches code that signs or publishes builds or packages, or handles
  credentials of any kind, I've requested a review from @DataDog/security-design-and-guidance.
• This PR doesn't touch any of that.

[codecov-commenter]

Codecov Report

All modified and coverable lines are covered by tests ✅

Comparison is base (ae8e043) 98.10% compared to head (bca56d2) 98.10%.

Additional details and impacted files

@@            Coverage Diff             @@
##              2.0    #3448      +/-   ##
==========================================
- Coverage   98.10%   98.10%   -0.01%     
==========================================
  Files        1260     1258       -2     
  Lines       72943    72891      -52     
  Branches     3419     3419              
==========================================
- Hits        71562    71510      -52     
  Misses       1381     1381              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[ekump]

👍 on the date format change

I like the consolidation. My only question/suggestion is should we tag the product in the extra fields output in the event there are multiple products logging? profiling_enabled is obvious, but are there fields that get output that wouldn't have the product name in it?

The output would just change from {..."profiling_enabled":false} to {..."profiling": {"profiling_enabled": false}}

[ivoanjo]

I like the consolidation. My only question/suggestion is should we tag the product in the extra fields output in the event there are multiple products logging? profiling_enabled is obvious, but are there fields that get output that wouldn't have the product name in it?

The output would just change from {..."profiling_enabled":false} to {..."profiling": {"profiling_enabled": false}}

This is a good point.

I'm thinking that profiling has been going on for a while (years), and we haven't felt the need to add more things here, so I'm leaning towards the "shorter output in the logs" win of not yet doing that separation, and only introducing it later once we want to add more keys.

But I don't have strong feelings so if other folks think it's worth introducing the extra group right out of the gate, I can live with that.

[delner]

I think reducing the verbosity is a fine goal. I also think having multiple return args for build_profiler_component is unintuitive and a bit messy in the sense that it now serves two roles: 1) get state and 2) get log artifacts. I think these concerns should be separated.

A different proposal (perhaps half-baked): what if the artifacts for env logging were embedded within the component itself? Such that you can simply pass component.to_h to the EnvironmentLogger or something like that? Then you are only dealing with one return value, and maybe having observable human readable fields on the Component is a bonus.

WDYT?

[ivoanjo]

The challenge in having the component become its own logger is that right now we return a nil Profiler instance, and we would need to instead introduce a null profiler object, just to support that use-case.

I'm not quite convinced it's worth going to that approach yet. Yet, I'm not against us doing that in the future. Overall, I think this decision is a two-way door so I propose we keep the current approach for this PR, and later we can change it without issue since this is all about private APIs internal to the library.

[delner]

The challenge in having the component become its own logger is that right now we return a nil Profiler instance, and we would need to instead introduce a null profiler object, just to support that use-case

Null reference is a good point, but if this is purely internal, I think it'd be trivial to introduce a safe operator when calling component's log artifacts to pass to the env logger, no?

I'd also argue build_component returning nil is quite unintuitive as well.

[ivoanjo]

Null reference is a good point, but if this is purely internal, I think it'd be trivial to introduce a safe operator when calling component's log artifacts to pass to the env logger, no?

The problem is that ideally, for something like profiler_enabled, we want profiler_enabled: false in the output when the profiler is nil. So we can't just skip -- there would need to be some extra logic to know what to do when the profiler is nil, whereas right now the core doesn't care -- it just gets an optional hash, and prints it.

[delner]

I see what you mean about extra logic being necessary. But I think this might be resolved by some product-agnostic/generic-component-handling logic. Moreover, you could handle this more directly within the call to extras, e.g.

profiler_logger_extra =  { profiling: (profiler_component&.log_artifacts || { profiling_disabled: false }) }
@environment_logger_extra.merge!(profiler_logger_extra)

After having taken a closer look at the output, I also don't like how profiling state is being logged under CORE. I think its confusing to combine product state into core state, merely for saving a log line.

When I think about it more precisely, I'm not so concerned with the verbosity of the number of lines we have, as I am with the verbosity of how long those lines are, or how often they are repeated. For me, this is striking an unhappy middle ground, where its verbose enough to be annoying, not easy to read, conflating different bits of configuration, repeating information, and committing some technical faux pas (multiple return args, nil return value for build, etc). I think it's better to be either have it be verbose to the point of clarity, or entirely invisible.

As such, I'm not in favor of this change. Open to hearing others' opinions as well.

[marcotc]

IMO, the startup logs are a small feature with a completely internal implementation.
I don't see a need to engineer for the future here, as any changes requested by our solutions team (the primary stakeholder) can be done immediately by us.

After having taken a closer look at the output, I also don't like how profiling state is being logged under CORE. I think its confusing to combine product state into core state, merely for saving a log line.

I agree that profiling is not CORE. Maybe we prematurely split out the environment logger in the past, and should only have a single log line?
Again, this is a tiny feature that, IMO, I would not personally spend too much time engineering.

[delner]

Maybe we prematurely split out the environment logger in the past, and should only have a single log line?

Like I said above, I don't see splitting output across multiple log lines as an issue in itself here; moreso length & repetition. I'd prefer the use of multiple log lines to properly categorize & display the output, to having one giant log line. (Consider for example how its easier to grep.) Both length and repetition are still issues, even with one line.

It's not an issue of "premature" if you don't agree with the ends of one-line-per-component, because even if done at the "correct" time, the result would still split output across multiple lines. (I could go deeper into why I think one-line-per-component is easier to scale, but for the sake of brevity, won't.)

The one problem I think we'd be likely to agree upon here worth solving is the repetition. Unfortunately, this PR doesn't make progress on that element of verbosity (because its hard, as we've previously discussed), so this is merely amounts to exchange of one style for another, hence why I don't really see the value here, especially when considering the faux pas of build_component return value behavior.

[AlexJF]

Several good points were already mentioned so not going to repeat them but agree with:

• Single line (less noise; aligns with other libraries; no way to reconfigure just a single component so don't really see the point of splitting in multiple log lines).
• KISS (minimal impact; easy to change/extend in the future; not enough entries to justify extra hierarchisation).

As nitpick I'd back the feedback that including CORE in the log line looks weird/not-very-useful anymore, maybe lets just strip the prefix altogether from the configuration log?

[ivoanjo]

We discussed this internally and agreed with going like this for now, although we may end up refactoring this, including breaking up log lines per-product again in the future.