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

[Dynatrace] Logging verbosity: Move metadata discrepancy logging to WarnThenDebug #4583

Conversation

pirgeo
Copy link
Contributor

@pirgeo pirgeo commented Jan 17, 2024

Many metrics have different descriptions based on their attributes (e.g., log4j2.events with tag loglevel=info has description Number of info level log events, while the same metric key with tag loglevel=trace has the description Number of trace level log events). Every time a discrepancy like that is detected, the Dynatrace exporter will log a warning. Consequently, many warnings will be logged, and continue to be logged during the runtime of the process. In order to reduce the number of warning logs produced, this PR introduces a WarnThenDebugLogger for this particular log.

While working on this, I realized that the other WarnThenDebugLoggers in the Dynatrace exporter are actually using the same instance (since they are initialized with the same class type). I fixed that by introducing thin wrappers for different WarnThenDebugLoggers. There is no change in application behaviour, just in the logging output.

@marcingrzejszczak
Copy link
Contributor

Thank you for your PR. Can you please elaborate more on what is currently not working and how this fixes things? I don't fully understand things.

@marcingrzejszczak marcingrzejszczak added the waiting for feedback We need additional information before we can continue label Jan 19, 2024
@pirgeo
Copy link
Contributor Author

pirgeo commented Jan 19, 2024

Absolutely! Micrometer allows multiple descriptions for one metric name. In Dynatrace, currently we only accept one description for all metrics of a metric key. Let me elaborate on my example above. Let's assume they were created like this (this is probably not true, but for the sake of the example it doesn't matter, I think):

Counter.Builder infoCounter = Counter.builder("log4j2.events")
    .tag("loglevel", "info")
    .description("Number of info level log event");
Counter.Builder traceCounter = Counter.builder("log4j2.events")
    .tag("loglevel", "trace")
    .description("Number of trace level log event");

They both have the same metric name (log4j2.events). When serializing, I would have to choose which of the descriptions I send to Dynatrace (since I can only set one of the two). Which meter is serialized first decides which description should be set - and it might be very different between exports and runs.

To circumvent this, we check for inconsistencies between descriptions before we export, and log a warning if they don't match. The problem I am trying to address with this PR is that we log a warning every time this happens, and on each export - that can be a lot of warning logs. Additionally, this is not a problem that will just right itself - it requires intervention by the application author, so continuously logging the warning does not help the person looking at the logs at all.

Hope that makes it a bit clearer - thanks for taking a look!

@marcingrzejszczak marcingrzejszczak added feedback-provided and removed waiting for feedback We need additional information before we can continue labels Jan 22, 2024
* logger with just a name (a class object has to be passed). If the WarnThenDebugLogger
* is created with the same class type multiple times, the same instance will be returned.
* This would mean that in a scenario with multiple loggers, only the first call would log
* the warning, and all subsequent calls will log at debug.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think that's accurate. The two instances will use the same logger but the level is still controlled by the instance flag in each.

I wrote the following test:

@Test
void twoInstancesSameLoggerClass() {
    WarnThenDebugLogger first = new WarnThenDebugLogger(WarnThenDebugLoggerTest.class);
    WarnThenDebugLogger second = new WarnThenDebugLogger(WarnThenDebugLoggerTest.class);

    first.log("hi");
    second.log("hello");
}

And the log output is:

16:19:03.684 [main] WARN io.micrometer.common.util.internal.logging.WarnThenDebugLoggerTest - hi Note that subsequent logs will be logged at debug level.
16:19:03.684 [main] WARN io.micrometer.common.util.internal.logging.WarnThenDebugLoggerTest - hello Note that subsequent logs will be logged at debug level.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think you are right, the description is off. I wanted to assert on the different WarnThenDebugLoggers, to ensure that all warning messages are triggered. Initially, I was using three separate WarnThenDebugLoggers to do that (without the subclasses). There is only one constructor for WarnThenDebugLogger and it takes a Class parameter:

public WarnThenDebugLogger(Class<?> clazz) {
this.logger = InternalLoggerFactory.getInstance(clazz);
}

Since there is no obvious choice of which Class type to put there, I at first put WarnThenDebugLogger.class.
In the tests, we are using the MockLoggerFactory to get these Loggers. There, I have two choices of how to retrieve the Loggers:
public MockLogger getLogger(Class<?> clazz) {
return getLogger(clazz.getName());
}
and
public MockLogger getLogger(String name) {
return loggers.computeIfAbsent(name, MockLogger::new);
}

Since there is no way of creating the WarnThenDebugLogger with a name instead of the Class object, all three used the WarnThenDebugLogger.class to create, and then the same WarnThenDebugLogger.class to retrieve them from the MockLoggerFactory. But: the MockLoggerFactory cannot distinguish between these instances, since they all have the same name. Consequently, the tests were very flaky, because it is not clear which WarnThenDebugLogger was being returned by mockLoggerFactory.getLogger(WarnThenDebugLogger.class).
In order to work around this, I created the new classes that basically set a specific "name" (by using the Class type of the subclass) to the separate WarnThenDebugLoggers. This way, there will be three separate WarnThenDebugLoggers in the MockLoggerFactory (each with a different name), and I can pull the right one to assert on.

Do you think this is the wrong approach? Alternatively, I could add API surface to the WarnThenDebugLogger to allow creating one with a specific name. Happy to discuss other alternatives as well!

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated the description in f05701b

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks. Perhaps we can look at improving the usability of MockLoggerFactory or some other way to make testing this easier. /cc @jonatan-ivanov
The changes are mostly internal, though the class that will be logged is different with this change. I assume you're okay with that, and if so, I'm okay to merge the changes.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, sounds good! Thank you!

@shakuzen shakuzen added registry: dynatrace A Dynatrace Registry related issue and removed feedback-provided labels Jan 31, 2024
@shakuzen shakuzen added this to the 1.12.3 milestone Jan 31, 2024
@shakuzen shakuzen added the bug A general bug label Jan 31, 2024
@shakuzen shakuzen merged commit 1b0e423 into micrometer-metrics:1.12.x Jan 31, 2024
6 checks passed
@pirgeo pirgeo deleted the dynatrace-metadata-verbosity branch January 31, 2024 13:52
izeye added a commit to izeye/micrometer that referenced this pull request Mar 20, 2024
@izeye izeye mentioned this pull request Mar 20, 2024
@izeye
Copy link
Contributor

izeye commented Mar 20, 2024

Many metrics have different descriptions based on their attributes (e.g., log4j2.events with tag loglevel=info has description Number of info level log events, while the same metric key with tag loglevel=trace has the description Number of trace level log events).

This seems to be similar to #3201. I created #4864 to try to resolve this.

@izeye
Copy link
Contributor

izeye commented Mar 20, 2024

Since there is no way of creating the WarnThenDebugLogger with a name instead of the Class object,

I also created #4865 to try to resolve this.

shakuzen pushed a commit that referenced this pull request Mar 22, 2024
@pirgeo
Copy link
Contributor Author

pirgeo commented Apr 1, 2024

Great news, thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug A general bug registry: dynatrace A Dynatrace Registry related issue
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants